writeback hang in current mainline

When running xfstests on current Linus' tree I get the following reproducible hang during test 013:

013 76s ...[ 196.150570] XFS mounting filesystem vdb5

[  360.596137] INFO: task fsstress:7898 blocked for more than 120
seconds.
[  360.598053] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[  360.600678] fsstress      D 00000006     0  7898   7897 0x00000000
[  360.602661]  f3a1beb0 00000046 f3a1be84 00000006 c1e164a0 00000282
f3a1be8c c0e5f980
[  360.606072]  f3eca340 f5c07540 c0e5f980 c0e5f980 f3eca340 c01805d9
f3a1bee4 00000000
[  360.609495]  f3a1beec f3a1beb8 c0222b38 f3a1bed4 c08fcf35 c0222b30
c1e164a0 c1e164a0
[  360.612944] Call Trace:
[  360.613918]  [<c01805d9>] ? prepare_to_wait+0x49/0x70
[  360.615432]  [<c0222b38>] bdi_sched_wait+0x8/0x10
[  360.617019]  [<c08fcf35>] __wait_on_bit+0x45/0x70
[  360.618448]  [<c0222b30>] ? bdi_sched_wait+0x0/0x10
[  360.619934]  [<c0222b30>] ? bdi_sched_wait+0x0/0x10
[  360.621520]  [<c08fd003>] out_of_line_wait_on_bit+0xa3/0xb0
[  360.623169]  [<c0180390>] ? wake_bit_function+0x0/0x50
[  360.624812]  [<c0222d1c>] bdi_alloc_queue_work+0xac/0x110
[  360.626395]  [<c0247470>] ? vfs_quota_sync+0x0/0x2b0
[  360.627961]  [<c0222dc7>] bdi_start_writeback+0x47/0x50
[  360.629632]  [<c0222e11>] writeback_inodes_sb_locked+0x41/0x50
[  360.631319]  [<c022721a>] __sync_filesystem+0x4a/0x90
[  360.632955]  [<c022727a>] sync_one_sb+0x1a/0x20
[  360.634360]  [<c020959c>] iterate_supers+0x6c/0xa0
[  360.635842]  [<c0227260>] ? sync_one_sb+0x0/0x20
[  360.637372]  [<c02272a4>] sys_sync+0x24/0x60
[  360.638751]  [<c013075c>] sysenter_do_call+0x12/0x3c
[  360.640321] 1 lock held by fsstress/7898:
[  360.641623]  #0:  (&type->s_umount_key#19){++++..}, at: [<c020958d>]

iterate_supers+0x5d/0xa0

This works fine with the xfs tree which has the same xfs code, but is otherwise at 2.6.34 level.

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>

Not good, can you see if reverting 7c8a3554 makes it go away?

Jens Axboe

Reverting back to the revision before 7c8a3554 gives me lots of warnings ala:

[  178.253431] ------------[ cut here ]------------
[  178.256845] WARNING: at
/home/hch/work/linux-2.6/fs/fs-writeback.c:596
writeback_inodes_wb+0x423/0x440()
[  178.259995] Hardware name: Bochs
[  178.261270] Modules linked in:
[  178.262508] Pid: 2298, comm: flush-253:16 Tainted: G        W
2.6.34-rc5 #121
[  178.265199] Call Trace:
[  178.266210]  [<c08d86ca>] ? printk+0x18/0x1a
[  178.267597]  [<c0162d0d>] warn_slowpath_common+0x6d/0xa0
[  178.269296]  [<c0216ff3>] ? writeback_inodes_wb+0x423/0x440
[  178.271348]  [<c0216ff3>] ? writeback_inodes_wb+0x423/0x440
[  178.273121]  [<c0162d55>] warn_slowpath_null+0x15/0x20
[  178.274681]  [<c0216ff3>] writeback_inodes_wb+0x423/0x440
[  178.276390]  [<c0217111>] wb_writeback+0x101/0x1b0
[  178.277846]  [<c01a9a79>] ? __call_rcu+0x99/0x130
[  178.279287]  [<c01a9b38>] ? call_rcu+0x8/0x10
[  178.281110]  [<c02161fa>] ? wb_clear_pending+0x7a/0xa0
[  178.282673]  [<c021728f>] wb_do_writeback+0xcf/0x1a0
[  178.284239]  [<c02171e0>] ? wb_do_writeback+0x20/0x1a0
[  178.285823]  [<c021738a>] bdi_writeback_task+0x2a/0x90
[  178.287371]  [<c01dca90>] ? bdi_start_fn+0x0/0xb0
[  178.288992]  [<c01dcae8>] bdi_start_fn+0x58/0xb0
[  178.290823]  [<c01dca90>] ? bdi_start_fn+0x0/0xb0
[  178.292378]  [<c017dc7c>] kthread+0x6c/0x80
[  178.293711]  [<c017dc10>] ? kthread+0x0/0x80
[  178.295073]  [<c013023a>] kernel_thread_helper+0x6/0x1c
[  178.296753] ---[ end trace a7919e7f17c0a80f ]---

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>

