Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

zvol/kworker/jbd2 possible deadlock (hung tasks) #2221

Closed
cbiffle opened this issue Mar 29, 2014 · 4 comments
Closed

zvol/kworker/jbd2 possible deadlock (hung tasks) #2221

cbiffle opened this issue Mar 29, 2014 · 4 comments

Comments

@cbiffle
Copy link

cbiffle commented Mar 29, 2014

I'm running a newish install of Arch Linux (~2 weeks, specific versions below). I've configured a single raidz of five SATA disks; it is not my root filesystem, though I do store /var/log there. To handle a portion of my data that I want encrypted at rest, I have a zvol with a LUKS container, and an ext4 filesystem within that.

Read/write performance to the filesystem on the zvol is unimpressive but acceptable. But I do notice occasional "hitches" where all I/O seems to pause. Today in the kernel output I noticed a report of several hung kernel threads. The system does appear to have recovered -- I'm messing around in the ext4 filesystem right now.

I've found a thread on the mailing list that describes issues in a very similar situation, but that was four years ago. I've also seen issue 21 and issue 1985; 21 seems closer than 1985 to my circumstances, but it was closed and believed to be fixed some time ago.

I'm curious if there's a generally accepted workaround for these issues -- the mailing list thread linked above suggested limiting the ARC, which does seem to get rather large on my 16GiB machine.

Anyway. Data dump begins here.

System Configuration

Linux metis 3.13.6-1-ARCH #1 SMP PREEMPT Fri Mar 7 22:47:48 CET 2014 x86_64 GNU/Linux
zfs-0.6.2 and spl-0.6.2, both built from the AUR recipe.
ASRock C2750D4I motherboard (Intel Avoton)

