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

[Breno Leitao <leitao@debian.org>]

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@debian.org>
---
 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