Bug 14430

Summary: sync() hangs in bdi_sched_wait
Product: IO/Storage Reporter: Petr Vandrovec (petr)
Component: Block LayerAssignee: Jens Axboe (axboe)
Status: CLOSED UNREPRODUCIBLE    
Severity: normal CC: rjw, shiwenlu518
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 2.6.32-rc5 Subsystem:
Regression: Yes Bisected commit-id:
Bug Depends on:    
Bug Blocks: 14230    
Attachments: kernel log

Description Petr Vandrovec 2009-10-17 19:14:09 UTC
Created attachment 23449 [details]
kernel log

Hello,
  when I upgraded from 2.6.31 to 2.6.32-rc5, syslinux once hung on me in sync().  When I tried to reproduce it, I was not able to yet.

INFO: task syslinux:4439 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
syslinux      D ffff8800033d5e40     0  4439   2283 0x00020000
BUG: using smp_processor_id() in preemptible [00000000] code: khungtaskd/400
caller is show_stack_log_lvl+0x29/0x150
Pid: 400, comm: khungtaskd Not tainted 2.6.32-rc5-64-00021-g758646f #31
Call Trace:
 [<ffffffff8125ac39>] debug_smp_processor_id+0xd9/0xe0
 [<ffffffff8100e9f9>] show_stack_log_lvl+0x29/0x150
 [<ffffffff8100fdc7>] show_stack+0x17/0x20
 [<ffffffff8104f9c5>] sched_show_task+0x95/0x100
 [<ffffffff810c9cc9>] watchdog+0x269/0x2c0
 [<ffffffff810c9ad3>] ? watchdog+0x73/0x2c0
 [<ffffffff810c9a60>] ? watchdog+0x0/0x2c0
 [<ffffffff810836ce>] kthread+0x8e/0xa0
 [<ffffffff8100cf5a>] child_rip+0xa/0x20
 [<ffffffff810512ea>] ? finish_task_switch+0x7a/0xe0
 [<ffffffff81451916>] ? _spin_unlock_irq+0x36/0x60
 [<ffffffff8100c8c0>] ? restore_args+0x0/0x30
 [<ffffffff81083640>] ? kthread+0x0/0xa0
 [<ffffffff8100cf50>] ? child_rip+0x0/0x20
 ffff8800d7b2fdd8 0000000000000046 0000000000000000 ffffffff810969f9
 ffff8800d7b2ffd8 ffff8800d7b2e000 ffff8800d7b2ffd8 ffff8800d7b2e000
 000000000000f468 0000000000000000 ffff880116f62390 ffffffff816770a0
Call Trace:
 [<ffffffff810969f9>] ? trace_hardirqs_off_caller+0x29/0xc0
 [<ffffffff81455109>] ? sub_preempt_count+0xa9/0xf0
 [<ffffffff81170969>] bdi_sched_wait+0x9/0x10
 [<ffffffff8144f19a>] __wait_on_bit+0x5a/0x90
 [<ffffffff81170960>] ? bdi_sched_wait+0x0/0x10
 [<ffffffff81170960>] ? bdi_sched_wait+0x0/0x10
 [<ffffffff8144f244>] out_of_line_wait_on_bit+0x74/0x90
 [<ffffffff81083b80>] ? wake_bit_function+0x0/0x40
 [<ffffffff8117094e>] ? bdi_queue_work+0xbe/0xd0
 [<ffffffff811709ea>] sync_inodes_sb+0x7a/0x170
 [<ffffffff81175e82>] __sync_filesystem+0x22/0x60
 [<ffffffff81175f8a>] sync_filesystems+0xca/0x130
 [<ffffffff8117604c>] sys_sync+0x1c/0x40
 [<ffffffff8103e0e8>] cstar_dispatch+0x7/0x2c
2 locks held by syslinux/4439:
 #0:  (mutex){+.+...}, at: [<ffffffff81175ede>] sync_filesystems+0x1e/0x130
 #1:  (&type->s_umount_key#30){++++..}, at: [<ffffffff81175f68>] sync_filesystems+0xa8/0x130

petr-dev3:/tmp$ cat /proc/mounts | cut -d' ' -f3 | sort | uniq -c
      1 binfmt_misc
      1 cifs
      1 debugfs
      1 devpts
      7 ext3
      1 fusectl
     51 nfs
      1 nfsd
      1 proc
      1 rootfs
      1 rpc_pipefs
      1 sysfs
      3 tmpfs
Comment 1 Jens Axboe 2009-10-19 01:40:10 UTC
Petr, was IO still going on at this point or was the disk idle? I ask because we have seen a bug here where the fs sync ends up basically doing sync writes to every dirty inode, instead of just waiting on the previously submitted async write. And that tends to go reaaaally slow. So it could be that very bug, hence my question.

