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

[PATCH v2 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 wakes the
   waiter and 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:

  [    9.262814] INFO: The task sync:276 has been waiting for writeback completion for more than 5 seconds (bdi 252:0, work items left: 2).
  [   14.683024] INFO: The task sync:276 has been waiting for writeback completion for more than 10 seconds (bdi 252:0, work items left: 2).
  [   20.103027] INFO: The task sync:276 has been waiting for writeback completion for more than 16 seconds (bdi 252:0, work items left: 2).
  [   25.222884] INFO: The task sync:276 has been waiting for writeback completion for more than 21 seconds (bdi 252:0, work items left: 2).
  [   30.542836] INFO: The task sync:276 has been waiting for writeback completion for more than 26 seconds (bdi 252:0, work items left: 2).
  [   33.562975] The task sync:276 waited 29 seconds for writeback completion on bdi 252:0

Without patch 4, the same test logs 18 reports.

Signed-off-by: Breno Leitao <leitao@debian.org>
---
Changes in v2:
- Print the bdi and the work items left on the report line itself (Jan)
- Patch 4: wake the waiter once per timeout instead of adding
  report_stamp (Jan); its changelog shows the hung task warnings that
  this can bring back
- Patch 4: the doubled reports come from wait_event() checking the
  condition twice per wakeup, not from the two flushers
- Collect Jan's Reviewed-by on patches 1 and 3 (patch 3 rebased on the
  one-line report)
- Link to v1: https://patch.msgid.link/20261106-writeback_stall_report-v1-0-bf0c3b9023a5@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           | 40 ++++++++++++++++++++++++++++------------
 include/linux/backing-dev.h |  3 ++-
 mm/memcontrol.c             |  2 +-
 3 files changed, 31 insertions(+), 14 deletions(-)
---
base-commit: 8b7179210b22f8e48a82c5ceacb9d56a9c4cfec4
change-id: 20261105-writeback_stall_report-170750a69946

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

[PATCH v2 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
Reviewed-by: Jan Kara <jack@suse.cz>
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 v2 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 add its name to the
report, 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)".

A sync of files dirtied from two cgroups, on a throttled null_blk
device, now reports:

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

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, 15 insertions(+), 10 deletions(-)

diff --git a/fs/fs-writeback.c b/fs/fs-writeback.c
index 01a00d7542b371..c5e9e5c0d506a9 100644
--- a/fs/fs-writeback.c
+++ b/fs/fs-writeback.c
@@ -196,7 +196,8 @@ 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;
@@ -204,8 +205,9 @@ 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.\n",
-			current->comm, current->pid, waited_secs);
+			"completion for more than %lu seconds (bdi %s, work items left: %d).\n",
+			current->comm, current->pid, waited_secs,
+			bdi_dev_name(bdi), atomic_read(&done->cnt));
 
 	return !atomic_read(&done->cnt);
 }
@@ -213,6 +215,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 +223,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 +1168,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 +2976,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 +3073,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

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

[Jan Kara]

On Tue 10-11-26 03:39:28, 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 add its name to the
> report, 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)".
> 
> A sync of files dirtied from two cgroups, on a throttled null_blk
> device, now reports:
> 
>   [   10.043698] INFO: The task sync:276 has been waiting for writeback completion for more than 7 seconds (bdi 252:0, work items left: 2).
> 
> 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           | 20 ++++++++++++--------
>  include/linux/backing-dev.h |  3 ++-
>  mm/memcontrol.c             |  2 +-
>  3 files changed, 15 insertions(+), 10 deletions(-)
> 
> diff --git a/fs/fs-writeback.c b/fs/fs-writeback.c
> index 01a00d7542b371..c5e9e5c0d506a9 100644
> --- a/fs/fs-writeback.c
> +++ b/fs/fs-writeback.c
> @@ -196,7 +196,8 @@ 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;
> @@ -204,8 +205,9 @@ 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.\n",
> -			current->comm, current->pid, waited_secs);
> +			"completion for more than %lu seconds (bdi %s, work items left: %d).\n",
> +			current->comm, current->pid, waited_secs,
> +			bdi_dev_name(bdi), atomic_read(&done->cnt));
>  
>  	return !atomic_read(&done->cnt);
>  }
> @@ -213,6 +215,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 +223,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 +1168,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 +2976,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 +3073,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

[PATCH v2 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:

  [   31.763963] INFO: The task sync:276 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:

  [   31.807879] The task sync:275 waited 29 seconds for writeback completion on bdi 252:0

Reviewed-by: Jan Kara <jack@suse.cz>
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 c5e9e5c0d506a9..e2da4781b5e00b 100644
--- a/fs/fs-writeback.c
+++ b/fs/fs-writeback.c
@@ -201,15 +201,16 @@ 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 (bdi %s, work items left: %d).\n",
 			current->comm, current->pid, waited_secs,
-			bdi_dev_name(bdi), atomic_read(&done->cnt));
+			bdi_dev_name(bdi), left);
 
-	return !atomic_read(&done->cnt);
+	return !left;
 }
 
 /**
@@ -226,9 +227,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 v2 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 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

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

[Jan Kara]

On Tue 10-11-26 03:39:30, Breno Leitao wrote:
> 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>

Looks good to me! Feel free to add:

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

								Honza

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