zfsonlinux/zfs — Issue #446: Deadlock with hung tasks during direct memory reclaim
Author: etienne-dechamps-o
Created: 2011-11-10 19:39:36+00:00
State: open

I'm running latest SPL/ZFS from git.

ZFS just deadlocked my server. This happened while it was doing quite a lot of things at the same time (most notably, rtorrent and a ZVOL-backed VirtualBox).

I have no idea what triggered it exactly. I noticed that my processes were getting deadlocked one after the other (hung and SIGKILL-proof). The box, however, stayed up and running (no panic), although most ZFS operations wouldn't complete. Basically I was still able to read the pool but it was impossible to write anything. I observed the phenomenon for a few minutes, then I rebooted the box. Needless to say, this will probably be difficult to reproduce.

What's much more interesting however is the kernel log:

[373562.701571] INFO: task kswapd0:45 blocked for more than 120 seconds.
[373562.703914] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[373562.706260] kswapd0 D ffff880419e31850 0 45 2 0x00000000
[373562.708618] ffff880419e31850 0000000000000046 0000000000000020 ffffffffa0109b25
[373562.710952] ffff88041f2628b0 0000000000012800 ffff880419e33fd8 ffff880419e33fd8
[373562.713286] 0000000000012800 ffff880419e31850 0000000000012800 0000000000012800
[373562.715572] Call Trace:
[373562.717970] [] ? kmalloc_nofail+0x18/0x26 [spl]
[373562.720182] [] ? _raw_spin_lock_irqsave+0x9/0x25
[373562.722395] [] ? cv_wait_common+0x75/0xbc [spl]
[373562.724939] [] ? wake_up_bit+0x23/0x23
[373562.727084] [] ? _cond_resched+0x9/0x20
[373562.729235] [] ? txg_wait_open+0x57/0x8d [zfs]
[373562.731415] [] ? should_resched+0x5/0x24
[373562.733506] [] ? dmu_tx_assign+0xf1/0x329 [zfs]
[373562.735695] [] ? dsl_dataset_block_freeable+0x34/0x40 [zfs]
[373562.737766] [] ? zfs_inactive+0xa2/0x145 [zfs]
[373562.739766] [] ? should_resched+0x5/0x24
[373562.741710] [] ? evict+0x7b/0x119
[373562.743641] [] ? dispose_list+0x32/0x3c
[373562.745499] [] ? shrink_icache_memory+0x2a4/0x2d4
[373562.747484] [] ? shrink_slab+0xe3/0x155
[373562.749661] [] ? balance_pgdat+0x2d1/0x57a
[373562.751656] [] ? kswapd+0x2b4/0x2cd
[373562.753428] [] ? wake_up_bit+0x23/0x23
[373562.755174] [] ? balance_pgdat+0x57a/0x57a
[373562.756912] [] ? balance_pgdat+0x57a/0x57a
[373562.758544] [] ? kthread+0x7a/0x82
[373562.760175] [] ? kernel_thread_helper+0x4/0x10
[373562.761876] [] ? kthread_worker_fn+0x149/0x149
[373562.763475] [] ? gs_change+0x13/0x13

