writeback: fix hung_task alarm when sync block

fs/fs-writeback.c +0 -0

index f2d0109..df879ee 100644
@@ -1311,7 +1311,11 @@ void writeback_inodes_sb_nr(struct super_block *sb,
 

Quoted 6 lines · Wanpeng Li

fs/fs-writeback.c +0 -0

index f2d0109..df879ee 100644
@@ -1311,7 +1311,11 @@ void writeback_inodes_sb_nr(struct super_block *sb,
 

fs/fs-writeback.c void writeback_inodes_sb_nr(struct super_block *sb, · line 1320

Quoted 10 lines

fs/fs-writeback.c +5 -1

 	WARN_ON(!rwsem_is_locked(&sb->s_umount));
 	bdi_queue_work(sb->s_bdi, &work);
-	wait_for_completion(&done);
+	if (sysctl_hung_task_timeout_secs)
+		while (!wait_for_completion_timeout(&done, HZ/2))
+			;
+	else
+		wait_for_completion(&done);
 }
 EXPORT_SYMBOL(writeback_inodes_sb_nr);

Is it really expected that writeback_inodes_sb_nr will routinely queue up more than 2 seconds worth of I/O (Yes, I understand that it isn't the only entity issuing I/O)?

For devices that are really slow, it may make
more sense to tune the system so that you don't have too much writeback I/O submitted at once. Dropping nr_requests for the given queue should fix this situation, I would think.

This really feels like we're papering over the problem.

Hi Jeff,

Quoted 8 lines · Jeff Moyer

Quoted 6 lines · Wanpeng Li

fs/fs-writeback.c +0 -0

index f2d0109..df879ee 100644
@@ -1311,7 +1311,11 @@ void writeback_inodes_sb_nr(struct super_block *sb,
 

Quoted 14 lines

fs/fs-writeback.c void writeback_inodes_sb_nr(struct super_block *sb, · line 1320

Quoted 10 lines

fs/fs-writeback.c +5 -1

 	WARN_ON(!rwsem_is_locked(&sb->s_umount));
 	bdi_queue_work(sb->s_bdi, &work);
-	wait_for_completion(&done);
+	if (sysctl_hung_task_timeout_secs)
+		while (!wait_for_completion_timeout(&done, HZ/2))
+			;
+	else
+		wait_for_completion(&done);
 }
 EXPORT_SYMBOL(writeback_inodes_sb_nr);

Is it really expected that writeback_inodes_sb_nr will routinely queue up more than 2 seconds worth of I/O (Yes, I understand that it isn't the only entity issuing I/O)?

Yes, in the case of syncing the whole superblock.
Basically sync() does its job in two steps:

for all sb:
writeback_inodes_sb_nr() # WB_SYNC_NONE
sync_inodes_sb() # WB_SYNC_ALL

Quoted 4 lines

For devices that are really slow, it may make
more sense to tune the system so that you don't have too much writeback I/O submitted at once. Dropping nr_requests for the given queue should fix this situation, I would think.

Hi Jeff,

Quoted 8 lines · Jeff Moyer

Quoted 6 lines · Wanpeng Li

fs/fs-writeback.c +0 -0

index f2d0109..df879ee 100644
@@ -1311,7 +1311,11 @@ void writeback_inodes_sb_nr(struct super_block *sb,
 

Quoted 14 lines

fs/fs-writeback.c void writeback_inodes_sb_nr(struct super_block *sb, · line 1320

Quoted 10 lines

fs/fs-writeback.c +5 -1

 	WARN_ON(!rwsem_is_locked(&sb->s_umount));
 	bdi_queue_work(sb->s_bdi, &work);
-	wait_for_completion(&done);
+	if (sysctl_hung_task_timeout_secs)
+		while (!wait_for_completion_timeout(&done, HZ/2))
+			;
+	else
+		wait_for_completion(&done);
 }
 EXPORT_SYMBOL(writeback_inodes_sb_nr);

Is it really expected that writeback_inodes_sb_nr will routinely queue up more than 2 seconds worth of I/O (Yes, I understand that it isn't the only entity issuing I/O)?

Yes, in the case of syncing the whole superblock.
Basically sync() does its job in two steps:

for all sb:
writeback_inodes_sb_nr() # WB_SYNC_NONE
sync_inodes_sb() # WB_SYNC_ALL

Quoted 4 lines

For devices that are really slow, it may make
more sense to tune the system so that you don't have too much writeback I/O submitted at once. Dropping nr_requests for the given queue should fix this situation, I would think.

The worried case is about sync() waiting

(nr_dirty + nr_writeback) / write_bandwidth

time, where it is nr_dirty that could grow rather large.

For example, if dirty threshold is 1GB and write_bandwidth is 10MB/s, the sync() will have to wait for 100 seconds. If there are heavy dirtiers running during the sync, it will typically take several hundreds of seconds (which looks not that good, but still much better than being livelocked in some old kernels)..

Quoted 1 line

This really feels like we're papering over the problem.

That's true. The majority users probably don't want to cache 100s worth of data in memory. It may be worthwhile to add a new per-bdi limit whose unit is number-of-seconds (of dirty data).

Quoted 50 lines · Fengguang Wu

Hi Jeff,

Quoted 8 lines · Jeff Moyer

Quoted 6 lines · Wanpeng Li

fs/fs-writeback.c +0 -0

index f2d0109..df879ee 100644
@@ -1311,7 +1311,11 @@ void writeback_inodes_sb_nr(struct super_block *sb,
 

Quoted 14 lines

fs/fs-writeback.c void writeback_inodes_sb_nr(struct super_block *sb, · line 1320

Quoted 10 lines

fs/fs-writeback.c +5 -1

 	WARN_ON(!rwsem_is_locked(&sb->s_umount));
 	bdi_queue_work(sb->s_bdi, &work);
-	wait_for_completion(&done);
+	if (sysctl_hung_task_timeout_secs)
+		while (!wait_for_completion_timeout(&done, HZ/2))
+			;
+	else
+		wait_for_completion(&done);
 }
 EXPORT_SYMBOL(writeback_inodes_sb_nr);

Is it really expected that writeback_inodes_sb_nr will routinely queue up more than 2 seconds worth of I/O (Yes, I understand that it isn't the only entity issuing I/O)?

Yes, in the case of syncing the whole superblock.
Basically sync() does its job in two steps:

for all sb:
writeback_inodes_sb_nr() # WB_SYNC_NONE
sync_inodes_sb() # WB_SYNC_ALL

Quoted 4 lines

For devices that are really slow, it may make
more sense to tune the system so that you don't have too much writeback I/O submitted at once. Dropping nr_requests for the given queue should fix this situation, I would think.

The worried case is about sync() waiting

(nr_dirty + nr_writeback) / write_bandwidth

time, where it is nr_dirty that could grow rather large.

For example, if dirty threshold is 1GB and write_bandwidth is 10MB/s, the sync() will have to wait for 100 seconds. If there are heavy dirtiers running during the sync, it will typically take several hundreds of seconds (which looks not that good, but still much better than being livelocked in some old kernels)..

Quoted 5 lines

Quoted 1 line

This really feels like we're papering over the problem.

That's true. The majority users probably don't want to cache 100s worth of data in memory. It may be worthwhile to add a new per-bdi limit whose unit is number-of-seconds (of dirty data).

Hi, Fengguang,

Another option is to limit the amount of time we wait to the amount of time we expect to have to wait. IOW, if we can estimate the amount of time we think the I/O will take to complete, we can set the hung_task_timeout[1] to *that* (with some fudge factor). Do you have a mechanism in place today to make such an estimate? The benefit of this solution is obvious: you still get notified when tasks are actually hung, but you don't get false warnings.

Good idea! Yes we can do some estimation and adaptively extend the hang timeout for the current writeback_inodes_sb_nr()/sync_inodes_sb() call.

Note that it's not going to reliably get rid of false warnings due to estimation errors, which could be pretty large and unavoidable on change of workload. But still, it would be a net improvement and perhaps enough to get rid of most false warnings, while still being able to catch livelock or other kind of task hang.

Quoted 9 lines · Fengguang Wu

Good idea! Yes we can do some estimation and adaptively extend the hang timeout for the current writeback_inodes_sb_nr()/sync_inodes_sb() call.

Note that it's not going to reliably get rid of false warnings due to estimation errors, which could be pretty large and unavoidable on change of workload. But still, it would be a net improvement and perhaps enough to get rid of most false warnings, while still being able to catch livelock or other kind of task hang.

Hi, Fengguang,

I didn't see a patch from you for this, so I went ahead and threw something together. Let me know what you think of it. I wasn't sure how to estimate the total I/O that will be issued for syncing out an entire superblock, though, so I didn't do that part.

Quoted 12 lines · Jeff Moyer

Quoted 9 lines · Fengguang Wu

Good idea! Yes we can do some estimation and adaptively extend the hang timeout for the current writeback_inodes_sb_nr()/sync_inodes_sb() call.

Note that it's not going to reliably get rid of false warnings due to estimation errors, which could be pretty large and unavoidable on change of workload. But still, it would be a net improvement and perhaps enough to get rid of most false warnings, while still being able to catch livelock or other kind of task hang.

Quoted 6 lines

Hi, Fengguang,

I didn't see a patch from you for this, so I went ahead and threw something together. Let me know what you think of it. I wasn't sure how to estimate the total I/O that will be issued for syncing out an entire superblock, though, so I didn't do that part.

As I said to the original patch - having a hang check timeout on a system that is overloaded w.r.t. IO is an important piece of information when it comes to debugging problems. Often the hangcheck timer is the first piece of information that we will get that indicates a problem somewhere in a production system.

Removing it does not magically fix the underlying problem - it simply means that we don't hear about them until someone complains that unmount is taking hours....

Quoted 20 lines · Dave Chinner

Quoted 12 lines · Jeff Moyer

Quoted 9 lines · Fengguang Wu

Good idea! Yes we can do some estimation and adaptively extend the hang timeout for the current writeback_inodes_sb_nr()/sync_inodes_sb() call.

Note that it's not going to reliably get rid of false warnings due to estimation errors, which could be pretty large and unavoidable on change of workload. But still, it would be a net improvement and perhaps enough to get rid of most false warnings, while still being able to catch livelock or other kind of task hang.

Quoted 6 lines

Hi, Fengguang,

I didn't see a patch from you for this, so I went ahead and threw something together. Let me know what you think of it. I wasn't sure how to estimate the total I/O that will be issued for syncing out an entire superblock, though, so I didn't do that part.

Quoted 5 lines

As I said to the original patch - having a hang check timeout on a system that is overloaded w.r.t. IO is an important piece of information when it comes to debugging problems. Often the hangcheck timer is the first piece of information that we will get that indicates a problem somewhere in a production system.

So, you believe that we should always check at 2 minute intervals (or whatever is configured), even if we know there is more than that much I/O queued? In case there is any confusion, here, the patch I posted ensured that we would eventually spew a warning, but only if the process was blocked for longer than we (the kernel) expected.

Quoted 3 lines

Removing it does not magically fix the underlying problem - it simply means that we don't hear about them until someone complains that unmount is taking hours....

There isn't necessarily an underlying problem. This is very much a gray area, Dave. We get plenty of false positives in this code. I was trying to reduce *that* problem. Do you have a better idea on how to address the issue?

Maybe this discussion requires looking at specific instances of the problem so we're all on the same page. What do you think is the best way forward, here?

Hi Jeff,

Quoted 8 lines · Jeff Moyer

Quoted 6 lines · Wanpeng Li

fs/fs-writeback.c +0 -0

index f2d0109..df879ee 100644
@@ -1311,7 +1311,11 @@ void writeback_inodes_sb_nr(struct super_block *sb,
 

Quoted 14 lines

fs/fs-writeback.c void writeback_inodes_sb_nr(struct super_block *sb, · line 1320

Quoted 10 lines

fs/fs-writeback.c +5 -1

 	WARN_ON(!rwsem_is_locked(&sb->s_umount));
 	bdi_queue_work(sb->s_bdi, &work);
-	wait_for_completion(&done);
+	if (sysctl_hung_task_timeout_secs)
+		while (!wait_for_completion_timeout(&done, HZ/2))
+			;
+	else
+		wait_for_completion(&done);
 }
 EXPORT_SYMBOL(writeback_inodes_sb_nr);

Is it really expected that writeback_inodes_sb_nr will routinely queue up more than 2 seconds worth of I/O (Yes, I understand that it isn't the only entity issuing I/O)?

Yes, in the case of syncing the whole superblock.
Basically sync() does its job in two steps:

for all sb:
writeback_inodes_sb_nr() # WB_SYNC_NONE
sync_inodes_sb() # WB_SYNC_ALL

Quoted 4 lines

For devices that are really slow, it may make
more sense to tune the system so that you don't have too much writeback I/O submitted at once. Dropping nr_requests for the given queue should fix this situation, I would think.

The worried case is about sync() waiting

(nr_dirty + nr_writeback) / write_bandwidth

time, where it is nr_dirty that could grow rather large.

For example, if dirty threshold is 1GB and write_bandwidth is 10MB/s, the sync() will have to wait for 100 seconds. If there are heavy dirtiers running during the sync, it will typically take several hundreds of seconds (which looks not that good, but still much better than being livelocked in some old kernels)..

Quoted 1 line

This really feels like we're papering over the problem.

That's true. The majority users probably don't want to cache 100s worth of data in memory. It may be worthwhile to add a new per-bdi limit whose unit is number-of-seconds (of dirty data).

Thanks,
Fengguang

Quoted 50 lines · Fengguang Wu

Hi Jeff,

Quoted 8 lines · Jeff Moyer

Quoted 6 lines · Wanpeng Li

fs/fs-writeback.c +0 -0

index f2d0109..df879ee 100644
@@ -1311,7 +1311,11 @@ void writeback_inodes_sb_nr(struct super_block *sb,
 

Quoted 14 lines

fs/fs-writeback.c void writeback_inodes_sb_nr(struct super_block *sb, · line 1320

Quoted 10 lines

fs/fs-writeback.c +5 -1

 	WARN_ON(!rwsem_is_locked(&sb->s_umount));
 	bdi_queue_work(sb->s_bdi, &work);
-	wait_for_completion(&done);
+	if (sysctl_hung_task_timeout_secs)
+		while (!wait_for_completion_timeout(&done, HZ/2))
+			;
+	else
+		wait_for_completion(&done);
 }
 EXPORT_SYMBOL(writeback_inodes_sb_nr);

Is it really expected that writeback_inodes_sb_nr will routinely queue up more than 2 seconds worth of I/O (Yes, I understand that it isn't the only entity issuing I/O)?

Yes, in the case of syncing the whole superblock.
Basically sync() does its job in two steps:

for all sb:
writeback_inodes_sb_nr() # WB_SYNC_NONE
sync_inodes_sb() # WB_SYNC_ALL

Quoted 4 lines

For devices that are really slow, it may make
more sense to tune the system so that you don't have too much writeback I/O submitted at once. Dropping nr_requests for the given queue should fix this situation, I would think.

The worried case is about sync() waiting

(nr_dirty + nr_writeback) / write_bandwidth

time, where it is nr_dirty that could grow rather large.

For example, if dirty threshold is 1GB and write_bandwidth is 10MB/s, the sync() will have to wait for 100 seconds. If there are heavy dirtiers running during the sync, it will typically take several hundreds of seconds (which looks not that good, but still much better than being livelocked in some old kernels)..

Quoted 5 lines

Quoted 1 line

This really feels like we're papering over the problem.

That's true. The majority users probably don't want to cache 100s worth of data in memory. It may be worthwhile to add a new per-bdi limit whose unit is number-of-seconds (of dirty data).

Hi Fengguang,

Maybe we have already have a threshold "dirty_expire_interval" to ensure pages will not dirty more than 30 seconds. Why should add a similar variable ? I think per-bdi flusher will try its best to flush dirty pages when waken up, just because the backing storages is too slow. :-)

Quoted 1 line

This really feels like we're papering over the problem.

That's true. The majority users probably don't want to cache 100s worth of data in memory. It may be worthwhile to add a new per-bdi limit whose unit is number-of-seconds (of dirty data).

From: Wanpeng Li <[email protected]>

"V1 -> V2"
* remove redundant hangcheck variable

I use several dd processes to write a slow SD card dd if=/dev/sda1 of=/dev/sdc4 bs=1M count=4000 and several sync commands(maybe > 10),dmesg show this:

[  366.888741] INFO: task sync:3518 blocked for more than 120 seconds.
[  366.888742] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  366.888746] sync            D 00000201     0  3518   3462 0x00000000
[  366.888752]  dcde5e54 00000082 00000000 00000201 00000000 c180d220 c1933d00 c1933d00
[  366.888758]  614a7ae7 00000023 f6bc0d00 ebecb280 c180d220 f6bc0d6c f04acbfc 00000000
[  366.888786]  f6bc0d6c dcde5e2c 00000023 f6bc0d44 00000000 00000000 ebd8b2b4 dcde5e6c
[  366.888788] Call Trace:
[  366.888792]  [<c107a0ee>] ? enqueue_entity+0xee/0x5a0
[  366.888795]  [<c15abc83>] schedule+0x23/0x60
[  366.888798]  [<c15aa5ad>] schedule_timeout+0x22d/0x2a0
[  366.888801]  [<c1071ce2>] ? check_preempt_curr+0x72/0x90
[  366.888804]  [<c1071d28>] ? ttwu_do_wakeup+0x28/0x130
[  366.888807]  [<c1037f28>] ? default_spin_lock_flags+0x8/0x10
[  366.888810]  [<c15acaad>] ? _raw_spin_lock_irqsave+0x2d/0x40
[  366.888813]  [<c15abb17>] wait_for_common+0xa7/0x110
[  366.888816]  [<c1074690>] ? try_to_wake_up+0x220/0x220
[  366.888819]  [<c15abc57>] wait_for_completion+0x17/0x20
[  366.888822]  [<c116ad80>] writeback_inodes_sb_nr+0x70/0x90
[  366.888825]  [<c116af75>] writeback_inodes_sb+0x25/0x30
[  366.888828]  [<c117159f>] __sync_filesystem+0x4f/0x90
[  366.888831]  [<c11715f7>] sync_one_sb+0x17/0x20
[  366.888834]  [<c114c430>] iterate_supers+0xc0/0xd0
[  366.888837]  [<c11715e0>] ? __sync_filesystem+0x90/0x90
[  366.888831]  [<c11715f7>] sync_one_sb+0x17/0x20
[  366.888834]  [<c114c430>] iterate_supers+0xc0/0xd0
[  366.888837]  [<c11715e0>] ? __sync_filesystem+0x90/0x90
[  366.888840]  [<c117167b>] sys_sync+0x2b/0x60
[  366.888842]  [<c15b385f>] sysenter_do_call+0x12/0x28

Too many similar messages flood the logs. So I use a present method to fix this issue.
------------------------------------------

Author: Mark Lord <[email protected]>
Date:   Fri Sep 24 09:51:13 2010 -0400

block: Prevent hang_check firing during long I/O
------------------------------------------

Signed-off-by Wanpeng Li <[email protected]>

---
fs/fs-writeback.c | 6 +++++-

1 file changed, 5 insertions(+), 1 deletion(-)

fs/fs-writeback.c +5 -1

index f2d0109..df879ee 100644
@@ -1311,7 +1311,11 @@ void writeback_inodes_sb_nr(struct super_block *sb,
 
 	WARN_ON(!rwsem_is_locked(&sb->s_umount));
 	bdi_queue_work(sb->s_bdi, &work);
-	wait_for_completion(&done);
+	if (sysctl_hung_task_timeout_secs)
+		while (!wait_for_completion_timeout(&done, HZ/2))
+			;
+	else
+		wait_for_completion(&done);
 }
 EXPORT_SYMBOL(writeback_inodes_sb_nr);
 

Signature · 1 line

1.7.9.5

Hi Fengguang,

This time it works well after testing.

Regards,
Wanpeng Li

From: Wanpeng Li <[email protected]>

"V1 -> V2"
* remove redundant hangcheck variable

I use several dd processes to write a slow SD card dd if=/dev/sda1 of=/dev/sdc4 bs=1M count=4000 and several sync commands(maybe > 10),dmesg show this:

[  366.888741] INFO: task sync:3518 blocked for more than 120 seconds.
[  366.888742] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  366.888746] sync            D 00000201     0  3518   3462 0x00000000
[  366.888752]  dcde5e54 00000082 00000000 00000201 00000000 c180d220 c1933d00 c1933d00
[  366.888758]  614a7ae7 00000023 f6bc0d00 ebecb280 c180d220 f6bc0d6c f04acbfc 00000000
[  366.888786]  f6bc0d6c dcde5e2c 00000023 f6bc0d44 00000000 00000000 ebd8b2b4 dcde5e6c
[  366.888788] Call Trace:
[  366.888792]  [<c107a0ee>] ? enqueue_entity+0xee/0x5a0
[  366.888795]  [<c15abc83>] schedule+0x23/0x60
[  366.888798]  [<c15aa5ad>] schedule_timeout+0x22d/0x2a0
[  366.888801]  [<c1071ce2>] ? check_preempt_curr+0x72/0x90
[  366.888804]  [<c1071d28>] ? ttwu_do_wakeup+0x28/0x130
[  366.888807]  [<c1037f28>] ? default_spin_lock_flags+0x8/0x10
[  366.888810]  [<c15acaad>] ? _raw_spin_lock_irqsave+0x2d/0x40
[  366.888813]  [<c15abb17>] wait_for_common+0xa7/0x110
[  366.888816]  [<c1074690>] ? try_to_wake_up+0x220/0x220
[  366.888819]  [<c15abc57>] wait_for_completion+0x17/0x20
[  366.888822]  [<c116ad80>] writeback_inodes_sb_nr+0x70/0x90
[  366.888825]  [<c116af75>] writeback_inodes_sb+0x25/0x30
[  366.888828]  [<c117159f>] __sync_filesystem+0x4f/0x90
[  366.888831]  [<c11715f7>] sync_one_sb+0x17/0x20
[  366.888834]  [<c114c430>] iterate_supers+0xc0/0xd0
[  366.888837]  [<c11715e0>] ? __sync_filesystem+0x90/0x90
[  366.888831]  [<c11715f7>] sync_one_sb+0x17/0x20
[  366.888834]  [<c114c430>] iterate_supers+0xc0/0xd0
[  366.888837]  [<c11715e0>] ? __sync_filesystem+0x90/0x90
[  366.888840]  [<c117167b>] sys_sync+0x2b/0x60
[  366.888842]  [<c15b385f>] sysenter_do_call+0x12/0x28

Too many similar messages flood the logs. So I use a present method to fix this issue.