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

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

[Breno Leitao]

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>

[PATCH 1/4] writeback: add the missing newline to the slow writeback report

[Breno Leitao]

wb_wait_for_completion_cb() reports a writeback wait that exceeds
hung_task_timeout_secs with a pr_info() that has no trailing newline.
printk() keeps such a record open for a continuation and does not
finalize it, so dmesg, the consoles and netconsole only see the report
once the next message is logged.

Terminate the message with a newline.

Fixes: d6e621590764 ("writeback: Add logging for slow writeback (exceeds sysctl_hung_task_timeout_secs)")
Cc: stable@vger.kernel.org
Signed-off-by: Breno Leitao <leitao@debian.org>
---
 fs/fs-writeback.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/fs/fs-writeback.c b/fs/fs-writeback.c
index 15260cf2a29b09..01a00d7542b371 100644
--- a/fs/fs-writeback.c
+++ b/fs/fs-writeback.c
@@ -204,7 +204,7 @@ static bool wb_wait_for_completion_cb(struct wb_completion *done)
 	done->progress_stamp = jiffies;
 	if (timeout && (waited_secs > timeout))
 		pr_info("INFO: The task %s:%d has been waiting for writeback "
-			"completion for more than %lu seconds.",
+			"completion for more than %lu seconds.\n",
 			current->comm, current->pid, waited_secs);
 
 	return !atomic_read(&done->cnt);

-- 
2.53.0-Meta

[PATCH 2/4] writeback: name the bdi in the slow writeback report

[Breno Leitao]

The slow writeback report names the waiting task and how long it has
waited, but not what it is waiting on. On a machine with several
filesystems there is no way to tell which device is slow.

Pass the bdi to wb_wait_for_completion() and print its name on a second
line, together with the number of work items still outstanding. A sync
issues one work item per cgroup wb with dirty inodes, so the count also
shows whether a single cgroup is holding up the others.

wb_wait_for_completion() took the bdi until commit 5b9cce4c7eb0
("writeback: Generalize and expose wb_completion") made it usable for
the memcg foreign flushes. memcg tracks those by bdi id only and passes
NULL, which bdi_dev_name() prints as "(unknown)".

The first line does not change, so anything matching on it keeps
working. A sync on a throttled null_blk device now reports:

  INFO: The task sync:180 has been waiting for writeback completion for more than 28 seconds.
        bdi 252:0, work items left: 1

Signed-off-by: Breno Leitao <leitao@debian.org>
---
 fs/fs-writeback.c           | 20 +++++++++++++-------
 include/linux/backing-dev.h |  3 ++-
 mm/memcontrol.c             |  2 +-
 3 files changed, 16 insertions(+), 9 deletions(-)

diff --git a/fs/fs-writeback.c b/fs/fs-writeback.c
index 01a00d7542b371..3dee9d65eaf721 100644
--- a/fs/fs-writeback.c
+++ b/fs/fs-writeback.c
@@ -196,16 +196,20 @@ static void wb_queue_work(struct bdi_writeback *wb,
 	spin_unlock_irq(&wb->work_lock);
 }
 
-static bool wb_wait_for_completion_cb(struct wb_completion *done)
+static bool wb_wait_for_completion_cb(struct wb_completion *done,
+				      struct backing_dev_info *bdi)
 {
 	unsigned long timeout = sysctl_hung_task_timeout_secs;
 	unsigned long waited_secs = (jiffies - done->wait_start) / HZ;
 
 	done->progress_stamp = jiffies;
-	if (timeout && (waited_secs > timeout))
+	if (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));
+	}
 
 	return !atomic_read(&done->cnt);
 }