[373562.764983] INFO: task zvol/2:344 blocked for more than 120 seconds.
[373562.766497] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[373562.767990] zvol/2 D ffff880419858080 0 344 2 0x00000000
[373562.769476] ffff880419858080 0000000000000046 ffffffff8103fd52 ffff880418fb61c0
[373562.770958] ffff88041f243610 0000000000012800 ffff880412183fd8 ffff880412183fd8
[373562.772392] 0000000000012800 ffff880419858080 0000000000012800 0000000000012800
[373562.773831] Call Trace:
[373562.775535] [] ? mutex_spin_on_owner+0x23/0x40
[373562.776877] [] ? _raw_spin_lock_irqsave+0x9/0x25
[373562.778336] [] ? cv_wait_common+0x75/0xbc [spl]
[373562.779682] [] ? wake_up_bit+0x23/0x23
[373562.780972] [] ? txg_wait_open+0x57/0x8d [zfs]
[373562.782231] [] ? should_resched+0x5/0x24
[373562.783525] [] ? dmu_tx_assign+0xf1/0x329 [zfs]
[373562.784744] [] ? dsl_dataset_block_freeable+0x34/0x40 [zfs]
[373562.785964] [] ? zfs_inactive+0xa2/0x145 [zfs]
[373562.787151] [] ? should_resched+0x5/0x24
[373562.788287] [] ? evict+0x7b/0x119
[373562.789394] [] ? dispose_list+0x32/0x3c
[373562.790516] [] ? shrink_icache_memory+0x2a4/0x2d4
[373562.791657] [] ? shrink_slab+0xe3/0x155
[373562.792733] [] ? do_try_to_free_pages+0x1b7/0x315
[373562.793878] [] ? try_to_free_pages+0xb6/0xf6
[373562.794977] [] ? __alloc_pages_nodemask+0x50b/0x7c1
[373562.796028] [] ? alloc_pages_current+0xa5/0xbf
[373562.797072] [] ? __get_free_pages+0x9/0x49
[373562.798149] [] ? spl_kmem_cache_alloc+0x13a/0x4d3 [spl]
[373562.799275] [] ? zil_alloc_lwb+0x24/0x106 [zfs]
[373562.800487] [] ? zil_lwb_write_start+0x20d/0x2b2 [zfs]
[373562.801757] [] ? zil_commit+0x247/0x4f3 [zfs]
[373562.802873] [] ? zvol_write+0x349/0x369 [zfs]
[373562.803942] [] ? taskq_thread+0x1d2/0x32c [spl]
[373562.804985] [] ? try_to_wake_up+0x199/0x199
[373562.806052] [] ? __taskq_create+0x373/0x373 [spl]
[373562.807144] [] ? __taskq_create+0x373/0x373 [spl]
[373562.808181] [] ? kthread+0x7a/0x82
[373562.809328] [] ? kernel_thread_helper+0x4/0x10
[373562.810382] [] ? kthread_worker_fn+0x149/0x149
[373562.811460] [] ? gs_change+0x13/0x13

[373562.812513] INFO: task txg_quiesce:895 blocked for more than 120 seconds.
[373562.813598] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[373562.814710] txg_quiesce D ffff880412259060 0 895 2 0x00000000
[373562.815804] ffff880412259060 0000000000000046 0000000000000082 ffff880400000000
[373562.816942] ffff88041f2d7750 0000000000012800 ffff880408033fd8 ffff880408033fd8
[373562.818094] 0000000000012800 ffff880412259060 0000000000012800 0000000000012800
[373562.819304] Call Trace:
[373562.820444] [] ? cv_wait_common+0x75/0xbc [spl]
[373562.821627] [] ? wake_up_bit+0x23/0x23
[373562.822812] [] ? _cond_resched+0x9/0x20
[373562.823977] [] ? txg_quiesce_thread+0x18b/0x1e9 [zfs]
[373562.825224] [] ? __thread_create+0x129/0x129 [spl]
[373562.826728] [] ? txg_sync_thread+0x331/0x331 [zfs]
[373562.828325] [] ? __thread_create+0x129/0x129 [spl]
[373562.830050] [] ? thread_generic_wrapper+0x6a/0x75 [spl]
[373562.831372] [] ? kthread+0x7a/0x82
[373562.832448] [] ? kernel_thread_helper+0x4/0x10
[373562.833549] [] ? kthread_worker_fn+0x149/0x149
[373562.834627] [] ? gs_change+0x13/0x13

[373562.835706] INFO: task rtorrent:3380 blocked for more than 120 seconds.
[373562.836788] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[373562.837911] rtorrent D ffff880418cbb5d0 0 3380 3371 0x00000000
[373562.839037] ffff880418cbb5d0 0000000000000086 0000000000000020 ffffffffa0109b25
[373562.840243] ffff880410c00a70 0000000000012800 ffff8803e1229fd8 ffff8803e1229fd8
[373562.841380] 0000000000012800 ffff880418cbb5d0 0000000000012800 0000000000012800
[373562.842543] Call Trace:
[373562.843716] [] ? kmalloc_nofail+0x18/0x26 [spl]
[373562.844871] [] ? _raw_spin_lock_irqsave+0x9/0x25
[373562.846076] [] ? cv_wait_common+0x75/0xbc [spl]
[373562.847233] [] ? wake_up_bit+0x23/0x23
[373562.848386] [] ? _cond_resched+0x9/0x20
[373562.849670] [] ? txg_wait_open+0x57/0x8d [zfs]
[373562.850823] [] ? should_resched+0x5/0x24
[373562.852037] [] ? dmu_tx_assign+0xf1/0x329 [zfs]
[373562.853233] [] ? dsl_dataset_block_freeable+0x34/0x40 [zfs]
[373562.854429] [] ? zfs_inactive+0xa2/0x145 [zfs]
[373562.855587] [] ? should_resched+0x5/0x24
[373562.856829] [] ? evict+0x7b/0x119
[373562.857987] [] ? should_resched+0x5/0x24
[373562.859137] [] ? dispose_list+0x32/0x3c
[373562.860283] [] ? shrink_icache_memory+0x2a4/0x2d4
[373562.861435] [] ? shrink_slab+0xe3/0x155
[373562.862606] [] ? do_try_to_free_pages+0x1b7/0x315
[373562.863789] [] ? try_to_free_pages+0xb6/0xf6
[373562.864954] [] ? __alloc_pages_nodemask+0x50b/0x7c1
[373562.866135] [] ? alloc_pages_current+0xa5/0xbf
[373562.867302] [] ? pte_alloc_one+0x11/0x39
[373562.868464] [] ? prio_tree_insert+0x27/0x239
[373562.869625] [] ? __pte_alloc+0x19/0x11c
[373562.870758] [] ? handle_mm_fault+0x1cf/0x22c
[373562.871984] [] ? do_page_fault+0x2e9/0x30e
[373562.873124] [] ? mmap_region+0x336/0x431
[373562.874238] [] ? get_unmapped_area+0xe4/0x13e
[373562.875322] [] ? fput+0x1a/0x1a2
[373562.876387] [] ? page_fault+0x25/0x30

