* Re: [PATCH] f2fs: dump more information when checkpoint was blocked for long time
@ 2025-07-29 15:07 ` Jaegeuk Kim
0 siblings, 0 replies; 8+ messages in thread
From: Jaegeuk Kim @ 2025-07-29 15:07 UTC (permalink / raw)
To: Chao Yu; +Cc: linux-f2fs-devel, linux-kernel, Jan Prusakowski
On 07/29, Chao Yu wrote:
> generic/299 w/ mode=lfs will cause long time latency, let's dump more
> information once we hit case.
>
> CP merge:
> - Queued : 0
> - Issued : 1
> - Total : 1
> - Cur time : 7565(ms)
> - Peak time : 7565(ms)
>
> F2FS-fs (vdc): checkpoint was blocked for 7565 ms, affecting 1 tasks
> CPU: 8 UID: 0 PID: 1614 Comm: f2fs_ckpt-253:3 Tainted: G O 6.16.0-rc3+ #406 PREEMPT(voluntary)
> Tainted: [O]=OOT_MODULE
> Call Trace:
> dump_stack_lvl+0x6e/0xa0
> __checkpoint_and_complete_reqs+0x1a6/0x1d0
> issue_checkpoint_thread+0x4b/0x140
> kthread+0x10d/0x250
> ret_from_fork+0x164/0x190
> ret_from_fork_asm+0x1a/0x30
Can we add more information for debugging this?
>
> Cc: Jan Prusakowski <jprusakowski@google.com>
> Signed-off-by: Chao Yu <chao@kernel.org>
> ---
> fs/f2fs/checkpoint.c | 9 ++++++++-
> fs/f2fs/f2fs.h | 3 +++
> 2 files changed, 11 insertions(+), 1 deletion(-)
>
> diff --git a/fs/f2fs/checkpoint.c b/fs/f2fs/checkpoint.c
> index db3831f7f2f5..b0dcaa8dc40d 100644
> --- a/fs/f2fs/checkpoint.c
> +++ b/fs/f2fs/checkpoint.c
> @@ -1788,8 +1788,15 @@ static void __checkpoint_and_complete_reqs(struct f2fs_sb_info *sbi)
>
> spin_lock(&cprc->stat_lock);
> cprc->cur_time = (unsigned int)div64_u64(sum_diff, count);
> - if (cprc->peak_time < cprc->cur_time)
> + if (cprc->peak_time < cprc->cur_time) {
> cprc->peak_time = cprc->cur_time;
> +
> + if (unlikely(cprc->peak_time >= CP_LONG_LATENCY_THRESHOLD)) {
> + f2fs_warn_ratelimited(sbi, "checkpoint was blocked for %u ms, affecting %llu tasks",
> + cprc->peak_time, count);
> + dump_stack();
> + }
> + }
> spin_unlock(&cprc->stat_lock);
> }
>
> diff --git a/fs/f2fs/f2fs.h b/fs/f2fs/f2fs.h
> index 46d23c2c086c..3130ca6a4770 100644
> --- a/fs/f2fs/f2fs.h
> +++ b/fs/f2fs/f2fs.h
> @@ -350,6 +350,9 @@ struct ckpt_req_control {
> unsigned int peak_time; /* peak wait time in msec until now */
> };
>
> +/* a time threshold that checkpoint was blocked for, unit: ms */
> +#define CP_LONG_LATENCY_THRESHOLD 5000
> +
> /* for the bitmap indicate blocks to be discarded */
> struct discard_entry {
> struct list_head list; /* list head */
> --
> 2.49.0
^ permalink raw reply [flat|nested] 8+ messages in thread* Re: [f2fs-dev] [PATCH] f2fs: dump more information when checkpoint was blocked for long time
2025-07-29 15:07 ` Jaegeuk Kim
@ 2025-07-30 8:00 ` Chao Yu
-1 siblings, 0 replies; 8+ messages in thread
From: Chao Yu via Linux-f2fs-devel @ 2025-07-30 8:00 UTC (permalink / raw)
To: Jaegeuk Kim; +Cc: linux-kernel, linux-f2fs-devel
On 7/29/25 23:07, Jaegeuk Kim wrote:
> On 07/29, Chao Yu wrote:
>> generic/299 w/ mode=lfs will cause long time latency, let's dump more
>> information once we hit case.
>>
>> CP merge:
>> - Queued : 0
>> - Issued : 1
>> - Total : 1
>> - Cur time : 7565(ms)
>> - Peak time : 7565(ms)
>>
>> F2FS-fs (vdc): checkpoint was blocked for 7565 ms, affecting 1 tasks
>> CPU: 8 UID: 0 PID: 1614 Comm: f2fs_ckpt-253:3 Tainted: G O 6.16.0-rc3+ #406 PREEMPT(voluntary)
>> Tainted: [O]=OOT_MODULE
>> Call Trace:
>> dump_stack_lvl+0x6e/0xa0
>> __checkpoint_and_complete_reqs+0x1a6/0x1d0
>> issue_checkpoint_thread+0x4b/0x140
>> kthread+0x10d/0x250
>> ret_from_fork+0x164/0x190
>> ret_from_fork_asm+0x1a/0x30
>
> Can we add more information for debugging this?
Oops, I need to dump information in user's thread instead of f2fs_ckpt.
Thanks,
>
>>
>> Cc: Jan Prusakowski <jprusakowski@google.com>
>> Signed-off-by: Chao Yu <chao@kernel.org>
>> ---
>> fs/f2fs/checkpoint.c | 9 ++++++++-
>> fs/f2fs/f2fs.h | 3 +++
>> 2 files changed, 11 insertions(+), 1 deletion(-)
>>
>> diff --git a/fs/f2fs/checkpoint.c b/fs/f2fs/checkpoint.c
>> index db3831f7f2f5..b0dcaa8dc40d 100644
>> --- a/fs/f2fs/checkpoint.c
>> +++ b/fs/f2fs/checkpoint.c
>> @@ -1788,8 +1788,15 @@ static void __checkpoint_and_complete_reqs(struct f2fs_sb_info *sbi)
>>
>> spin_lock(&cprc->stat_lock);
>> cprc->cur_time = (unsigned int)div64_u64(sum_diff, count);
>> - if (cprc->peak_time < cprc->cur_time)
>> + if (cprc->peak_time < cprc->cur_time) {
>> cprc->peak_time = cprc->cur_time;
>> +
>> + if (unlikely(cprc->peak_time >= CP_LONG_LATENCY_THRESHOLD)) {
>> + f2fs_warn_ratelimited(sbi, "checkpoint was blocked for %u ms, affecting %llu tasks",
>> + cprc->peak_time, count);
>> + dump_stack();
>> + }
>> + }
>> spin_unlock(&cprc->stat_lock);
>> }
>>
>> diff --git a/fs/f2fs/f2fs.h b/fs/f2fs/f2fs.h
>> index 46d23c2c086c..3130ca6a4770 100644
>> --- a/fs/f2fs/f2fs.h
>> +++ b/fs/f2fs/f2fs.h
>> @@ -350,6 +350,9 @@ struct ckpt_req_control {
>> unsigned int peak_time; /* peak wait time in msec until now */
>> };
>>
>> +/* a time threshold that checkpoint was blocked for, unit: ms */
>> +#define CP_LONG_LATENCY_THRESHOLD 5000
>> +
>> /* for the bitmap indicate blocks to be discarded */
>> struct discard_entry {
>> struct list_head list; /* list head */
>> --
>> 2.49.0
_______________________________________________
Linux-f2fs-devel mailing list
Linux-f2fs-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/linux-f2fs-devel
^ permalink raw reply [flat|nested] 8+ messages in thread* Re: [PATCH] f2fs: dump more information when checkpoint was blocked for long time
@ 2025-07-30 8:00 ` Chao Yu
0 siblings, 0 replies; 8+ messages in thread
From: Chao Yu @ 2025-07-30 8:00 UTC (permalink / raw)
To: Jaegeuk Kim; +Cc: chao, linux-f2fs-devel, linux-kernel, Jan Prusakowski
On 7/29/25 23:07, Jaegeuk Kim wrote:
> On 07/29, Chao Yu wrote:
>> generic/299 w/ mode=lfs will cause long time latency, let's dump more
>> information once we hit case.
>>
>> CP merge:
>> - Queued : 0
>> - Issued : 1
>> - Total : 1
>> - Cur time : 7565(ms)
>> - Peak time : 7565(ms)
>>
>> F2FS-fs (vdc): checkpoint was blocked for 7565 ms, affecting 1 tasks
>> CPU: 8 UID: 0 PID: 1614 Comm: f2fs_ckpt-253:3 Tainted: G O 6.16.0-rc3+ #406 PREEMPT(voluntary)
>> Tainted: [O]=OOT_MODULE
>> Call Trace:
>> dump_stack_lvl+0x6e/0xa0
>> __checkpoint_and_complete_reqs+0x1a6/0x1d0
>> issue_checkpoint_thread+0x4b/0x140
>> kthread+0x10d/0x250
>> ret_from_fork+0x164/0x190
>> ret_from_fork_asm+0x1a/0x30
>
> Can we add more information for debugging this?
Oops, I need to dump information in user's thread instead of f2fs_ckpt.
Thanks,
>
>>
>> Cc: Jan Prusakowski <jprusakowski@google.com>
>> Signed-off-by: Chao Yu <chao@kernel.org>
>> ---
>> fs/f2fs/checkpoint.c | 9 ++++++++-
>> fs/f2fs/f2fs.h | 3 +++
>> 2 files changed, 11 insertions(+), 1 deletion(-)
>>
>> diff --git a/fs/f2fs/checkpoint.c b/fs/f2fs/checkpoint.c
>> index db3831f7f2f5..b0dcaa8dc40d 100644
>> --- a/fs/f2fs/checkpoint.c
>> +++ b/fs/f2fs/checkpoint.c
>> @@ -1788,8 +1788,15 @@ static void __checkpoint_and_complete_reqs(struct f2fs_sb_info *sbi)
>>
>> spin_lock(&cprc->stat_lock);
>> cprc->cur_time = (unsigned int)div64_u64(sum_diff, count);
>> - if (cprc->peak_time < cprc->cur_time)
>> + if (cprc->peak_time < cprc->cur_time) {
>> cprc->peak_time = cprc->cur_time;
>> +
>> + if (unlikely(cprc->peak_time >= CP_LONG_LATENCY_THRESHOLD)) {
>> + f2fs_warn_ratelimited(sbi, "checkpoint was blocked for %u ms, affecting %llu tasks",
>> + cprc->peak_time, count);
>> + dump_stack();
>> + }
>> + }
>> spin_unlock(&cprc->stat_lock);
>> }
>>
>> diff --git a/fs/f2fs/f2fs.h b/fs/f2fs/f2fs.h
>> index 46d23c2c086c..3130ca6a4770 100644
>> --- a/fs/f2fs/f2fs.h
>> +++ b/fs/f2fs/f2fs.h
>> @@ -350,6 +350,9 @@ struct ckpt_req_control {
>> unsigned int peak_time; /* peak wait time in msec until now */
>> };
>>
>> +/* a time threshold that checkpoint was blocked for, unit: ms */
>> +#define CP_LONG_LATENCY_THRESHOLD 5000
>> +
>> /* for the bitmap indicate blocks to be discarded */
>> struct discard_entry {
>> struct list_head list; /* list head */
>> --
>> 2.49.0
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: [f2fs-dev] [PATCH] f2fs: dump more information when checkpoint was blocked for long time
2025-07-29 15:07 ` Jaegeuk Kim
@ 2025-07-30 8:40 ` Chao Yu
-1 siblings, 0 replies; 8+ messages in thread
From: Chao Yu via Linux-f2fs-devel @ 2025-07-30 8:40 UTC (permalink / raw)
To: Jaegeuk Kim; +Cc: linux-kernel, linux-f2fs-devel
On 7/29/25 23:07, Jaegeuk Kim wrote:
> On 07/29, Chao Yu wrote:
>> generic/299 w/ mode=lfs will cause long time latency, let's dump more
>> information once we hit case.
>>
>> CP merge:
>> - Queued : 0
>> - Issued : 1
>> - Total : 1
>> - Cur time : 7565(ms)
>> - Peak time : 7565(ms)
>>
>> F2FS-fs (vdc): checkpoint was blocked for 7565 ms, affecting 1 tasks
>> CPU: 8 UID: 0 PID: 1614 Comm: f2fs_ckpt-253:3 Tainted: G O 6.16.0-rc3+ #406 PREEMPT(voluntary)
>> Tainted: [O]=OOT_MODULE
>> Call Trace:
>> dump_stack_lvl+0x6e/0xa0
>> __checkpoint_and_complete_reqs+0x1a6/0x1d0
>> issue_checkpoint_thread+0x4b/0x140
>> kthread+0x10d/0x250
>> ret_from_fork+0x164/0x190
>> ret_from_fork_asm+0x1a/0x30
>
> Can we add more information for debugging this?
I guess we can add more stats in write_checkpoint() to see which
stage we cost most of the latency.
Thanks,
>
>>
>> Cc: Jan Prusakowski <jprusakowski@google.com>
>> Signed-off-by: Chao Yu <chao@kernel.org>
>> ---
>> fs/f2fs/checkpoint.c | 9 ++++++++-
>> fs/f2fs/f2fs.h | 3 +++
>> 2 files changed, 11 insertions(+), 1 deletion(-)
>>
>> diff --git a/fs/f2fs/checkpoint.c b/fs/f2fs/checkpoint.c
>> index db3831f7f2f5..b0dcaa8dc40d 100644
>> --- a/fs/f2fs/checkpoint.c
>> +++ b/fs/f2fs/checkpoint.c
>> @@ -1788,8 +1788,15 @@ static void __checkpoint_and_complete_reqs(struct f2fs_sb_info *sbi)
>>
>> spin_lock(&cprc->stat_lock);
>> cprc->cur_time = (unsigned int)div64_u64(sum_diff, count);
>> - if (cprc->peak_time < cprc->cur_time)
>> + if (cprc->peak_time < cprc->cur_time) {
>> cprc->peak_time = cprc->cur_time;
>> +
>> + if (unlikely(cprc->peak_time >= CP_LONG_LATENCY_THRESHOLD)) {
>> + f2fs_warn_ratelimited(sbi, "checkpoint was blocked for %u ms, affecting %llu tasks",
>> + cprc->peak_time, count);
>> + dump_stack();
>> + }
>> + }
>> spin_unlock(&cprc->stat_lock);
>> }
>>
>> diff --git a/fs/f2fs/f2fs.h b/fs/f2fs/f2fs.h
>> index 46d23c2c086c..3130ca6a4770 100644
>> --- a/fs/f2fs/f2fs.h
>> +++ b/fs/f2fs/f2fs.h
>> @@ -350,6 +350,9 @@ struct ckpt_req_control {
>> unsigned int peak_time; /* peak wait time in msec until now */
>> };
>>
>> +/* a time threshold that checkpoint was blocked for, unit: ms */
>> +#define CP_LONG_LATENCY_THRESHOLD 5000
>> +
>> /* for the bitmap indicate blocks to be discarded */
>> struct discard_entry {
>> struct list_head list; /* list head */
>> --
>> 2.49.0
_______________________________________________
Linux-f2fs-devel mailing list
Linux-f2fs-devel@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/linux-f2fs-devel
^ permalink raw reply [flat|nested] 8+ messages in thread* Re: [PATCH] f2fs: dump more information when checkpoint was blocked for long time
@ 2025-07-30 8:40 ` Chao Yu
0 siblings, 0 replies; 8+ messages in thread
From: Chao Yu @ 2025-07-30 8:40 UTC (permalink / raw)
To: Jaegeuk Kim; +Cc: chao, linux-f2fs-devel, linux-kernel, Jan Prusakowski
On 7/29/25 23:07, Jaegeuk Kim wrote:
> On 07/29, Chao Yu wrote:
>> generic/299 w/ mode=lfs will cause long time latency, let's dump more
>> information once we hit case.
>>
>> CP merge:
>> - Queued : 0
>> - Issued : 1
>> - Total : 1
>> - Cur time : 7565(ms)
>> - Peak time : 7565(ms)
>>
>> F2FS-fs (vdc): checkpoint was blocked for 7565 ms, affecting 1 tasks
>> CPU: 8 UID: 0 PID: 1614 Comm: f2fs_ckpt-253:3 Tainted: G O 6.16.0-rc3+ #406 PREEMPT(voluntary)
>> Tainted: [O]=OOT_MODULE
>> Call Trace:
>> dump_stack_lvl+0x6e/0xa0
>> __checkpoint_and_complete_reqs+0x1a6/0x1d0
>> issue_checkpoint_thread+0x4b/0x140
>> kthread+0x10d/0x250
>> ret_from_fork+0x164/0x190
>> ret_from_fork_asm+0x1a/0x30
>
> Can we add more information for debugging this?
I guess we can add more stats in write_checkpoint() to see which
stage we cost most of the latency.
Thanks,
>
>>
>> Cc: Jan Prusakowski <jprusakowski@google.com>
>> Signed-off-by: Chao Yu <chao@kernel.org>
>> ---
>> fs/f2fs/checkpoint.c | 9 ++++++++-
>> fs/f2fs/f2fs.h | 3 +++
>> 2 files changed, 11 insertions(+), 1 deletion(-)
>>
>> diff --git a/fs/f2fs/checkpoint.c b/fs/f2fs/checkpoint.c
>> index db3831f7f2f5..b0dcaa8dc40d 100644
>> --- a/fs/f2fs/checkpoint.c
>> +++ b/fs/f2fs/checkpoint.c
>> @@ -1788,8 +1788,15 @@ static void __checkpoint_and_complete_reqs(struct f2fs_sb_info *sbi)
>>
>> spin_lock(&cprc->stat_lock);
>> cprc->cur_time = (unsigned int)div64_u64(sum_diff, count);
>> - if (cprc->peak_time < cprc->cur_time)
>> + if (cprc->peak_time < cprc->cur_time) {
>> cprc->peak_time = cprc->cur_time;
>> +
>> + if (unlikely(cprc->peak_time >= CP_LONG_LATENCY_THRESHOLD)) {
>> + f2fs_warn_ratelimited(sbi, "checkpoint was blocked for %u ms, affecting %llu tasks",
>> + cprc->peak_time, count);
>> + dump_stack();
>> + }
>> + }
>> spin_unlock(&cprc->stat_lock);
>> }
>>
>> diff --git a/fs/f2fs/f2fs.h b/fs/f2fs/f2fs.h
>> index 46d23c2c086c..3130ca6a4770 100644
>> --- a/fs/f2fs/f2fs.h
>> +++ b/fs/f2fs/f2fs.h
>> @@ -350,6 +350,9 @@ struct ckpt_req_control {
>> unsigned int peak_time; /* peak wait time in msec until now */
>> };
>>
>> +/* a time threshold that checkpoint was blocked for, unit: ms */
>> +#define CP_LONG_LATENCY_THRESHOLD 5000
>> +
>> /* for the bitmap indicate blocks to be discarded */
>> struct discard_entry {
>> struct list_head list; /* list head */
>> --
>> 2.49.0
^ permalink raw reply [flat|nested] 8+ messages in thread