Re: [PATCH 4/4] writeback: report a slow writeback wait once per timeout

[Jan Kara]

On Fri 06-11-26 04:26:34, Breno Leitao wrote:
> The slow writeback report is printed on every wakeup of the waiter past
> hung_task_timeout_secs, and the waiter is woken more often than that.
> 
> Each flusher working for it wakes it once it has not run for half the
> timeout. All waiters on a bdi share bdi->wb_waitq, so a wakeup meant for
> one of them reaches all of them.
> 
> A sync of files dirtied from two cgroups, on a throttled null_blk device
> with the timeout set to 5 seconds, gets a report every half timeout,
> each printed twice, 18 reports for a 29 second wait:
> 
>   [   10.327992] INFO: The task sync:276 has been waiting for writeback completion for more than 8 seconds.
>   [   10.328000]       bdi 252:0, work items left: 2
>   [   10.328003] INFO: The task sync:276 has been waiting for writeback completion for more than 8 seconds.
>   [   10.328004]       bdi 252:0, work items left: 2
>   [   12.888187] INFO: The task sync:276 has been waiting for writeback completion for more than 10 seconds.
>   [   12.888195]       bdi 252:0, work items left: 2
>   [   12.888197] INFO: The task sync:276 has been waiting for writeback completion for more than 10 seconds.
>   [   12.888198]       bdi 252:0, work items left: 2
>   ...
> 
> Remember when the waiter last reported, and report again only once
> another timeout has passed. The wakeups do not change, so the hung task
> detector still sees the waiter making progress. The same test now
> prints 5 reports:
> 
>   [    7.661129] INFO: The task sync:277 has been waiting for writeback completion for more than 5 seconds.
>   [    7.661136]       bdi 252:0, work items left: 2
>   [   13.241102] INFO: The task sync:277 has been waiting for writeback completion for more than 11 seconds.
>   [   13.241109]       bdi 252:0, work items left: 2
>   ...
>   [   31.801068] The task sync:277 waited 29 seconds for writeback completion on bdi 252:0
> 
> Signed-off-by: Breno Leitao <leitao@xxxxxxxxxx>

Now I'm waiting for someone to complain it gets written out too
infrequently :). Is this change substantially different from
writeback_sb_inodes() waking up done->waitq less frequently?

								Honza

> ---
>  fs/fs-writeback.c                | 5 ++++-
>  include/linux/backing-dev-defs.h | 1 +
>  2 files changed, 5 insertions(+), 1 deletion(-)
> 
> diff --git a/fs/fs-writeback.c b/fs/fs-writeback.c
> index cdb2631b8552e1..8d354784326f7a 100644
> --- a/fs/fs-writeback.c
> +++ b/fs/fs-writeback.c
> @@ -204,7 +204,9 @@ static bool wb_wait_for_completion_cb(struct wb_completion *done,
>  	int left = atomic_read(&done->cnt);
>  
>  	done->progress_stamp = jiffies;
> -	if (left && timeout && (waited_secs > timeout)) {
> +	if (left && timeout &&
> +	    time_after(jiffies, done->report_stamp + timeout * HZ)) {
> +		done->report_stamp = jiffies;
>  		pr_info("INFO: The task %s:%d has been waiting for writeback "
>  			"completion for more than %lu seconds.\n",
>  			current->comm, current->pid, waited_secs);
> @@ -232,6 +234,7 @@ void wb_wait_for_completion(struct wb_completion *done,
>  	unsigned long timeout, waited;
>  
>  	done->wait_start = jiffies;
> +	done->report_stamp = done->wait_start;
>  	atomic_dec(&done->cnt);		/* put down the initial count */
>  	wait_event(*done->waitq, wb_wait_for_completion_cb(done, bdi));
>  
> diff --git a/include/linux/backing-dev-defs.h b/include/linux/backing-dev-defs.h
> index 4f10849373150d..f9fd3b1bf4c609 100644
> --- a/include/linux/backing-dev-defs.h
> +++ b/include/linux/backing-dev-defs.h
> @@ -67,6 +67,7 @@ struct wb_completion {
>  	wait_queue_head_t	*waitq;
>  	unsigned long progress_stamp;	/* The jiffies when slow progress is detected */
>  	unsigned long wait_start;	/* The jiffies when waiting for the writeback work to finish */
> +	unsigned long report_stamp;	/* The jiffies of the last report */
>  };
>  
>  #define __WB_COMPLETION_INIT(_waitq)	\
> 
> -- 
> 2.53.0-Meta
> 
-- 
Jan Kara <jack@xxxxxxxx>
SUSE Labs, CR