[PATCH 0/4] writeback: make slow writeback report more actionable

[Breno Leitao <leitao@debian.org>]

Since v6.19, writeback waiters are woken while their writeback makes
progress, so a slow sync no longer trips the hung task detector.
Instead, a waiter past hung_task_timeout_secs logs:

  INFO: The task sync:180 has been waiting for writeback completion for more than 28 seconds.

Across the Meta fleet, this line is logged about 19,000 times a day
(the median over 40 days), and up to 82,000 times on a busy day.

Over one day, 194 hosts logged 16,858 of these lines for only about
2,000 waits, half of them longer than 160 seconds. Most reports were
printed twice, and a wait logged a median of 7 lines.

Going through these reports, a few things made them hard to use and
quickly act on:

1. The message has no trailing newline, so it only shows up once the
   next message is logged. Patch 1 fixes that, for stable.
2. It does not say which device is slow. Patch 2 adds the bdi and the
   number of work items left.
3. The end of the wait is logged as one more "has been waiting" line.
   Patch 3 logs the total wait instead.
4. It is printed every half timeout, often twice. Patch 4 prints it
   once per timeout.

With the series, a sync of files dirtied from two cgroups, on a null_blk
device throttled to 4 MB/s and with hung_task_timeout_secs set to 5,
logs:

  [    7.632999] INFO: The task sync:275 has been waiting for writeback completion for more than 5 seconds.
  [    7.633006]       bdi 252:0, work items left: 2
  [   12.913256] INFO: The task sync:275 has been waiting for writeback completion for more than 10 seconds.
  [   12.913263]       bdi 252:0, work items left: 2
  [   18.353245] INFO: The task sync:275 has been waiting for writeback completion for more than 16 seconds.
  [   18.353252]       bdi 252:0, work items left: 2
  [   23.633304] INFO: The task sync:275 has been waiting for writeback completion for more than 21 seconds.
  [   23.633312]       bdi 252:0, work items left: 2
  [   28.893299] INFO: The task sync:275 has been waiting for writeback completion for more than 26 seconds.
  [   28.893307]       bdi 252:0, work items left: 2
  [   31.792987] The task sync:275 waited 29 seconds for writeback completion on bdi 252:0

Without patch 4, the same test logs 18 reports.

One question I left open: the report uses pr_info(). The hung task
warning these waiters used to trigger uses pr_err(), which still reaches
the consoles, netconsole included, with "quiet" on the command line
(console loglevel 4). The report does not, and pr_warn() would not
either. Should it be pr_err()?

Signed-off-by: Breno Leitao <leitao@debian.org>
---
Breno Leitao (4):
      writeback: add the missing newline to the slow writeback report
      writeback: name the bdi in the slow writeback report
      writeback: log the end of a slow writeback wait
      writeback: report a slow writeback wait once per timeout

 fs/fs-writeback.c                | 37 ++++++++++++++++++++++++++++---------
 include/linux/backing-dev-defs.h |  1 +
 include/linux/backing-dev.h      |  3 ++-
 mm/memcontrol.c                  |  2 +-
 4 files changed, 32 insertions(+), 11 deletions(-)
---
base-commit: 8b7179210b22f8e48a82c5ceacb9d56a9c4cfec4
change-id: 20261105-writeback_stall_report-170750a69946

Best regards,
--  
Breno Leitao <leitao@debian.org>