If the disk is idle (and network, if this is an nfs mount it's waiting on), then it's likely another bug. I'll code up a debug patch that we can merge to help fix these issues, since it's hard to collect data afterwards.
Comment 2 Petr Vandrovec 2009-10-19 02:39:21 UTC
As far as I can tell disk was idle, and NFS did not complain about any retries either - I believe that 'ps axf | grep D' reported only syslinux, no-one else, operations like 'df' did work (so NFS & friends seemed to be OK), only running 'sync' from command line got hung.  Box was in this state for over 15 minutes until I decided to alt-sysrq-b box...

I'll try reproducing it, but I have no idea how successful I'll be - I've did same build 3 times since hang, and they all succeeded without any hangs.
Comment 3 Petr Vandrovec 2009-10-20 07:45:27 UTC
I've kept running 'while true; do sync; done' for a day, while doing regular work.  Once sync took more than 120 seconds (which I find quite surprising given that sync was supposed to run back-to-back), but sync completed successfully before I've noticed.  So for now it is not reproducible.

[235441.210125] INFO: task sync:13249 blocked for more than 120 seconds.
[235441.210276] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[235441.210425] sync          D ffff88012cdd5e40     0 13249   5520 0x00000000
[235441.210609] BUG: using smp_processor_id() in preemptible [00000000] code: khungtaskd/400
[235441.210761] caller is show_stack_log_lvl+0x29/0x150
[235441.210866] Pid: 400, comm: khungtaskd Not tainted 2.6.32-rc5-64-00021-g758646f #31
[235441.211008] Call Trace:
[235441.211084]  [<ffffffff8125ac39>] debug_smp_processor_id+0xd9/0xe0
[235441.211208]  [<ffffffff8100e9f9>] show_stack_log_lvl+0x29/0x150
[235441.211328]  [<ffffffff8100fdc7>] show_stack+0x17/0x20
[235441.211438]  [<ffffffff8104f9c5>] sched_show_task+0x95/0x100
[235441.211556]  [<ffffffff810c9cc9>] watchdog+0x269/0x2c0
[235441.211666]  [<ffffffff810c9ad3>] ? watchdog+0x73/0x2c0
[235441.211776]  [<ffffffff810c9a60>] ? watchdog+0x0/0x2c0
[235441.211886]  [<ffffffff810836ce>] kthread+0x8e/0xa0
[235441.211992]  [<ffffffff8100cf5a>] child_rip+0xa/0x20
[235441.212096]  [<ffffffff810512ea>] ? finish_task_switch+0x7a/0xe0
[235441.212216]  [<ffffffff81451916>] ? _spin_unlock_irq+0x36/0x60
[235441.212335]  [<ffffffff8100c8c0>] ? restore_args+0x0/0x30
[235441.212450]  [<ffffffff81083640>] ? kthread+0x0/0xa0
[235441.212554]  [<ffffffff8100cf50>] ? child_rip+0x0/0x20
[235441.212662]  ffff88020133ddd8 0000000000000046 0000000000000000 ffffffff810969f9
[235441.212890]  ffff88020133dfd8 ffff88020133c000 ffff88020133dfd8 ffff88020133c000
[235441.213117]  000000000000f468 0000000000000002 ffff88006a36c720 ffff88011ba88000
[235441.213346] Call Trace:
[235441.213418]  [<ffffffff810969f9>] ? trace_hardirqs_off_caller+0x29/0xc0
[235441.213548]  [<ffffffff81455109>] ? sub_preempt_count+0xa9/0xf0
[235441.213699]  [<ffffffff81170969>] bdi_sched_wait+0x9/0x10
[235441.213703]  [<ffffffff8144f19a>] __wait_on_bit+0x5a/0x90
[235441.213706]  [<ffffffff81170960>] ? bdi_sched_wait+0x0/0x10
[235441.213710]  [<ffffffff81170960>] ? bdi_sched_wait+0x0/0x10
[235441.213713]  [<ffffffff8144f244>] out_of_line_wait_on_bit+0x74/0x90
[235441.213717]  [<ffffffff81083b80>] ? wake_bit_function+0x0/0x40
[235441.213721]  [<ffffffff8117092c>] ? bdi_queue_work+0x9c/0xd0
[235441.213724]  [<ffffffff811709ea>] sync_inodes_sb+0x7a/0x170
[235441.213728]  [<ffffffff81175e82>] __sync_filesystem+0x22/0x60
[235441.213732]  [<ffffffff81175f8a>] sync_filesystems+0xca/0x130
[235441.213735]  [<ffffffff8117604c>] sys_sync+0x1c/0x40
[235441.213740]  [<ffffffff8100be6b>] system_call_fastpath+0x16/0x1b
[235441.213744] 2 locks held by sync/13249:
[235441.213746]  #0:  (mutex){+.+...}, at: [<ffffffff81175ede>] sync_filesystems+0x1e/0x130
[235441.213752]  #1:  (&type->s_umount_key#30){++++..}, at: [<ffffffff81175f68>] sync_filesystems+0xa8/0x130
Comment 4 Jens Axboe 2009-10-20 07:50:43 UTC
OK,that is helpfulo (in that something weird reproduces). I'll do the debug patch as soon as I can.
Comment 5 Petr Vandrovec 2009-11-17 00:59:45 UTC
I did not see it for some time, so I guess it went away.