Oops yes, you need to revert the parent too. But nevermind, I think I see the issue. Can you try the below (go back to -git again)?

index ea8592b..5e6cc61 100644
@@ -121,6 +121,7 @@ static void bdi_work_free(struct rcu_head *head)
 static void wb_work_complete(struct bdi_work *work)
 {
 	const enum writeback_sync_modes sync_mode = work->args.sync_mode;
+	const int caller_frees = work->args.sb_pinned;
 	int onstack = bdi_work_on_stack(work);
 
 	/*

@@ -131,7 +132,7 @@ static void wb_work_complete(struct bdi_work *work)
 	 */
 	if (!onstack)
 		bdi_work_clear(work);
-	if (sync_mode == WB_SYNC_NONE || onstack)
+	if ((sync_mode == WB_SYNC_NONE && caller_frees) || onstack)
 		call_rcu(&work->rcu_head, bdi_work_free);
 }
 

@@ -206,8 +207,10 @@ static void bdi_alloc_queue_work(struct backing_dev_info *bdi,
 	if (work) {
 		bdi_work_init(work, args);
 		bdi_queue_work(bdi, work);
-		if (wait)
+		if (wait) {
 			bdi_wait_on_work_clear(work);
+			kfree(work);
+		}
 	} else {
 		struct bdi_writeback *wb = &bdi->wb;
 

Jens Axboe

This one crashes during mount of the first XFS fs in a really strange way:

[   44.897741] XFS mounting filesystem vdb6
[   45.188094] BUG: unable to handle kernel paging request at 6b6b6b6b
[   45.190150] IP: [<6b6b6b6b>] 0x6b6b6b6b
[   45.191531] *pde = 00000000 
[   45.192055] Oops: 0010 [#1] SMP 
[   45.192055] last sysfs file: /sys/devices/virtual/net/lo/operstate
[   45.192055] Modules linked in:
[   45.192055] 
[   45.192055] Pid: 1216, comm: udevd Not tainted 2.6.34 #123 /Bochs
[   45.192055] EIP: 0060:[<6b6b6b6b>] EFLAGS: 00010202 CPU: 0
[   45.192055] EIP is at 0x6b6b6b6b
[   45.192055] EAX: f5c501e8 EBX: c2144120 ECX: 00000000 EDX: f5c501e8
[   45.192055] ESI: f3ebbe9c EDI: 00000001 EBP: f6fdfab0 ESP: f6fdfa8c
[   45.192055]  DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
[   45.192055] Process udevd (pid: 1216, ti=f6fde000 task=f6fe2d70
task.ti=f6fde000)
[   45.192055] Stack:
[   45.192055]  c01b3e0c 00000296 f6fe2d70 f3ebbe9c c2144138 c0c50e00
00000001 00000024
[   45.192055] <0> 00000009 f6fdfab8 c01b4060 f6fdfb00 c016a828 c01862a4
856a5530 0000000a
[   45.192055] <0> 856aedde 0000000a c2003f84 c0c2ea24 0000000a 00000000
0000000a 00000000
[   45.192055] Call Trace:
[   45.192055]  [<c01b3e0c>] ? __rcu_process_callbacks+0x10c/0x340
[   45.192055]  [<c01b4060>] ? rcu_process_callbacks+0x20/0x40
[   45.192055]  [<c016a828>] ? __do_softirq+0x98/0x1c0
[   45.192055]  [<c01862a4>] ? sched_clock_local+0xa4/0x180
[   45.192055]  [<c016a9b5>] ? do_softirq+0x65/0x70
[   45.192055]  [<c016ab3d>] ? irq_exit+0x6d/0x80
[   45.192055]  [<c01467c6>] ? smp_apic_timer_interrupt+0x56/0x90
[   45.192055]  [<c06c06a4>] ? trace_hardirqs_off_thunk+0xc/0x18
[   45.192055]  [<c08ff5ef>] ? apic_timer_interrupt+0x2f/0x34
[   45.192055]  [<c0196aaa>] ? lock_release+0xca/0x220
[   45.192055]  [<c08fef66>] ? _raw_spin_unlock+0x16/0x20
[   45.192055]  [<c088a551>] ? unix_peer_get+0x31/0x40
[   45.192055]  [<c088b527>] ? unix_dgram_poll+0xd7/0x160
[   45.192055]  [<c080d582>] ? sock_poll+0x12/0x20
[   45.192055]  [<c0215d53>] ? do_sys_poll+0x223/0x480
[   45.192055]  [<c0215a00>] ? __pollwait+0x0/0xd0
[   45.192055]  [<c0215ad0>] ? pollwake+0x0/0x60
[   45.192055]  [<c0215ad0>] ? pollwake+0x0/0x60
[   45.192055]  [<c0215ad0>] ? pollwake+0x0/0x60
[   45.192055]  [<c0135898>] ? sched_clock+0x8/0x10
[   45.192055]  [<c01862a4>] ? sched_clock_local+0xa4/0x180
[   45.192055]  [<c01864a9>] ? sched_clock_cpu+0x129/0x180
[   45.192055]  [<c014f1f5>] ? pvclock_clocksource_read+0xf5/0x190
[   45.192055]  [<c014f1f5>] ? pvclock_clocksource_read+0xf5/0x190
[   45.192055]  [<c014e5f7>] ? kvm_clock_read+0x17/0x20
[   45.192055]  [<c0135898>] ? sched_clock+0x8/0x10
[   45.192055]  [<c01862a4>] ? sched_clock_local+0xa4/0x180
[   45.192055]  [<c01864a9>] ? sched_clock_cpu+0x129/0x180
[   45.192055]  [<c01955c3>] ? __lock_acquire+0x2f3/0x1310
[   45.192055]  [<c019162b>] ? trace_hardirqs_off+0xb/0x10
[   45.192055]  [<c018656d>] ? cpu_clock+0x6d/0x70
[   45.192055]  [<c01e8936>] ? might_fault+0x46/0xa0
[   45.192055]  [<c01e8936>] ? might_fault+0x46/0xa0
[   45.192055]  [<c01e8936>] ? might_fault+0x46/0xa0
[   45.192055]  [<c014f1f5>] ? pvclock_clocksource_read+0xf5/0x190
[   45.192055]  [<c014e5f7>] ? kvm_clock_read+0x17/0x20
[   45.192055]  [<c01898cb>] ? ktime_get_ts+0xdb/0x110
[   45.192055]  [<c0215234>] ? poll_select_set_timeout+0x64/0x70
[   45.192055]  [<c0216124>] ? sys_poll+0x54/0xb0
[   45.192055]  [<c013075c>] ? sysenter_do_call+0x12/0x3c
[   45.192055] Code:  Bad EIP value.
[   45.192055] EIP: [<6b6b6b6b>] 0x6b6b6b6b SS:ESP 0068:f6fdfa8c
[   45.192055] CR2: 000000006b6b6b6b
[   45.290509] ---[ end trace 09bdcdca6b9734ca ]---
[   45.291988] Kernel panic - not syncing: Fatal exception in interrupt
[   45.293915] Pid: 1216, comm: udevd Tainted: G      D     2.6.34 #123
[   45.295793] Call Trace:
[   45.296864]  [<c08fc07d>] ? printk+0x28/0x2a
[   45.298206]  [<c08fbfd8>] panic+0x42/0xbf
[   45.299515]  [<c09002f5>] oops_end+0xc5/0xd0
[   45.300972]  [<c015051e>] no_context+0xbe/0x150
[   45.302375]  [<c0150640>] __bad_area_nosemaphore+0x90/0x130
[   45.304218]  [<c0902196>] ? do_page_fault+0x226/0x430
[   45.305779]  [<c01506f2>] bad_area_nosemaphore+0x12/0x20
[   45.307345]  [<c09022f1>] do_page_fault+0x381/0x430
[   45.308949]  [<c018656d>] ? cpu_clock+0x6d/0x70
[   45.310344]  [<c08fef25>] ? _raw_spin_unlock_irqrestore+0x35/0x60
[   45.312154]  [<c0901f70>] ? do_page_fault+0x0/0x430
[   45.313663]  [<c08ff797>] error_code+0x6b/0x70
[   45.315095]  [<c0901f70>] ? do_page_fault+0x0/0x430
[   45.316690]  [<c01b3e0c>] ? __rcu_process_callbacks+0x10c/0x340
[   45.318380]  [<c01b4060>] rcu_process_callbacks+0x20/0x40
[   45.319999]  [<c016a828>] __do_softirq+0x98/0x1c0
[   45.321583]  [<c01862a4>] ? sched_clock_local+0xa4/0x180
[   45.323300]  [<c016a9b5>] do_softirq+0x65/0x70
[   45.324809]  [<c016ab3d>] irq_exit+0x6d/0x80
[   45.326213]  [<c01467c6>] smp_apic_timer_interrupt+0x56/0x90
[   45.336186]  [<c06c06a4>] ? trace_hardirqs_off_thunk+0xc/0x18
[   45.337865]  [<c08ff5ef>] apic_timer_interrupt+0x2f/0x34
[   45.339440]  [<c0196aaa>] ? lock_release+0xca/0x220
[   45.341016]  [<c08fef66>] _raw_spin_unlock+0x16/0x20
[   45.342623]  [<c088a551>] unix_peer_get+0x31/0x40
[   45.344207]  [<c088b527>] unix_dgram_poll+0xd7/0x160
[   45.345741]  [<c080d582>] sock_poll+0x12/0x20
[   45.347107]  [<c0215d53>] do_sys_poll+0x223/0x480
[   45.348694]  [<c0215a00>] ? __pollwait+0x0/0xd0
[   45.350108]  [<c0215ad0>] ? pollwake+0x0/0x60
[   45.351504]  [<c0215ad0>] ? pollwake+0x0/0x60
[   45.352963]  [<c0215ad0>] ? pollwake+0x0/0x60
[   45.354335]  [<c0135898>] ? sched_clock+0x8/0x10
[   45.355835]  [<c01862a4>] ? sched_clock_local+0xa4/0x180
[   45.357514]  [<c01864a9>] ? sched_clock_cpu+0x129/0x180
[   45.359075]  [<c014f1f5>] ? pvclock_clocksource_read+0xf5/0x190
[   45.360894]  [<c014f1f5>] ? pvclock_clocksource_read+0xf5/0x190
[   45.362683]  [<c014e5f7>] ? kvm_clock_read+0x17/0x20
[   45.364486]  [<c0135898>] ? sched_clock+0x8/0x10
[   45.365935]  [<c01862a4>] ? sched_clock_local+0xa4/0x180
[   45.367566]  [<c01864a9>] ? sched_clock_cpu+0x129/0x180
[   45.370936]  [<c01955c3>] ? __lock_acquire+0x2f3/0x1310
[   45.372679]  [<c019162b>] ? trace_hardirqs_off+0xb/0x10
[   45.374250]  [<c018656d>] ? cpu_clock+0x6d/0x70
[   45.375722]  [<c01e8936>] ? might_fault+0x46/0xa0
[   45.377291]  [<c01e8936>] ? might_fault+0x46/0xa0
[   45.378802]  [<c01e8936>] ? might_fault+0x46/0xa0
[   45.380367]  [<c014f1f5>] ? pvclock_clocksource_read+0xf5/0x190
[   45.382137]  [<c014e5f7>] ? kvm_clock_read+0x17/0x20
[   45.383851]  [<c01898cb>] ? ktime_get_ts+0xdb/0x110
[   45.385464]  [<c0215234>] ? poll_select_set_timeout+0x64/0x70
[   45.387150]  [<c0216124>] sys_poll+0x54/0xb0
[   45.388611]  [<c013075c>] sysenter_do_call+0x12/0x3c

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>

Clearly only half baked, weird. So from the looks of it:

it still ends up calling call_rcu() which I did not intend for it to do, I must have made a mistake. My test equipment is packed down these days, but I'll try on my workstation and send you a better patch.

Ugh ok I see it, I had the caller_frees reverted. Try this :-)

index ea8592b..e173d02 100644
@@ -121,6 +121,7 @@ static void bdi_work_free(struct rcu_head *head)
 static void wb_work_complete(struct bdi_work *work)
 {
 	const enum writeback_sync_modes sync_mode = work->args.sync_mode;
+	const int caller_frees = work->args.sb_pinned;
 	int onstack = bdi_work_on_stack(work);
 
 	/*

@@ -131,7 +132,7 @@ static void wb_work_complete(struct bdi_work *work)
 	 */
 	if (!onstack)
 		bdi_work_clear(work);
-	if (sync_mode == WB_SYNC_NONE || onstack)
+	if ((sync_mode == WB_SYNC_NONE && !caller_frees) || onstack)
 		call_rcu(&work->rcu_head, bdi_work_free);
 }
 

@@ -206,8 +207,10 @@ static void bdi_alloc_queue_work(struct backing_dev_info *bdi,
 	if (work) {
 		bdi_work_init(work, args);
 		bdi_queue_work(bdi, work);
-		if (wait)
+		if (wait) {
 			bdi_wait_on_work_clear(work);
+			kfree(work);
+		}
 	} else {
 		struct bdi_writeback *wb = &bdi->wb;
 

Jens Axboe

This seems to fix it. Running some more tests now.

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>

Goodie, then the analysis at least is correct. A potentially cleaner fix would be to just allocate the WB_SYNC_NONE && sb_pinned work struct on the stack, since then we can get rid of that nastiness in wb_work_complete() as well (and not pass 'sb_pinned' around so much).

If you have time, care to test this one as well?

index 5c4161f..e9d6182 100644
@@ -193,8 +193,7 @@ static void bdi_wait_on_work_clear(struct bdi_work *work)
 }
 
 static void bdi_alloc_queue_work(struct backing_dev_info *bdi,
-				 struct wb_writeback_args *args,
-				 int wait)
+				 struct wb_writeback_args *args)
 {
 	struct bdi_work *work;
 

@@ -206,8 +205,6 @@ static void bdi_alloc_queue_work(struct backing_dev_info *bdi,
 	if (work) {
 		bdi_work_init(work, args);
 		bdi_queue_work(bdi, work);
-		if (wait)
-			bdi_wait_on_work_clear(work);
 	} else {
 		struct bdi_writeback *wb = &bdi->wb;
 

@@ -216,6 +213,18 @@ static void bdi_alloc_queue_work(struct backing_dev_info *bdi,
 	}
 }
 
+static void bdi_queue_wait_wb_args(struct backing_dev_info *bdi,
+				   struct wb_writeback_args *args)
+{
+	struct bdi_work work;
+
+	bdi_work_init(&work, args);
+	work.state |= WS_ONSTACK;
+
+	bdi_queue_work(bdi, &work);
+	bdi_wait_on_work_clear(&work);
+}
+
 /**
  * bdi_sync_writeback - start and wait for writeback
  * @bdi: the backing device to write from

@@ -240,13 +249,8 @@ static void bdi_sync_writeback(struct backing_dev_info *bdi,
 		 */
 		.sb_pinned	= 1,
 	};
-	struct bdi_work work;
-
-	bdi_work_init(&work, &args);
-	work.state |= WS_ONSTACK;
 
-	bdi_queue_work(bdi, &work);
-	bdi_wait_on_work_clear(&work);
+	bdi_queue_wait_wb_args(bdi, &args);
 }
 
 /**

@@ -282,7 +286,10 @@ void bdi_start_writeback(struct backing_dev_info *bdi, struct super_block *sb,
 		args.for_background = 1;
 	}
 
-	bdi_alloc_queue_work(bdi, &args, sb_locked);
+	if (!sb_locked)
+		bdi_alloc_queue_work(bdi, &args);
+	else
+		bdi_queue_wait_wb_args(bdi, &args);
 }
 
 /*

@@ -1011,7 +1018,7 @@ static void bdi_writeback_all(struct super_block *sb, long nr_pages)
 		if (!bdi_has_dirty_io(bdi))
 			continue;
 
-		bdi_alloc_queue_work(bdi, &args, 0);
+		bdi_alloc_queue_work(bdi, &args);
 	}
 
 	rcu_read_unlock();

Jens Axboe

Both this and the previous one hang hard in xfstests 007, with no chance of getting a backtrace.

For now I would recommend to revert
21c12849fef73efc9a898b6702fe421fd774f515 and
29c795f02e68ecd7bb1374844d3e55e882ac158f,
which makes xfstests run fine for me.

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>

OK, thanks for the testing. I'll revert the two and work up a real solution once I have the test equipment online again.

Jens Axboe

BTW, if you have one more chance to test... Use the latest one, but also apply this one:

http://lkml.org/lkml/2010/5/26/215

which fixes a silly thinko that's closely related to this logic.

Jens Axboe

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to [email protected].  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>

I already had this applied during my test run for your second patch.

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>

OK. From your previous mail:

For now I would recommend to revert 21c12849fef73efc9a898b6702fe421fd774f515 and 29c795f02e68ecd7bb1374844d3e55e882ac158f, which makes xfstests run fine for me.

Just to ensure we are on the same page, what commits are these? They are not valid shas in Linus' tree. Did you mean

        e913fc825dc685a444cb4c1d0f9d32f372f59861
        7c8a3554c683f512dbcee26faedb42e4c05f12fa

?

Jens Axboe

Sorry, those were my local revert commits.

Exactly!

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>

Makes sense then. So the change from those commits (with the fixes from today) ensures that we properly do WB_SYNC_NONE writeback when sb->s_umount is held instead of just skipping those inodes. The question is, is that exposing some other bug or is the code still buggy...

You said that you could not get a backtrace when the test hung, were you able to get anything out of it?

Jens Axboe

No, the VM hung hard and I couldn't get any useful information.

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>