Disks are spread across two Marvell SATA controllers -- two on an 88SE9172, the other three on an 88SE9230. There is a separate kernel bug affecting the 88SE9172 but I don't think it's related (it causes disks to vanish, which isn't happening here).

dmesg output

[56926.824121] INFO: task jbd2/dm-0-8:611 blocked for more than 120 seconds.
[56926.831003]       Tainted: P           O 3.13.6-1-ARCH #1
[56926.836470] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[56926.844420] jbd2/dm-0-8     D ffff880460671c50     0   611      2 0x00000000
[56926.844429]  ffff880460671bc0 0000000000000046 ffff880468edb600 ffff880460671fd8
[56926.844434]  0000000000014440 0000000000014440 ffff880468edb600 0000000000000000
[56926.844438]  0000100000000001 ffff88046975a000 ffff88046975a000 000000003fc4f5e0
[56926.844443] Call Trace:
[56926.844456]  [<ffffffffa1580edb>] ? __split_and_process_bio+0x39b/0x4f0 [dm_mod]
[56926.844462]  [<ffffffff8101c1b9>] ? read_tsc+0x9/0x20
[56926.844468]  [<ffffffff810c48d8>] ? ktime_get_ts+0x48/0xe0
[56926.844471]  [<ffffffff8101c1b9>] ? read_tsc+0x9/0x20
[56926.844476]  [<ffffffff811d3c50>] ? generic_block_bmap+0x50/0x50
[56926.844480]  [<ffffffff81515d99>] schedule+0x29/0x70
[56926.844484]  [<ffffffff8151603f>] io_schedule+0x8f/0xe0
[56926.844487]  [<ffffffff811d3c5e>] sleep_on_buffer+0xe/0x20
[56926.844491]  [<ffffffff815163a2>] __wait_on_bit+0x62/0x90
[56926.844495]  [<ffffffff811d3c50>] ? generic_block_bmap+0x50/0x50
[56926.844498]  [<ffffffff81516447>] out_of_line_wait_on_bit+0x77/0x90
[56926.844503]  [<ffffffff810a2c70>] ? autoremove_wake_function+0x40/0x40
[56926.844507]  [<ffffffff811d3d5a>] __wait_on_buffer+0x2a/0x30
[56926.844522]  [<ffffffffa01c449b>] jbd2_journal_commit_transaction+0x115b/0x1c50 [jbd2]
[56926.844529]  [<ffffffffa01c9e1e>] kjournald2+0xbe/0x240 [jbd2]
[56926.844533]  [<ffffffff810a2c30>] ? __wake_up_sync+0x20/0x20
[56926.844540]  [<ffffffffa01c9d60>] ? commit_timeout+0x10/0x10 [jbd2]
[56926.844545]  [<ffffffff810835b2>] kthread+0xd2/0xf0
[56926.844549]  [<ffffffff810834e0>] ? kthread_create_on_node+0x180/0x180
[56926.844553]  [<ffffffff815215fc>] ret_from_fork+0x7c/0xb0
[56926.844557]  [<ffffffff810834e0>] ? kthread_create_on_node+0x180/0x180
[56926.844569] INFO: task kworker/u16:1:11606 blocked for more than 120 seconds.
[56926.851807]       Tainted: P           O 3.13.6-1-ARCH #1
[56926.857254] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[56926.865169] kworker/u16:1   D ffff880379d73770     0 11606      2 0x00000000
[56926.865178] Workqueue: writeback bdi_writeback_workfn (flush-254:0)
[56926.865181]  ffff880379d736e0 0000000000000046 ffff88037684c800 ffff880379d73fd8
[56926.865185]  0000000000014440 0000000000014440 ffff88037684c800 0000000000000046
[56926.865189]  ffff880379d73668 ffffffff810925fa 0000000000026eb6 ffff880379d73658
[56926.865193] Call Trace:
[56926.865199]  [<ffffffff810925fa>] ? try_to_wake_up+0x1fa/0x2c0
[56926.865204]  [<ffffffff810a8680>] ? cpuacct_charge+0x50/0x60
[56926.865207]  [<ffffffff8109a984>] ? update_curr+0xe4/0x190
[56926.865212]  [<ffffffff81096be8>] ? __enqueue_entity+0x78/0x80
[56926.865219]  [<ffffffffa01c0890>] ? jbd2_journal_restart+0x20/0x20 [jbd2]
[56926.865223]  [<ffffffff81515d99>] schedule+0x29/0x70
[56926.865226]  [<ffffffff8151603f>] io_schedule+0x8f/0xe0
[56926.865232]  [<ffffffffa01c089e>] sleep_on_shadow_bh+0xe/0x20 [jbd2]
[56926.865236]  [<ffffffff815163a2>] __wait_on_bit+0x62/0x90
[56926.865242]  [<ffffffff81090329>] ? ttwu_do_wakeup+0x19/0xf0
[56926.865248]  [<ffffffffa01c0890>] ? jbd2_journal_restart+0x20/0x20 [jbd2]
[56926.865252]  [<ffffffff81516447>] out_of_line_wait_on_bit+0x77/0x90
[56926.865256]  [<ffffffff810a2c70>] ? autoremove_wake_function+0x40/0x40
[56926.865260]  [<ffffffff810a2845>] ? wake_up_bit+0x25/0x30
[56926.865266]  [<ffffffffa01c1b5c>] do_get_write_access+0x1dc/0x5d0 [jbd2]
[56926.865270]  [<ffffffff81519a85>] ? _raw_spin_unlock+0x25/0x30
[56926.865277]  [<ffffffffa01c1f77>] jbd2_journal_get_write_access+0x27/0x40 [jbd2]
[56926.865290]  [<ffffffffa021f996>] __ext4_journal_get_write_access+0x36/0x80 [ext4]
[56926.865300]  [<ffffffffa022639e>] ext4_mb_mark_diskspace_used+0x6e/0x4c0 [ext4]
[56926.865311]  [<ffffffffa0227bfd>] ext4_mb_new_blocks+0x2fd/0x5e0 [ext4]
[56926.865321]  [<ffffffffa021996c>] ? ext4_ext_find_extent+0x12c/0x2d0 [ext4]
[56926.865331]  [<ffffffffa021d770>] ext4_ext_map_blocks+0x590/0x1510 [ext4]
[56926.865340]  [<ffffffffa01f0800>] ? ext4_direct_IO+0x110/0x4c0 [ext4]
[56926.865348]  [<ffffffffa01f2f35>] ext4_map_blocks+0x2c5/0x500 [ext4]
[56926.865357]  [<ffffffffa01f5fab>] ext4_writepages+0x65b/0xd50 [ext4]
[56926.865362]  [<ffffffff811420de>] do_writepages+0x1e/0x40
[56926.865366]  [<ffffffff811cce20>] __writeback_single_inode+0x40/0x2a0
[56926.865370]  [<ffffffff811cdd8a>] writeback_sb_inodes+0x26a/0x450
[56926.865374]  [<ffffffff811ce00f>] __writeback_inodes_wb+0x9f/0xd0
[56926.865378]  [<ffffffff811ce26b>] wb_writeback+0x22b/0x330
[56926.865382]  [<ffffffff811cebd4>] bdi_writeback_workfn+0x334/0x480
[56926.865386]  [<ffffffff8107c4f7>] process_one_work+0x167/0x420
[56926.865390]  [<ffffffff8107cec1>] worker_thread+0x121/0x3a0
[56926.865394]  [<ffffffff8107cda0>] ? manage_workers.isra.23+0x2a0/0x2a0
[56926.865398]  [<ffffffff810835b2>] kthread+0xd2/0xf0
[56926.865402]  [<ffffffff810834e0>] ? kthread_create_on_node+0x180/0x180
[56926.865406]  [<ffffffff815215fc>] ret_from_fork+0x7c/0xb0
[56926.865410]  [<ffffffff810834e0>] ? kthread_create_on_node+0x180/0x180
[56975.807354] systemd[1]: Starting Journal Service...
[57046.961790] INFO: task arc_adapt:275 blocked for more than 120 seconds.
[57046.968482]       Tainted: P           O 3.13.6-1-ARCH #1
[57046.973941] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[57046.981845] arc_adapt       D 0000000000000246     0   275      2 0x00000000
[57046.981851]  ffff880461fe7d78 0000000000000046 ffff8804682ee300 ffff880461fe7fd8
[57046.981856]  0000000000014440 0000000000014440 ffff8804682ee300 ffff880467630068
[57046.981860]  ffff88046184b600 ffff880461fe7cc8 ffffffff00000010 ffff880461fe7d10
[57046.981865] Call Trace:
[57046.981874]  [<ffffffff8109b89c>] ? check_preempt_wakeup+0x17c/0x270
[57046.981879]  [<ffffffff8108d4fb>] ? ttwu_stat+0x9b/0x110
[57046.981883]  [<ffffffff810925fa>] ? try_to_wake_up+0x1fa/0x2c0
[57046.981888]  [<ffffffff81515d99>] schedule+0x29/0x70
[57046.981892]  [<ffffffff81516196>] schedule_preempt_disabled+0x16/0x20
[57046.981896]  [<ffffffff8151861d>] __mutex_lock_slowpath+0x13d/0x390
[57046.981899]  [<ffffffff81518882>] mutex_lock+0x12/0x22
[57046.981920]  [<ffffffffa06e1406>] dbuf_destroy+0x56/0x1d0 [zfs]
[57046.981933]  [<ffffffffa06e3870>] dbuf_do_evict+0x60/0xa0 [zfs]
[57046.981944]  [<ffffffffa06d787f>] arc_do_user_evicts+0x9f/0x140 [zfs]
[57046.981955]  [<ffffffffa06dcce0>] ? arc_adjust_meta+0x230/0x230 [zfs]
[57046.981967]  [<ffffffffa06dcd73>] arc_adapt_thread+0x93/0x190 [zfs]
[57046.981978]  [<ffffffffa028a9ca>] thread_generic_wrapper+0x7a/0x90 [spl]
[57046.981985]  [<ffffffffa028a950>] ? __thread_exit+0xa0/0xa0 [spl]
[57046.981990]  [<ffffffff810835b2>] kthread+0xd2/0xf0
[57046.981994]  [<ffffffff810834e0>] ? kthread_create_on_node+0x180/0x180
[57046.981998]  [<ffffffff815215fc>] ret_from_fork+0x7c/0xb0
[57046.982002]  [<ffffffff810834e0>] ? kthread_create_on_node+0x180/0x180
[57046.982006] INFO: task zvol/1:279 blocked for more than 120 seconds.
[57046.988426]       Tainted: P           O 3.13.6-1-ARCH #1
[57046.993873] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[57047.001776] zvol/1          D 0000000000000246     0   279      2 0x00000000
[57047.001781]  ffff880461807a38 0000000000000046 ffff8804682ebf00 ffff880461807fd8
[57047.001785]  0000000000014440 0000000000014440 ffff8804682ebf00 ffff88046825ec68
[57047.001789]  ffff8804682ebf00 ffff8804685b10b0 0000000000000006 ffff8804685b10b0
[57047.001794] Call Trace:
[57047.001799]  [<ffffffff81515d99>] schedule+0x29/0x70
[57047.001803]  [<ffffffff81516196>] schedule_preempt_disabled+0x16/0x20
[57047.001807]  [<ffffffff8151861d>] __mutex_lock_slowpath+0x13d/0x390
[57047.001810]  [<ffffffff81518882>] mutex_lock+0x12/0x22
[57047.001823]  [<ffffffffa06e2bc7>] dbuf_create+0xf7/0x430 [zfs]
[57047.001836]  [<ffffffffa06e3aca>] ? __dbuf_hold_impl+0x21a/0x4c0 [zfs]
[57047.001848]  [<ffffffffa06e3a74>] __dbuf_hold_impl+0x1c4/0x4c0 [zfs]
[57047.001860]  [<ffffffffa06e3a2c>] __dbuf_hold_impl+0x17c/0x4c0 [zfs]
[57047.001873]  [<ffffffffa06e3deb>] dbuf_hold_impl+0x7b/0xa0 [zfs]
[57047.001887]  [<ffffffffa06f6b9f>] dmu_tx_count_write+0x3af/0x6d0 [zfs]
[57047.001902]  [<ffffffffa06f7a66>] dmu_tx_hold_write+0x36/0x50 [zfs]
[57047.001917]  [<ffffffffa0787dda>] zvol_write+0x9a/0x480 [zfs]
[57047.001924]  [<ffffffffa028c977>] taskq_thread+0x237/0x4b0 [spl]
[57047.001929]  [<ffffffff81092700>] ? wake_up_process+0x40/0x40
[57047.001935]  [<ffffffffa028c740>] ? taskq_cancel_id+0x1f0/0x1f0 [spl]
[57047.001939]  [<ffffffff810835b2>] kthread+0xd2/0xf0
[57047.001944]  [<ffffffff810834e0>] ? kthread_create_on_node+0x180/0x180
[57047.001947]  [<ffffffff815215fc>] ret_from_fork+0x7c/0xb0
[57047.001951]  [<ffffffff810834e0>] ? kthread_create_on_node+0x180/0x180
[57047.001955] INFO: task zvol/2:280 blocked for more than 120 seconds.
[57047.008374]       Tainted: P           O 3.13.6-1-ARCH #1
[57047.013824] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[57047.021722] zvol/2          D 0000000000000246     0   280      2 0x00000000
[57047.021727]  ffff880461809a68 0000000000000046 ffff8804682eb600 ffff880461809fd8
[57047.021731]  0000000000014440 0000000000014440 ffff8804682eb600 ffff8800061e39a8
[57047.021736]  0000000000000246 ffffffff8106e72c 0000000000000010 0000000000000282
[57047.021740] Call Trace:
[57047.021745]  [<ffffffff8106e72c>] ? init_timer_key+0x2c/0xd0
[57047.021749]  [<ffffffff8108d4fb>] ? ttwu_stat+0x9b/0x110
[57047.021753]  [<ffffffff81515d99>] schedule+0x29/0x70
[57047.021756]  [<ffffffff81516196>] schedule_preempt_disabled+0x16/0x20
[57047.021760]  [<ffffffff8151861d>] __mutex_lock_slowpath+0x13d/0x390
[57047.021764]  [<ffffffff81518882>] mutex_lock+0x12/0x22
[57047.021782]  [<ffffffffa06e2bc7>] dbuf_create+0xf7/0x430 [zfs]
[57047.021795]  [<ffffffffa06e3aca>] ? __dbuf_hold_impl+0x21a/0x4c0 [zfs]
[57047.021807]  [<ffffffffa06e3a74>] __dbuf_hold_impl+0x1c4/0x4c0 [zfs]
[57047.021820]  [<ffffffffa06e3deb>] dbuf_hold_impl+0x7b/0xa0 [zfs]
[57047.021832]  [<ffffffffa06e40b0>] dbuf_hold+0x20/0x40 [zfs]
[57047.021845]  [<ffffffffa06eb5bd>] dmu_buf_hold_array_by_dnode+0x15d/0x610 [zfs]
[57047.021859]  [<ffffffffa06ebb4d>] dmu_buf_hold_array+0x5d/0x80 [zfs]
[57047.021872]  [<ffffffffa06ece62>] dmu_write_req+0x72/0x210 [zfs]
[57047.021887]  [<ffffffffa0787e07>] zvol_write+0xc7/0x480 [zfs]
[57047.021894]  [<ffffffffa028c977>] taskq_thread+0x237/0x4b0 [spl]
[57047.021898]  [<ffffffff81092700>] ? wake_up_process+0x40/0x40
[57047.021905]  [<ffffffffa028c740>] ? taskq_cancel_id+0x1f0/0x1f0 [spl]
[57047.021909]  [<ffffffff810835b2>] kthread+0xd2/0xf0
[57047.021913]  [<ffffffff810834e0>] ? kthread_create_on_node+0x180/0x180
[57047.021917]  [<ffffffff815215fc>] ret_from_fork+0x7c/0xb0
[57047.021921]  [<ffffffff810834e0>] ? kthread_create_on_node+0x180/0x180
[57047.021924] INFO: task zvol/3:281 blocked for more than 120 seconds.
[57047.028341]       Tainted: P           O 3.13.6-1-ARCH #1
[57047.033795] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[57047.041700] zvol/3          D 0000000000000246     0   281      2 0x00000000
[57047.041705]  ffff88046180bb18 0000000000000046 ffff8804682ead00 ffff88046180bfd8
[57047.041710]  0000000000014440 0000000000014440 ffff8804682ead00 537c1232983f9fc9
[57047.041714]  0000000000000000 0000000000000202 ffff880329267060 00000000000000a1
[57047.041718] Call Trace:
[57047.041723]  [<ffffffff810925fa>] ? try_to_wake_up+0x1fa/0x2c0
[57047.041729]  [<ffffffff810926e3>] ? wake_up_process+0x23/0x40
[57047.041732]  [<ffffffff81515d99>] schedule+0x29/0x70
[57047.041736]  [<ffffffff81516196>] schedule_preempt_disabled+0x16/0x20
[57047.041740]  [<ffffffff8151861d>] __mutex_lock_slowpath+0x13d/0x390
[57047.041743]  [<ffffffff81518882>] mutex_lock+0x12/0x22
[57047.041756]  [<ffffffffa06e1406>] dbuf_destroy+0x56/0x1d0 [zfs]
[57047.041769]  [<ffffffffa06e380a>] dbuf_evict+0x1a/0x20 [zfs]
[57047.041781]  [<ffffffffa06e3337>] dbuf_rele_and_unlock+0xb7/0x260 [zfs]
[57047.041800]  [<ffffffffa06e363d>] dmu_buf_rele+0x3d/0x50 [zfs]
[57047.041814]  [<ffffffffa06f6b3f>] dmu_tx_count_write+0x34f/0x6d0 [zfs]
[57047.041829]  [<ffffffffa06f7a66>] dmu_tx_hold_write+0x36/0x50 [zfs]
[57047.041844]  [<ffffffffa0787dda>] zvol_write+0x9a/0x480 [zfs]
[57047.041852]  [<ffffffffa028c977>] taskq_thread+0x237/0x4b0 [spl]
[57047.041856]  [<ffffffff81092700>] ? wake_up_process+0x40/0x40
[57047.041863]  [<ffffffffa028c740>] ? taskq_cancel_id+0x1f0/0x1f0 [spl]
[57047.041867]  [<ffffffff810835b2>] kthread+0xd2/0xf0
[57047.041871]  [<ffffffff810834e0>] ? kthread_create_on_node+0x180/0x180
[57047.041875]  [<ffffffff815215fc>] ret_from_fork+0x7c/0xb0
[57047.041879]  [<ffffffff810834e0>] ? kthread_create_on_node+0x180/0x180
[57047.041882] INFO: task zvol/4:282 blocked for more than 120 seconds.
[57047.048298]       Tainted: P           O 3.13.6-1-ARCH #1
[57047.053747] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[57047.061649] zvol/4          D 0000000000000246     0   282      2 0x00000000
[57047.061654]  ffff88046180da68 0000000000000046 ffff8804682ea400 ffff88046180dfd8
[57047.061658]  0000000000014440 0000000000014440 ffff8804682ea400 ffff88046180dfd8
[57047.061662]  0000000000014440 0000000000014440 ffff8804682ea400 ffff880467630068
[57047.061666] Call Trace:
[57047.061672]  [<ffffffff8108d4fb>] ? ttwu_stat+0x9b/0x110
[57047.061676]  [<ffffffff81515d99>] schedule+0x29/0x70
[57047.061679]  [<ffffffff81516196>] schedule_preempt_disabled+0x16/0x20
[57047.061683]  [<ffffffff8151861d>] __mutex_lock_slowpath+0x13d/0x390
[57047.061687]  [<ffffffff81518882>] mutex_lock+0x12/0x22
[57047.061700]  [<ffffffffa06e2bc7>] dbuf_create+0xf7/0x430 [zfs]
[57047.061712]  [<ffffffffa06e3aca>] ? __dbuf_hold_impl+0x21a/0x4c0 [zfs]
[57047.061724]  [<ffffffffa06e3a74>] __dbuf_hold_impl+0x1c4/0x4c0 [zfs]
[57047.061737]  [<ffffffffa06e3deb>] dbuf_hold_impl+0x7b/0xa0 [zfs]
[57047.061749]  [<ffffffffa06e40b0>] dbuf_hold+0x20/0x40 [zfs]
[57047.061762]  [<ffffffffa06eb5bd>] dmu_buf_hold_array_by_dnode+0x15d/0x610 [zfs]
[57047.061776]  [<ffffffffa06ebb4d>] dmu_buf_hold_array+0x5d/0x80 [zfs]
[57047.061789]  [<ffffffffa06ece62>] dmu_write_req+0x72/0x210 [zfs]
[57047.061804]  [<ffffffffa0787e07>] zvol_write+0xc7/0x480 [zfs]
[57047.061817]  [<ffffffffa028c977>] taskq_thread+0x237/0x4b0 [spl]
[57047.061822]  [<ffffffff81092700>] ? wake_up_process+0x40/0x40
[57047.061829]  [<ffffffffa028c740>] ? taskq_cancel_id+0x1f0/0x1f0 [spl]
[57047.061833]  [<ffffffff810835b2>] kthread+0xd2/0xf0
[57047.061837]  [<ffffffff810834e0>] ? kthread_create_on_node+0x180/0x180
[57047.061841]  [<ffffffff815215fc>] ret_from_fork+0x7c/0xb0
[57047.061845]  [<ffffffff810834e0>] ? kthread_create_on_node+0x180/0x180
[57047.061848] INFO: task zvol/5:283 blocked for more than 120 seconds.
[57047.068267]       Tainted: P           O 3.13.6-1-ARCH #1
[57047.073718] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[57047.081619] zvol/5          D 0000000000000246     0   283      2 0x00000000
[57047.081623]  ffff88046180fb18 0000000000000046 ffff8804682e9b00 ffff88046180ffd8
[57047.081628]  0000000000014440 0000000000014440 ffff8804682e9b00 ffffffff8108d4fb
[57047.081632]  000000078101c739 0000000000000202 0000000000000005 ffff88046184d74a
[57047.081636] Call Trace:
[57047.081641]  [<ffffffff8108d4fb>] ? ttwu_stat+0x9b/0x110
[57047.081645]  [<ffffffff810925fa>] ? try_to_wake_up+0x1fa/0x2c0
[57047.081650]  [<ffffffff810926e3>] ? wake_up_process+0x23/0x40
[57047.081653]  [<ffffffff81515d99>] schedule+0x29/0x70
[57047.081657]  [<ffffffff81516196>] schedule_preempt_disabled+0x16/0x20
[57047.081661]  [<ffffffff8151861d>] __mutex_lock_slowpath+0x13d/0x390
[57047.081665]  [<ffffffff81518882>] mutex_lock+0x12/0x22
[57047.081677]  [<ffffffffa06e1406>] dbuf_destroy+0x56/0x1d0 [zfs]
[57047.081689]  [<ffffffffa06e380a>] dbuf_evict+0x1a/0x20 [zfs]
[57047.081701]  [<ffffffffa06e3337>] dbuf_rele_and_unlock+0xb7/0x260 [zfs]
[57047.081713]  [<ffffffffa06e363d>] dmu_buf_rele+0x3d/0x50 [zfs]
[57047.081728]  [<ffffffffa06f6b3f>] dmu_tx_count_write+0x34f/0x6d0 [zfs]
[57047.081743]  [<ffffffffa06f7a66>] dmu_tx_hold_write+0x36/0x50 [zfs]
[57047.081757]  [<ffffffffa0787dda>] zvol_write+0x9a/0x480 [zfs]
[57047.081764]  [<ffffffffa028c977>] taskq_thread+0x237/0x4b0 [spl]
[57047.081768]  [<ffffffff81092700>] ? wake_up_process+0x40/0x40
[57047.081775]  [<ffffffffa028c740>] ? taskq_cancel_id+0x1f0/0x1f0 [spl]
[57047.081779]  [<ffffffff810835b2>] kthread+0xd2/0xf0
[57047.081783]  [<ffffffff810834e0>] ? kthread_create_on_node+0x180/0x180
[57047.081787]  [<ffffffff815215fc>] ret_from_fork+0x7c/0xb0
[57047.081791]  [<ffffffff810834e0>] ? kthread_create_on_node+0x180/0x180
[57047.081794] INFO: task zvol/6:284 blocked for more than 120 seconds.
[57047.088208]       Tainted: P           O 3.13.6-1-ARCH #1
[57047.093656] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[57047.101556] zvol/6          D 0000000000000246     0   284      2 0x00000000
[57047.101560]  ffff880461811a88 0000000000000046 ffff8804682e8900 ffff880461811fd8
[57047.101565]  0000000000014440 0000000000014440 ffff8804682e8900 ffff8804697c6208
[57047.101569]  ffff8804697c6200 0000000000014440 0000000000014440 0000000000014440
[57047.101573] Call Trace:
[57047.101578]  [<ffffffff8108f33a>] ? update_rq_clock.part.69+0x1a/0x100
[57047.101583]  [<ffffffff81099505>] ? set_next_entity+0x95/0xb0
[57047.101588]  [<ffffffff8101359c>] ? __switch_to+0x10c/0x4d0
[57047.101591]  [<ffffffff81515d99>] schedule+0x29/0x70
[57047.101595]  [<ffffffff81516196>] schedule_preempt_disabled+0x16/0x20
[57047.101599]  [<ffffffff8151861d>] __mutex_lock_slowpath+0x13d/0x390
[57047.101603]  [<ffffffff81518882>] mutex_lock+0x12/0x22
[57047.101616]  [<ffffffffa06e2bc7>] dbuf_create+0xf7/0x430 [zfs]
[57047.101628]  [<ffffffffa06e3aca>] ? __dbuf_hold_impl+0x21a/0x4c0 [zfs]
[57047.101641]  [<ffffffffa06e3a74>] __dbuf_hold_impl+0x1c4/0x4c0 [zfs]
[57047.101653]  [<ffffffffa06e3deb>] dbuf_hold_impl+0x7b/0xa0 [zfs]
[57047.101667]  [<ffffffffa06f6b9f>] dmu_tx_count_write+0x3af/0x6d0 [zfs]
[57047.101682]  [<ffffffffa06f7a66>] dmu_tx_hold_write+0x36/0x50 [zfs]
[57047.101697]  [<ffffffffa0787dda>] zvol_write+0x9a/0x480 [zfs]
[57047.101704]  [<ffffffffa028c977>] taskq_thread+0x237/0x4b0 [spl]
[57047.101708]  [<ffffffff81092700>] ? wake_up_process+0x40/0x40
[57047.101715]  [<ffffffffa028c740>] ? taskq_cancel_id+0x1f0/0x1f0 [spl]
[57047.101719]  [<ffffffff810835b2>] kthread+0xd2/0xf0
[57047.101723]  [<ffffffff810834e0>] ? kthread_create_on_node+0x180/0x180
[57047.101727]  [<ffffffff815215fc>] ret_from_fork+0x7c/0xb0
[57047.101731]  [<ffffffff810834e0>] ? kthread_create_on_node+0x180/0x180
[57047.101734] INFO: task zvol/7:285 blocked for more than 120 seconds.
[57047.108148]       Tainted: P           O 3.13.6-1-ARCH #1
[57047.113597] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[57047.121496] zvol/7          D 0000000000000246     0   285      2 0x00000000
[57047.121501]  ffff880461813b18 0000000000000046 ffff8804682eec00 ffff880461813fd8
[57047.121505]  0000000000014440 0000000000014440 ffff8804682eec00 ffffffff8109cf67
[57047.121509]  ffff88047fd94440 0000000000000202 ffff88047fd94440 ffff8804682e8f4a
[57047.121514] Call Trace:
[57047.121519]  [<ffffffff8109cf67>] ? enqueue_task_fair+0x107/0x540
[57047.121523]  [<ffffffff810925fa>] ? try_to_wake_up+0x1fa/0x2c0
[57047.121528]  [<ffffffff810926e3>] ? wake_up_process+0x23/0x40
[57047.121531]  [<ffffffff81515d99>] schedule+0x29/0x70
[57047.121535]  [<ffffffff81516196>] schedule_preempt_disabled+0x16/0x20
[57047.121539]  [<ffffffff8151861d>] __mutex_lock_slowpath+0x13d/0x390
[57047.121542]  [<ffffffff81518882>] mutex_lock+0x12/0x22
[57047.121555]  [<ffffffffa06e1406>] dbuf_destroy+0x56/0x1d0 [zfs]
[57047.121567]  [<ffffffffa06e380a>] dbuf_evict+0x1a/0x20 [zfs]
[57047.121579]  [<ffffffffa06e3337>] dbuf_rele_and_unlock+0xb7/0x260 [zfs]
[57047.121591]  [<ffffffffa06e363d>] dmu_buf_rele+0x3d/0x50 [zfs]
[57047.121605]  [<ffffffffa06f6b3f>] dmu_tx_count_write+0x34f/0x6d0 [zfs]
[57047.121620]  [<ffffffffa06f7a66>] dmu_tx_hold_write+0x36/0x50 [zfs]
[57047.121635]  [<ffffffffa0787dda>] zvol_write+0x9a/0x480 [zfs]
[57047.121642]  [<ffffffffa028c977>] taskq_thread+0x237/0x4b0 [spl]
[57047.121646]  [<ffffffff81092700>] ? wake_up_process+0x40/0x40
[57047.121653]  [<ffffffffa028c740>] ? taskq_cancel_id+0x1f0/0x1f0 [spl]
[57047.121657]  [<ffffffff810835b2>] kthread+0xd2/0xf0
[57047.121661]  [<ffffffff810834e0>] ? kthread_create_on_node+0x180/0x180
[57047.121665]  [<ffffffff815215fc>] ret_from_fork+0x7c/0xb0
[57047.121669]  [<ffffffff810834e0>] ? kthread_create_on_node+0x180/0x180
[57066.070885] systemd[1]: systemd-journald.service stop-sigterm timed out. Killing.

zpool status

Notice the checksum error on the fifth disk. It was preexisting -- the aforementioned Marvell bug caused the disk to go offline and I had to scrub to clean up after it.

  pool: tank0
 state: ONLINE
status: One or more devices has experienced an unrecoverable error.  An
        attempt was made to correct the error.  Applications are unaffected.
action: Determine if the device needs to be replaced, and clear the errors
        using 'zpool clear' or replace the device with 'zpool replace'.
   see: http://zfsonlinux.org/msg/ZFS-8000-9P
  scan: scrub repaired 32K in 1h9m with 0 errors on Thu Mar 27 23:09:33 2014
config:

        NAME                                 STATE     READ WRITE CKSUM
        tank0                                ONLINE       0     0     0
          raidz1-0                           ONLINE       0     0     0
            ata-ST4000VN000-1H4168_Z301538Q  ONLINE       0     0     0
            ata-ST4000VN000-1H4168_Z3015D2D  ONLINE       0     0     0
            ata-ST4000VN000-1H4168_Z3015D40  ONLINE       0     0     0
            ata-ST4000VN000-1H4168_Z3015EBY  ONLINE       0     0     0
            ata-ST4000VN000-1H4168_Z3017J4J  ONLINE       0     0     1

errors: No known data errors

zfs get all tank0

NAME   PROPERTY              VALUE                  SOURCE
tank0  type                  filesystem             -
tank0  creation              Fri Mar 21  7:58 2014  -
tank0  used                  657G                   -
tank0  available             13.6T                  -
tank0  referenced            268K                   -
tank0  compressratio         1.04x                  -
tank0  mounted               yes                    -
tank0  quota                 none                   default
tank0  reservation           none                   default
tank0  recordsize            128K                   default
tank0  mountpoint            /tank0                 default
tank0  sharenfs              off                    default
tank0  checksum              on                     default
tank0  compression           lz4                    local
tank0  atime                 on                     default
tank0  devices               on                     default
tank0  exec                  on                     default
tank0  setuid                on                     default
tank0  readonly              off                    default
tank0  zoned                 off                    default
tank0  snapdir               hidden                 default
tank0  aclinherit            restricted             default
tank0  canmount              on                     default
tank0  xattr                 on                     default
tank0  copies                1                      default
tank0  version               5                      -
tank0  utf8only              off                    -
tank0  normalization         none                   -
tank0  casesensitivity       sensitive              -
tank0  vscan                 off                    default
tank0  nbmand                off                    default
tank0  sharesmb              off                    default
tank0  refquota              none                   default
tank0  refreservation        none                   default
tank0  primarycache          all                    default
tank0  secondarycache        all                    default
tank0  usedbysnapshots       0                      -
tank0  usedbydataset         268K                   -
tank0  usedbychildren        657G                   -
tank0  usedbyrefreservation  0                      -
tank0  logbias               latency                default
tank0  dedup                 off                    default
tank0  mlslabel              none                   default
tank0  sync                  standard               default
tank0  refcompressratio      1.00x                  -
tank0  written               268K                   -
tank0  snapdev               hidden                 default

zfs get all tank0/enc0

This is the zvol.

NAME        PROPERTY              VALUE                  SOURCE
tank0/enc0  type                  volume                 -
tank0/enc0  creation              Mon Mar 24 19:30 2014  -
tank0/enc0  used                  323G                   -
tank0/enc0  available             13.6T                  -
tank0/enc0  referenced            323G                   -
tank0/enc0  compressratio         1.00x                  -
tank0/enc0  reservation           none                   default
tank0/enc0  volsize               1T                     local
tank0/enc0  volblocksize          8K                     -
tank0/enc0  checksum              on                     default
tank0/enc0  compression           off                    local
tank0/enc0  readonly              off                    default
tank0/enc0  copies                1                      default
tank0/enc0  refreservation        none                   default
tank0/enc0  primarycache          all                    default
tank0/enc0  secondarycache        all                    default
tank0/enc0  usedbysnapshots       0                      -
tank0/enc0  usedbydataset         323G                   -
tank0/enc0  usedbychildren        0                      -
tank0/enc0  usedbyrefreservation  0                      -
tank0/enc0  logbias               latency                default
tank0/enc0  dedup                 off                    default
tank0/enc0  mlslabel              none                   default
tank0/enc0  sync                  standard               default
tank0/enc0  refcompressratio      1.00x                  -
tank0/enc0  written               323G                   -
tank0/enc0  snapdev               hidden                 default

Contents of /sys/module/zfs/parameters

l2arc_feed_again = 1
l2arc_feed_min_ms = 200
l2arc_feed_secs = 1
l2arc_headroom = 2
l2arc_headroom_boost = 200
l2arc_nocompress = 0
l2arc_noprefetch = 1
l2arc_norw = 0
l2arc_write_boost = 8388608
l2arc_write_max = 8388608
metaslab_debug = 0
spa_config_path = /etc/zfs/zpool.cache
zfetch_array_rd_sz = 1048576
zfetch_block_cap = 256
zfetch_max_streams = 8
zfetch_min_sec_reap = 2
zfs_arc_grow_retry = 5
zfs_arc_max = 0
zfs_arc_memory_throttle_disable = 1
zfs_arc_meta_limit = 0
zfs_arc_meta_prune = 1048576
zfs_arc_min = 0
zfs_arc_min_prefetch_lifespan = 300
zfs_arc_p_min_shift = 4
zfs_arc_shrink_shift = 5
zfs_autoimport_disable = 0
zfs_deadman_enabled = 1
zfs_deadman_synctime = 1000
zfs_dedup_prefetch = 1
zfs_disable_dup_eviction = 0
zfs_expire_snapshot = 300
zfs_flags = 1
zfs_free_min_time_ms = 1000
zfs_immediate_write_sz = 32768
zfs_mdcomp_disable = 0
zfs_nocacheflush = 0
zfs_no_scrub_io = 0
zfs_no_scrub_prefetch = 0
zfs_no_write_throttle = 0
zfs_pd_blks_max = 100
zfs_prefetch_disable = 0
zfs_read_chunk_size = 1048576
zfs_recover = 0
zfs_resilver_delay = 2
zfs_resilver_min_time_ms = 3000
zfs_scan_idle = 50
zfs_scan_min_time_ms = 500
zfs_scrub_delay = 4
zfs_sync_pass_deferred_free = 2
zfs_sync_pass_dont_compress = 5
zfs_sync_pass_rewrite = 2
zfs_top_maxinflight = 32
zfs_txg_history = 60
zfs_txg_synctime_ms = 1000
zfs_txg_timeout = 5
zfs_vdev_aggregation_limit = 131072
zfs_vdev_cache_bshift = 16
zfs_vdev_cache_max = 16384
zfs_vdev_cache_size = 0
zfs_vdev_max_pending = 10
zfs_vdev_min_pending = 4
zfs_vdev_mirror_switch_us = 10000
zfs_vdev_ramp_rate = 2
zfs_vdev_read_gap_limit = 32768
zfs_vdev_scheduler = noop
zfs_vdev_time_shift = 29
zfs_vdev_write_gap_limit = 4096
zfs_write_limit_inflated = 50470170624
zfs_write_limit_max = 2102923776
zfs_write_limit_min = 33554432
zfs_write_limit_override = 0
zfs_write_limit_shift = 3
zfs_zevent_cols = 80
zfs_zevent_console = 0
zfs_zevent_len_max = 128
zil_replay_disable = 0
zil_slog_limit = 1048576
zio_bulk_flags = 0
zio_delay_max = 30000
zio_injection_enabled = 0
zio_requeue_io_start_cut_in_line = 1
zvol_inhibit_dev = 0
zvol_major = 230
zvol_max_discard_blocks = 16384
zvol_threads = 32

Please let me know if there's anything I should try, or any other data I ought to provide. Thanks!

@cbiffle
Copy link
Author

cbiffle commented Mar 29, 2014

Reading over issue 1909 led me to suspect that someone might ask about the Arch kernel's PREEMPT settings.

My overall kernel config is 4,832 non-comment lines (!) so I'll paste a section here:

$ zcat /proc/config.gz  | grep PREEMPT
CONFIG_TREE_PREEMPT_RCU=y
CONFIG_PREEMPT_RCU=y
CONFIG_PREEMPT_NOTIFIERS=y
# CONFIG_PREEMPT_NONE is not set
# CONFIG_PREEMPT_VOLUNTARY is not set
CONFIG_PREEMPT=y
CONFIG_PREEMPT_COUNT=y
# CONFIG_DEBUG_PREEMPT is not set
# CONFIG_PREEMPT_TRACER is not set

@ryao
Copy link
Contributor

ryao commented Jul 11, 2014

@cbiffle Something went wrong with locking. It is not clear to me what that might be. Was there any more dmesg output or were these all threads? Did you let the system sit for 4 minutes to ensure that all hung threads triggered the hangcheck timer? Are you able to reproduce this issue or was this a one time thing?

@ryao
Copy link
Contributor

ryao commented Jul 13, 2014

@cbiffle When I looked at this two days ago, I was speed reading through reports to see if I could find issues linked to #2484. I had mistaken this for a deadlock. That being said, I think I see at least part of what happened here to cause the "hitch" that you described:

  1. do_try_to_free_pages() called wakeup_flusher_threads(), which is how we were in Workqueue: writeback bdi_writeback_workfn (flush-254:0).
  2. zvol/4:282 blocked on a lock while holding the transaction open.
  3. The lock zvol/4:282 wanted was under contention from other zvol threads that were not holding transactions open.

At the same time, #2484 probably would be able to help here, but that reminds to be seen. That being said, we should look into a possible contention issue.

@behlendorf
Copy link
Contributor

Closing as out of date.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants