Re: [PATCH] f2fs: dump more information when checkpoint was blocked for long time

[Jaegeuk Kim <jaegeuk@kernel.org>]

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