@@ -213,6 +217,7 @@ static bool wb_wait_for_completion_cb(struct wb_completion *done)
 /**
  * wb_wait_for_completion - wait for completion of bdi_writeback_works
  * @done: target wb_completion
+ * @bdi: bdi work items were issued to, NULL for the memcg foreign flushes
  *
  * Wait for one or more work items issued to @bdi with their ->done field
  * set to @done, which should have been initialized with
@@ -220,11 +225,12 @@ static bool wb_wait_for_completion_cb(struct wb_completion *done)
  * are completed.  Work items which are waited upon aren't freed
  * automatically on completion.
  */
-void wb_wait_for_completion(struct wb_completion *done)
+void wb_wait_for_completion(struct wb_completion *done,
+			    struct backing_dev_info *bdi)
 {
 	done->wait_start = jiffies;
 	atomic_dec(&done->cnt);		/* put down the initial count */
-	wait_event(*done->waitq, wb_wait_for_completion_cb(done));
+	wait_event(*done->waitq, wb_wait_for_completion_cb(done, bdi));
 }
 
 #ifdef CONFIG_CGROUP_WRITEBACK
@@ -1164,7 +1170,7 @@ static void bdi_split_work_to_wbs(struct backing_dev_info *bdi,
 		last_wb = wb;
 
 		rcu_read_unlock();
-		wb_wait_for_completion(&fallback_work_done);
+		wb_wait_for_completion(&fallback_work_done, bdi);
 		goto restart;
 	}
 	rcu_read_unlock();
@@ -2972,7 +2978,7 @@ static void __writeback_inodes_sb_nr(struct super_block *sb, unsigned long nr,
 	WARN_ON(!rwsem_is_locked(&sb->s_umount));
 
 	bdi_split_work_to_wbs(sb->s_bdi, &work, skip_if_busy);
-	wb_wait_for_completion(&done);
+	wb_wait_for_completion(&done, bdi);
 }
 
 /**
@@ -3069,7 +3075,7 @@ void sync_inodes_sb(struct super_block *sb)
 	/* protect against inode wb switch, see inode_switch_wbs_work_fn() */
 	bdi_down_write_wb_switch_rwsem(bdi);
 	bdi_split_work_to_wbs(bdi, &work, false);
-	wb_wait_for_completion(&done);
+	wb_wait_for_completion(&done, bdi);
 	bdi_up_write_wb_switch_rwsem(bdi);
 
 	wait_sb_inodes(sb);
diff --git a/include/linux/backing-dev.h b/include/linux/backing-dev.h
index c2284466e7aa66..808d939d2ca7f9 100644
--- a/include/linux/backing-dev.h
+++ b/include/linux/backing-dev.h
@@ -39,7 +39,8 @@ struct backing_dev_info *bdi_alloc(int node_id);
 void wb_start_background_writeback(struct bdi_writeback *wb);
 void wb_workfn(struct work_struct *work);
 
-void wb_wait_for_completion(struct wb_completion *done);
+void wb_wait_for_completion(struct wb_completion *done,
+			    struct backing_dev_info *bdi);
 
 extern spinlock_t bdi_lock;
 extern struct list_head bdi_list;
diff --git a/mm/memcontrol.c b/mm/memcontrol.c
index ac6c43ea8c5a6d..df462d279a655e 100644
--- a/mm/memcontrol.c
+++ b/mm/memcontrol.c
@@ -4525,7 +4525,7 @@ static void mem_cgroup_css_free(struct cgroup_subsys_state *css)
 
 #ifdef CONFIG_CGROUP_WRITEBACK
 	for (i = 0; i < MEMCG_CGWB_FRN_CNT; i++)
-		wb_wait_for_completion(&memcg->cgwb_frn[i].done);
+		wb_wait_for_completion(&memcg->cgwb_frn[i].done, NULL);
 #endif
 	if (cgroup_subsys_on_dfl(memory_cgrp_subsys) && !cgroup_memory_nosocket)
 		static_branch_dec(&memcg_sockets_enabled_key);

-- 
2.53.0-Meta

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

[Breno Leitao]

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

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

Re: [PATCH 1/4] writeback: add the missing newline to the slow writeback report

[Jan Kara]

On Fri 06-11-26 04:26:31, Breno Leitao wrote:
> wb_wait_for_completion_cb() reports a writeback wait that exceeds
> hung_task_timeout_secs with a pr_info() that has no trailing newline.
> printk() keeps such a record open for a continuation and does not
> finalize it, so dmesg, the consoles and netconsole only see the report
> once the next message is logged.
> 
> Terminate the message with a newline.
> 
> Fixes: d6e621590764 ("writeback: Add logging for slow writeback (exceeds sysctl_hung_task_timeout_secs)")
> Cc: stable@vger.kernel.org
> Signed-off-by: Breno Leitao <leitao@debian.org>

Sure. Feel free to add:

Reviewed-by: Jan Kara <jack@suse.cz>

								Honza

> ---
>  fs/fs-writeback.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/fs/fs-writeback.c b/fs/fs-writeback.c
> index 15260cf2a29b09..01a00d7542b371 100644
> --- a/fs/fs-writeback.c
> +++ b/fs/fs-writeback.c
> @@ -204,7 +204,7 @@ static bool wb_wait_for_completion_cb(struct wb_completion *done)
>  	done->progress_stamp = jiffies;
>  	if (timeout && (waited_secs > timeout))
>  		pr_info("INFO: The task %s:%d has been waiting for writeback "
> -			"completion for more than %lu seconds.",
> +			"completion for more than %lu seconds.\n",
>  			current->comm, current->pid, waited_secs);
>  
>  	return !atomic_read(&done->cnt);
> 
> -- 
> 2.53.0-Meta
> 
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

Re: [PATCH 2/4] writeback: name the bdi in the slow writeback report

[Jan Kara]

On Fri 06-11-26 04:26:32, Breno Leitao wrote:
> The slow writeback report names the waiting task and how long it has
> waited, but not what it is waiting on. On a machine with several
> filesystems there is no way to tell which device is slow.
> 
> Pass the bdi to wb_wait_for_completion() and print its name on a second
> line, together with the number of work items still outstanding. A sync
> issues one work item per cgroup wb with dirty inodes, so the count also
> shows whether a single cgroup is holding up the others.
> 
> wb_wait_for_completion() took the bdi until commit 5b9cce4c7eb0
> ("writeback: Generalize and expose wb_completion") made it usable for
> the memcg foreign flushes. memcg tracks those by bdi id only and passes
> NULL, which bdi_dev_name() prints as "(unknown)".
> 
> The first line does not change, so anything matching on it keeps
> working. A sync on a throttled null_blk device now reports:
> 
>   INFO: The task sync:180 has been waiting for writeback completion for more than 28 seconds.
>         bdi 252:0, work items left: 1
> 
> Signed-off-by: Breno Leitao <leitao@debian.org>

Dunno, I'd put everything on one line. Otherwise things can get interleaved
by other messages. Kernel messages are not really an ABI, we can change
them...

								Honza

> ---
>  fs/fs-writeback.c           | 20 +++++++++++++-------
>  include/linux/backing-dev.h |  3 ++-
>  mm/memcontrol.c             |  2 +-
>  3 files changed, 16 insertions(+), 9 deletions(-)
> 
> diff --git a/fs/fs-writeback.c b/fs/fs-writeback.c
> index 01a00d7542b371..3dee9d65eaf721 100644
> --- a/fs/fs-writeback.c
> +++ b/fs/fs-writeback.c
> @@ -196,16 +196,20 @@ static void wb_queue_work(struct bdi_writeback *wb,
>  	spin_unlock_irq(&wb->work_lock);
>  }
>  
> -static bool wb_wait_for_completion_cb(struct wb_completion *done)
> +static bool wb_wait_for_completion_cb(struct wb_completion *done,
> +				      struct backing_dev_info *bdi)
>  {
>  	unsigned long timeout = sysctl_hung_task_timeout_secs;
>  	unsigned long waited_secs = (jiffies - done->wait_start) / HZ;
>  
>  	done->progress_stamp = jiffies;
> -	if (timeout && (waited_secs > timeout))
> +	if (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));
> +	}
>  
>  	return !atomic_read(&done->cnt);
>  }
> @@ -213,6 +217,7 @@ static bool wb_wait_for_completion_cb(struct wb_completion *done)
>  /**
>   * wb_wait_for_completion - wait for completion of bdi_writeback_works
>   * @done: target wb_completion
> + * @bdi: bdi work items were issued to, NULL for the memcg foreign flushes
>   *
>   * Wait for one or more work items issued to @bdi with their ->done field
>   * set to @done, which should have been initialized with
> @@ -220,11 +225,12 @@ static bool wb_wait_for_completion_cb(struct wb_completion *done)
>   * are completed.  Work items which are waited upon aren't freed
>   * automatically on completion.
>   */
> -void wb_wait_for_completion(struct wb_completion *done)
> +void wb_wait_for_completion(struct wb_completion *done,
> +			    struct backing_dev_info *bdi)
>  {
>  	done->wait_start = jiffies;
>  	atomic_dec(&done->cnt);		/* put down the initial count */
> -	wait_event(*done->waitq, wb_wait_for_completion_cb(done));
> +	wait_event(*done->waitq, wb_wait_for_completion_cb(done, bdi));
>  }
>  
>  #ifdef CONFIG_CGROUP_WRITEBACK
> @@ -1164,7 +1170,7 @@ static void bdi_split_work_to_wbs(struct backing_dev_info *bdi,
>  		last_wb = wb;
>  
>  		rcu_read_unlock();
> -		wb_wait_for_completion(&fallback_work_done);
> +		wb_wait_for_completion(&fallback_work_done, bdi);
>  		goto restart;
>  	}
>  	rcu_read_unlock();
> @@ -2972,7 +2978,7 @@ static void __writeback_inodes_sb_nr(struct super_block *sb, unsigned long nr,
>  	WARN_ON(!rwsem_is_locked(&sb->s_umount));
>  
>  	bdi_split_work_to_wbs(sb->s_bdi, &work, skip_if_busy);
> -	wb_wait_for_completion(&done);
> +	wb_wait_for_completion(&done, bdi);
>  }
>  
>  /**
> @@ -3069,7 +3075,7 @@ void sync_inodes_sb(struct super_block *sb)
>  	/* protect against inode wb switch, see inode_switch_wbs_work_fn() */
>  	bdi_down_write_wb_switch_rwsem(bdi);
>  	bdi_split_work_to_wbs(bdi, &work, false);
> -	wb_wait_for_completion(&done);
> +	wb_wait_for_completion(&done, bdi);
>  	bdi_up_write_wb_switch_rwsem(bdi);
>  
>  	wait_sb_inodes(sb);
> diff --git a/include/linux/backing-dev.h b/include/linux/backing-dev.h
> index c2284466e7aa66..808d939d2ca7f9 100644
> --- a/include/linux/backing-dev.h
> +++ b/include/linux/backing-dev.h
> @@ -39,7 +39,8 @@ struct backing_dev_info *bdi_alloc(int node_id);
>  void wb_start_background_writeback(struct bdi_writeback *wb);
>  void wb_workfn(struct work_struct *work);
>  
> -void wb_wait_for_completion(struct wb_completion *done);
> +void wb_wait_for_completion(struct wb_completion *done,
> +			    struct backing_dev_info *bdi);
>  
>  extern spinlock_t bdi_lock;
>  extern struct list_head bdi_list;
> diff --git a/mm/memcontrol.c b/mm/memcontrol.c
> index ac6c43ea8c5a6d..df462d279a655e 100644
> --- a/mm/memcontrol.c
> +++ b/mm/memcontrol.c
> @@ -4525,7 +4525,7 @@ static void mem_cgroup_css_free(struct cgroup_subsys_state *css)
>  
>  #ifdef CONFIG_CGROUP_WRITEBACK
>  	for (i = 0; i < MEMCG_CGWB_FRN_CNT; i++)
> -		wb_wait_for_completion(&memcg->cgwb_frn[i].done);
> +		wb_wait_for_completion(&memcg->cgwb_frn[i].done, NULL);
>  #endif
>  	if (cgroup_subsys_on_dfl(memory_cgrp_subsys) && !cgroup_memory_nosocket)
>  		static_branch_dec(&memcg_sockets_enabled_key);
> 
> -- 
> 2.53.0-Meta
> 
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

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

