Re: [PATCH 3/4] writeback: log the end of a slow writeback wait

[Jan Kara]

On Fri 06-11-26 04:26:33, Breno Leitao wrote:
> A slow writeback wait ends with one more "has been waiting" report,
> printed by the wakeup that sees the last work item complete:
> 
>   INFO: The task sync:180 has been waiting for writeback completion for more than 29 seconds.
>         bdi 252:0, work items left: 0
> 
> That line reads as if the task were still waiting. To tell a slow
> writeback from a stuck one, the reader has to notice that the reports
> stopped, which is easy to miss in a busy log.
> 
> Report only while work items are outstanding, and log how long the wait
> took once it is over:
> 
>   The task sync:181 waited 29 seconds for writeback completion on bdi 252:0
> 
> Signed-off-by: Breno Leitao <leitao@xxxxxxxxxx>

Looks good. Feel free to add:

Reviewed-by: Jan Kara <jack@xxxxxxx>

								Honza

> ---
>  fs/fs-writeback.c | 16 +++++++++++++---
>  1 file changed, 13 insertions(+), 3 deletions(-)
> 
> diff --git a/fs/fs-writeback.c b/fs/fs-writeback.c
> index 3dee9d65eaf721..cdb2631b8552e1 100644
> --- a/fs/fs-writeback.c
> +++ b/fs/fs-writeback.c
> @@ -201,17 +201,18 @@ static bool wb_wait_for_completion_cb(struct wb_completion *done,
>  {
>  	unsigned long timeout = sysctl_hung_task_timeout_secs;
>  	unsigned long waited_secs = (jiffies - done->wait_start) / HZ;
> +	int left = atomic_read(&done->cnt);
>  
>  	done->progress_stamp = jiffies;
> -	if (timeout && (waited_secs > timeout)) {
> +	if (left && timeout && (waited_secs > timeout)) {
>  		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);
>  		pr_info("      bdi %s, work items left: %d\n",
> -			bdi_dev_name(bdi), atomic_read(&done->cnt));
> +			bdi_dev_name(bdi), left);
>  	}
>  
> -	return !atomic_read(&done->cnt);
> +	return !left;
>  }
>  
>  /**
> @@ -228,9 +229,18 @@ static bool wb_wait_for_completion_cb(struct wb_completion *done,
>  void wb_wait_for_completion(struct wb_completion *done,
>  			    struct backing_dev_info *bdi)
>  {
> +	unsigned long timeout, waited;
> +
>  	done->wait_start = jiffies;
>  	atomic_dec(&done->cnt);		/* put down the initial count */
>  	wait_event(*done->waitq, wb_wait_for_completion_cb(done, bdi));
> +
> +	timeout = sysctl_hung_task_timeout_secs;
> +	waited = jiffies - done->wait_start;
> +	if (timeout && waited > timeout * HZ)
> +		pr_info("The task %s:%d waited %lu seconds for writeback completion on bdi %s\n",
> +			current->comm, current->pid, waited / HZ,
> +			bdi_dev_name(bdi));
>  }
>  
>  #ifdef CONFIG_CGROUP_WRITEBACK
> 
> -- 
> 2.53.0-Meta
> 
-- 
Jan Kara <jack@xxxxxxxx>
SUSE Labs, CR