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

[Breno Leitao <leitao@debian.org>]

The slow writeback report is printed on every wakeup of the waiter past
hung_task_timeout_secs, and twice each time.

Each flusher working for the waiter wakes it once it has not run for
half the timeout, so the hung task detector sees it make progress.

Since commit 84654c7f4730 ("wait: avoid spurious calls to
prepare_to_wait_event() in ___wait_event()"), wait_event() checks the
condition right after schedule() and again after
prepare_to_wait_event(), so each of those wakeups reports twice.

A sync of files dirtied from two cgroups, on a throttled null_blk device
with the timeout set to 5 seconds, gets 18 reports for a 29 second wait:

 INFO: The task sync:275 has been waiting for writeback completion for more than 7 seconds (bdi 252:0, work items left: 2).
 INFO: The task sync:275 has been waiting for writeback completion for more than 7 seconds (bdi 252:0, work items left: 2).
 INFO: The task sync:275 has been waiting for writeback completion for more than 10 seconds (bdi 252:0, work items left: 2).
 INFO: The task sync:275 has been waiting for writeback completion for more than 10 seconds (bdi 252:0, work items left: 2).
 ...

Set ->progress_stamp when the wait starts, so the first check does not
take a zero stamp for a timeout. The same test now prints 5 reports:

 INFO: The task sync:276 has been waiting for writeback completion for more than 5 seconds (bdi 252:0, work items left: 2).
 INFO: The task sync:276 has been waiting for writeback completion for more than 10 seconds (bdi 252:0, work items left: 2).
 ...
 The task sync:276 waited 29 seconds for writeback completion on bdi 252:0

The flusher only checks for progress between inodes, so the wakeups now
land on the first inode boundary past the timeout, a bit more than a
timeout apart. The hung task detector scans once per timeout, so it can
catch the waiter between two wakeups.

Suggested-by: Jan Kara <jack@suse.cz>
Signed-off-by: Breno Leitao <leitao@debian.org>
---
 fs/fs-writeback.c | 8 +++++---
 1 file changed, 5 insertions(+), 3 deletions(-)

diff --git a/fs/fs-writeback.c b/fs/fs-writeback.c
index e2da4781b5e00b..fcb7fb0196208b 100644
--- a/fs/fs-writeback.c
+++ b/fs/fs-writeback.c
@@ -203,12 +203,13 @@ static bool wb_wait_for_completion_cb(struct wb_completion *done,
 	unsigned long waited_secs = (jiffies - done->wait_start) / HZ;
 	int left = atomic_read(&done->cnt);
 
-	done->progress_stamp = jiffies;
-	if (left && timeout && (waited_secs > timeout))
+	if (left && timeout &&
+	    time_after(jiffies, done->progress_stamp + timeout * HZ))
 		pr_info("INFO: The task %s:%d has been waiting for writeback "
 			"completion for more than %lu seconds (bdi %s, work items left: %d).\n",
 			current->comm, current->pid, waited_secs,
 			bdi_dev_name(bdi), left);
+	done->progress_stamp = jiffies;
 
 	return !left;
 }
@@ -230,6 +231,7 @@ void wb_wait_for_completion(struct wb_completion *done,
 	unsigned long timeout, waited;
 
 	done->wait_start = jiffies;
+	done->progress_stamp = done->wait_start;
 	atomic_dec(&done->cnt);		/* put down the initial count */
 	wait_event(*done->waitq, wb_wait_for_completion_cb(done, bdi));
 
@@ -2135,7 +2137,7 @@ static long writeback_sb_inodes(struct super_block *sb,
 
 		/* Report progress to inform the hung task detector of the progress. */
 		if (work->done && work->done->progress_stamp && timeout &&
-		   (jiffies - work->done->progress_stamp) > HZ * timeout / 2)
+		   (jiffies - work->done->progress_stamp) > HZ * timeout)
 			wake_up_all(work->done->waitq);
 
 		wbc_detach_inode(&wbc);

-- 
2.53.0-Meta