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

[Breno Leitao]

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>
---
 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