[373562.877469] INFO: task nxagent:12517 blocked for more than 120 seconds.
[373562.878539] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[373562.879630] nxagent D ffff8803f53468b0 0 12517 1 0x00000004
[373562.880741] ffff8803f53468b0 0000000000000086 0000000000000020 ffffffffa0109b25
[373562.881885] ffff880410c22040 0000000000012800 ffff88020b501fd8 ffff88020b501fd8
[373562.883035] 0000000000012800 ffff8803f53468b0 0000000000012800 0000000000012800
[373562.884224] Call Trace:
[373562.885357] [] ? kmalloc_nofail+0x18/0x26 [spl]
[373562.886526] [] ? _raw_spin_lock_irqsave+0x9/0x25
[373562.887872] [] ? cv_wait_common+0x75/0xbc [spl]
[373562.889048] [] ? wake_up_bit+0x23/0x23
[373562.890659] [] ? _cond_resched+0x9/0x20
[373562.891823] [] ? txg_wait_open+0x57/0x8d [zfs]
[373562.892944] [] ? should_resched+0x5/0x24
[373562.894094] [] ? dmu_tx_assign+0xf1/0x329 [zfs]
[373562.895213] [] ? dsl_dataset_block_freeable+0x34/0x40 [zfs]
[373562.896336] [] ? zfs_inactive+0xa2/0x145 [zfs]
[373562.897452] [] ? should_resched+0x5/0x24
[373562.898557] [] ? evict+0x7b/0x119
[373562.899618] [] ? should_resched+0x5/0x24
[373562.900686] [] ? dispose_list+0x32/0x3c
[373562.901751] [] ? shrink_icache_memory+0x2a4/0x2d4
[373562.902893] [] ? shrink_slab+0xe3/0x155
[373562.903965] [] ? do_try_to_free_pages+0x1b7/0x315
[373562.905030] [] ? try_to_free_pages+0xb6/0xf6
[373562.906329] [] ? __alloc_pages_nodemask+0x50b/0x7c1
[373562.907527] [] ? alloc_pages_current+0xa5/0xbf
[373562.908681] [] ? tcp_sendmsg+0x37f/0x733
[373562.909765] [] ? __pollwait+0xd6/0xd6
[373562.910812] [] ? sock_aio_write+0xde/0xed
[373562.912208] [] ? set_fd_set+0x31/0x38
[373562.913283] [] ? do_sync_write+0xb1/0xea
[373562.914358] [] ? should_resched+0x5/0x24
[373562.915405] [] ? need_resched+0x1a/0x23
[373562.916444] [] ? finish_task_switch+0x4c/0xaf
[373562.917502] [] ? need_resched+0x1a/0x23
[373562.918614] [] ? __schedule+0x598/0x5af
[373562.919656] [] ? security_file_permission+0x18/0x33
[373562.920702] [] ? vfs_write+0xb9/0xf9
[373562.921767] [] ? sys_write+0x45/0x6b
[373562.922806] [] ? system_call_fastpath+0x16/0x1b

What's interesting is that the `rtorrent` process was doing a direct memory reclaim (see stack trace), while most other tasks were spinning in `kmalloc_nofail`. Seems to me that the fix for the infamous #287 bug may be unveiling a new kind of issue.