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

[Chris Down <chris@chrisdown.name>]

Hi Breno,

Breno Leitao writes:
>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.

This does happen in practice. With your null_blk setup and the timeout at
5 seconds, the waiter gets woken every 5.0 to 6.1 seconds. khungtaskd
reported sync as "blocked for more than 5 seconds" in one of five 40
second syncs with the default check interval, and twice in a single sync
with hung_task_check_interval_secs=1. With hung_task_panic set, that
panics a machine whose writeback is making progress. Stopping these
warnings is what 1888635532fb ("writeback: Wake up waiting tasks when
finishing the writeback of a chunk.") was for, so as Jan said, the wakeups
have to stay below the timeout.

>-	done->progress_stamp = jiffies;
>-	if (left && timeout && (waited_secs > timeout))
>+	if (left && timeout &&
>+	    time_after(jiffies, done->progress_stamp + timeout * HZ))

But this check can't stay as it is once that's done. progress_stamp is
reset on every wakeup, so if the flusher wakes the waiter every half
timeout, this is only true when a single inode holds up the flusher for
more than the other half. With the threshold in writeback_sb_inodes() put
back to timeout / 2 and the rest of this patch kept, the same test prints
no "has been waiting" reports at all, only the "waited N seconds" line
from patch 3. Going by the code, three quarters of the timeout would
mostly have the same problem.

The report_stamp you had in v1 keeps the reports apart without touching
the wakeups, so maybe go back to that and leave writeback_sb_inodes()
alone? That also gets rid of the duplicate from wait_event() checking
twice. With v1's report_stamp on top of patches 1-3, I get one report per
timeout and no hung task warnings.

Thanks!

Chris