Linux Kernel crash mutex_lock_slowpath "blocked for more than 120 seconds". What to do?
- by Roddick
I have out-of-the box Debian Lenny with non-custom kernel 2.6.26-2-amd64.
Brand new server that is used to 5% of it's potential, CPU and Disk-wise.
Meaning it probably not crashing because of overload.
every few days it freezes with hundreds of these messages in console log:
: [284847.828428] INFO: task apache2:12473 blocked for more than 120 seconds.
: [284847.868468] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
: [284847.912759] apache2 D ffff8101bc6b7ab0 0 12473 14358
: [284847.912763] ffff810160d5bc50 0000000000000082 ffff8101c0002e40 0000000000000000
: [284847.912766] ffff8101a7c42950 ffff810327d92810 ffff8101a7c42bd8 0000000400000044
: [284847.912770] ffff8101c0002e40 00000000000612d0 0000000000000000 00000040000612d0
: [284847.912773] Call Trace:
: [284847.912786] [<ffffffff80429b0d>] __mutex_lock_slowpath+0x64/0x9b
: [284847.912790] [<ffffffff80429972>] mutex_lock+0xa/0xb
: [284847.912794] [<ffffffff802a20b9>] do_lookup+0x82/0x1c1
: [284847.912800] [<ffffffff802a4271>] __link_path_walk+0x87a/0xd19
: [284847.912805] [<ffffffff80295844>] kmem_getpages+0x96/0x15f
: [284847.912808] [<ffffffff80295fb7>] ____cache_alloc_node+0x6d/0x106
: [284847.912814] [<ffffffff802a4756>] path_walk+0x46/0x8b
: [284847.912819] [<ffffffff802a4a82>] do_path_lookup+0x158/0x1cf
: [284847.912822] [<ffffffff802a3879>] getname+0x140/0x1a7
: [284847.912827] [<ffffffff802a53f1>] __user_walk_fd+0x37/0x4c
: [284847.912831] [<ffffffff8029e381>] vfs_lstat_fd+0x18/0x47
: [284847.912840] [<ffffffff8029e3c9>] sys_newlstat+0x19/0x31
: [284847.912848] [<ffffffff8020beda>] system_call_after_swapgs+0x8a/0x8f
Almost all traces has __mutex_lock_slowpath as top-level.
Only some has different trace:
: [284847.737386] INFO: task apache2:12472 blocked for more than 120 seconds.
: [284847.777551] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
: [284847.824881] apache2 D ffff8101bc6b7ab0 0 12472 14358
: [284847.824886] ffff8101b9cc1c50 0000000000000086 ffffffffa0131e0a 0000000000000002
: [284847.824889] ffff8102e7454300 ffff810324c6cad0 ffff8102e7454588 0000000000000000
: [284847.824893] 0000000000000001 0000000000000296 0000000000000003 ffff8101b9cc1c58
: [284847.824896] Call Trace:
: [284847.828403] [<ffffffffa0131e0a>] :ext3:__ext3_journal_dirty_metadata+0x1e/0x46
: [284847.828412] [<ffffffff80429b0d>] __mutex_lock_slowpath+0x64/0x9b
: [284847.828418] [<ffffffff80429972>] mutex_lock+0xa/0xb
: [284847.828421] [<ffffffff802a20b9>] do_lookup+0x82/0x1c1
: [284847.828427] [<ffffffff802a4271>] __link_path_walk+0x87a/0xd19
: [284847.828428] [<ffffffff80271296>] find_lock_page+0x1f/0x8a
: [284847.828428] [<ffffffff80273182>] filemap_fault+0x1c2/0x33c
: [284847.828428] [<ffffffff802a4756>] path_walk+0x46/0x8b
: [284847.828428] [<ffffffff802a4a82>] do_path_lookup+0x158/0x1cf
: [284847.828428] [<ffffffff802a3879>] getname+0x140/0x1a7
: [284847.828428] [<ffffffff802a53f1>] __user_walk_fd+0x37/0x4c
: [284847.828428] [<ffffffff8029e381>] vfs_lstat_fd+0x18/0x47
: [284847.828428] [<ffffffff8029e3c9>] sys_newlstat+0x19/0x31
: [284847.828428] [<ffffffff8020beda>] system_call_after_swapgs+0x8a/0x8f
kernel: [1912668.466347] INFO: task apache2:17984 blocked for more than 120 seconds.
[1912668.507035] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
: [1912668.555165] apache2 D ffff8101c5637ba0 0 17984 17282
: [1912668.596752] ffff810166a7dd30 0000000000000086 0000000000000000 ffff810166a7dcd8
: [1912668.643341] ffff8101c563c880 ffff81024505f000 0000000000000002 ffff810166a7dd68
: [1912668.699566] 0000000000000086 00000000000cb1a0 0000000000000000 ffff81017f344d60
: [1912668.744773] Call Trace:
: [1912668.761754] [<ffffffff8022a3ed>] pick_next_task_fair+0x6e/0x7a
: [1912668.829311] [<ffffffff802be0e2>] bio_alloc_bioset+0x89/0xd9
: [1912668.861930] [<ffffffff8024ac3a>] getnstimeofday+0x39/0x98
: [1912668.897005] [<ffffffff802710f6>] sync_page+0x0/0x41
: [1912668.927868] [<ffffffff80429487>] io_schedule+0x5c/0x9e
: [1912668.960286] [<ffffffff80271132>] sync_page+0x3c/0x41
: [1912668.991756] [<ffffffff804295fa>] __wait_on_bit_lock+0x36/0x66
: [1912669.031757] [<ffffffff802710e3>] __lock_page+0x5e/0x64
: [1912669.064191] [<ffffffff802461d3>] wake_bit_function+0x0/0x23
: [1912669.100100] [<ffffffff80281bc5>] handle_mm_fault+0x5e4/0x8de
: [1912669.134531] [<ffffffff802461a5>] autoremove_wake_function+0x0/0x2e
: [1912669.174623] [<ffffffff802aa108>] fcntl_setlk+0x1cf/0x291
: [1912669.210623] [<ffffffff802461a5>] autoremove_wake_function+0x0/0x2e
: [1912669.246923] [<ffffffff802a677f>] sys_fcntl+0x280/0x2f7
After googling for "mutex_lock_slowpath" I can only find the Kernel mailing list discussions that this issue was introduced in some commit. Wthout reference to verison.
Discussions as recent as Jan 25, 2011.
The Kernel I am using is form Debian Lenny, year ago.
What should I do? Is this bug even fixed in kernel? if it's such obvious bug why it happens so rarely?
Should I download latest kernel from kernel.org and upgrade?
Should I use Debian backports to install new "Approved" kernel?
Am I missing something? What to do?