[Jan Kara]

On Fri 06-11-26 04:26:33, Breno Leitao wrote:
> 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>

Looks good. Feel free to add:

Reviewed-by: Jan Kara <jack@suse.cz>

								Honza

> ---
>  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
> 
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

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

[Jan Kara]

On Fri 06-11-26 04:26:34, Breno Leitao wrote:
> 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@debian.org>

Now I'm waiting for someone to complain it gets written out too
infrequently :). Is this change substantially different from
writeback_sb_inodes() waking up done->waitq less frequently?

								Honza

> ---
>  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
> 
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

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

[Breno Leitao]

On Fri, Nov 06, 2026 at 03:37:45PM +0100, Jan Kara wrote:
> On Fri 06-11-26 04:26:34, Breno Leitao wrote:
> > 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@debian.org>
> 
> Now I'm waiting for someone to complain it gets written out too
> infrequently :). 

Once per timeout is also how often the hung task detector checks by
default, and patch 3 logs the total once the wait ends, so maybe that is
exactly what people need? Not sure.

> Is this change substantially different from
> writeback_sb_inodes() waking up done->waitq less frequently?

You mean the ->progress_stamp field? That is not used for reporting
purposes, right? Should it be?

It could drop the duplicates: a wakeup with work left runs the
wait_event() condition twice (since 84654c7f4730, it is checked right
after schedule() and again after prepare_to_wait_event()), and the
second check would find ->progress_stamp just refreshed by the first.

But the waiter refreshes ->progress_stamp on every wakeup, so it cannot
space the reports further apart than the wakeups, and those have to
come more often than the hung task timeout.

So it is a choice between a report every half timeout with no new
field, or once per timeout with report_stamp. Which one do you prefer?

Thanks for the review,
--breno

Re: [PATCH 2/4] writeback: name the bdi in the slow writeback report

[Breno Leitao]

On Fri, Nov 06, 2026 at 03:27:49PM +0100, Jan Kara wrote:
> On Fri 06-11-26 04:26:32, Breno Leitao wrote:
> > The slow writeback report names the waiting task and how long it has
> > waited, but not what it is waiting on. On a machine with several
> > filesystems there is no way to tell which device is slow.
> > 
> > Pass the bdi to wb_wait_for_completion() and print its name on a second
> > line, together with the number of work items still outstanding. A sync
> > issues one work item per cgroup wb with dirty inodes, so the count also
> > shows whether a single cgroup is holding up the others.
> > 
> > wb_wait_for_completion() took the bdi until commit 5b9cce4c7eb0
> > ("writeback: Generalize and expose wb_completion") made it usable for
> > the memcg foreign flushes. memcg tracks those by bdi id only and passes
> > NULL, which bdi_dev_name() prints as "(unknown)".
> > 
> > The first line does not change, so anything matching on it keeps
> > working. A sync on a throttled null_blk device now reports:
> > 
> >   INFO: The task sync:180 has been waiting for writeback completion for more than 28 seconds.
> >         bdi 252:0, work items left: 1
> > 
> > Signed-off-by: Breno Leitao <leitao@debian.org>
> 
> Dunno, I'd put everything on one line. Otherwise things can get interleaved
> by other messages. Kernel messages are not really an ABI, we can change
> them...

Ack!

I will get them in a single line and respin,

--breno