search

openzfs / zfs

OpenZFS on Linux and FreeBSD
https://openzfs.github.io/openzfs-docs
Other
10.63k stars 1.75k forks source link

txg_quiesce_thread crash on contentious ZVOL IO abuse - taskq_thread_dynamic related #4464

Closed sempervictus closed 5 years ago

sempervictus commented 8 years ago

While running burn-in tests on a recent build at the datacenter we found that our test loop, which iterates over ZVOLs with single depth synchronous IOs from FIO, can apparently still come up with the txg_quiesce_thread problem, but only when we're toggling ARC settings on the parent dataset between runs. The tests are each 5m of 8 threads doing sync read, random read, sync write, random write, and then a mix of random r/w. Its pretty abusive, and since we started using @DeHackEd's BE5 branch as a base for the build it's been very resistant to crashes of his nature under these conditions.

Disabling spl_taskq_thread_dynamic seems to either fix this, or bury it deeper than our current test pattern shows. The other interesting note is that this seems to occur on RAIDZ2 pools, entirely of SSD, while an all spinner 5-way mirror does not exhibit the behavior.

The zvol_request -> zfs_range_lock -> die_in_scheduling thing has come up before, and is easier to induce on smaller block sized ZVOLs - this happened @ volblocksize=4k while FIO was running 8 threads of blocksize=8k, direct=1, iodepth=1 directly on three ZVOLs in the same pool. This same system has passed this same test multiple times, even with spl_taskq_thread_dynamic=1, though has never failed wit spl_taskq_thread_dynamic=0 (which is how we still run production).

To narrow this down, the test stack which produced the following stack trace consisted of:

  * origin/master
  ** Change KM_SLEEP to TQ_SLEEP in spa_deadman()
  * DHE/BE5 @ 4b9ed698b4838a36daa591d08728a692095f8f01

The resulting output to dmesg is:

[Sat Mar 26 08:05:53 2016] INFO: task txg_quiesce:30035 blocked for more than 180 seconds.
[Sat Mar 26 08:05:53 2016]       Tainted: P           OE   4.4.3-ssv-i7 #ssv
[Sat Mar 26 08:05:53 2016] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Sat Mar 26 08:05:53 2016] txg_quiesce     D ffff8807c6803d48     0 30035      2 0x00000000
[Sat Mar 26 08:05:53 2016]  ffff8807c6803d48 ffff88081c2f0000 ffff8807dfa82000 ffff8807c6804000
[Sat Mar 26 08:05:53 2016]  ffff880f9f640fc0 ffff880f9f641000 ffff880f9f640fe8 0000000000000000
[Sat Mar 26 08:05:53 2016]  ffff8807c6803d60 ffffffff827b9955 ffff880f9f640ff8 ffff8807c6803dc0
[Sat Mar 26 08:05:53 2016] Call Trace:
[Sat Mar 26 08:05:53 2016]  [<ffffffff827b9955>] schedule+0x35/0x80
[Sat Mar 26 08:05:53 2016]  [<ffffffffc00e621d>] cv_wait_common+0xed/0x120 [spl]
[Sat Mar 26 08:05:53 2016]  [<ffffffff820bc5f0>] ? prepare_to_wait_event+0xf0/0xf0
[Sat Mar 26 08:05:53 2016]  [<ffffffffc00e6265>] __cv_wait+0x15/0x20 [spl]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0b9248f>] txg_quiesce_thread+0x2cf/0x3e0 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0b921c0>] ? txg_delay+0x160/0x160 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc00e12f1>] thread_generic_wrapper+0x71/0x80 [spl]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc00e1280>] ? __thread_exit+0x20/0x20 [spl]
[Sat Mar 26 08:05:53 2016]  [<ffffffff82096f69>] kthread+0xc9/0xe0
[Sat Mar 26 08:05:53 2016]  [<ffffffff82096ea0>] ? kthread_park+0x60/0x60
[Sat Mar 26 08:05:53 2016]  [<ffffffff827bd78f>] ret_from_fork+0x3f/0x70
[Sat Mar 26 08:05:53 2016]  [<ffffffff82096ea0>] ? kthread_park+0x60/0x60
[Sat Mar 26 08:05:53 2016] INFO: task fio:26342 blocked for more than 180 seconds.
[Sat Mar 26 08:05:53 2016]       Tainted: P           OE   4.4.3-ssv-i7 #ssv
[Sat Mar 26 08:05:53 2016] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Sat Mar 26 08:05:53 2016] fio             D ffff8807d6ee3788     0 26342  26290 0x00000000
[Sat Mar 26 08:05:53 2016]  ffff8807d6ee3788 ffff88081be20000 ffff88080a426000 ffff8807d6ee4000
[Sat Mar 26 08:05:53 2016]  ffff8810114f29c8 ffff880818668a40 ffff8810114f29f0 0000000000000000
[Sat Mar 26 08:05:53 2016]  ffff8807d6ee37a0 ffffffff827b9955 ffff880818668a38 ffff8807d6ee3800
[Sat Mar 26 08:05:53 2016] Call Trace:
[Sat Mar 26 08:05:53 2016]  [<ffffffff827b9955>] schedule+0x35/0x80
[Sat Mar 26 08:05:53 2016]  [<ffffffffc00e621d>] cv_wait_common+0xed/0x120 [spl]
[Sat Mar 26 08:05:53 2016]  [<ffffffff820bc5f0>] ? prepare_to_wait_event+0xf0/0xf0
[Sat Mar 26 08:05:53 2016]  [<ffffffffc00e6265>] __cv_wait+0x15/0x20 [spl]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0bbe269>] zfs_range_lock+0x219/0x5d0 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0be2b39>] zvol_request+0x259/0x7a0 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffff82363e87>] ? generic_make_request_checks+0x2a7/0x550
[Sat Mar 26 08:05:53 2016]  [<ffffffff82367334>] generic_make_request+0xe4/0x1a0
[Sat Mar 26 08:05:53 2016]  [<ffffffff82367475>] submit_bio+0x85/0x170
[Sat Mar 26 08:05:53 2016]  [<ffffffff8235f63d>] ? bio_alloc_bioset+0x11d/0x200
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222fb3f>] do_blockdev_direct_IO+0x1cef/0x1f10
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222a9a0>] ? I_BDEV+0x20/0x20
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222fda3>] __blockdev_direct_IO+0x43/0x50
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b05c>] blkdev_direct_IO+0x4c/0x50
[Sat Mar 26 08:05:53 2016]  [<ffffffff8217778e>] generic_file_direct_write+0x9e/0x150
[Sat Mar 26 08:05:53 2016]  [<ffffffff82177900>] __generic_file_write_iter+0xc0/0x1e0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b2b0>] ? bd_unlink_disk_holder+0xf0/0xf0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b330>] blkdev_write_iter+0x80/0x100
[Sat Mar 26 08:05:53 2016]  [<ffffffff82327e1d>] ? security_file_permission+0x3d/0xc0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223d689>] aio_run_iocb+0x1f9/0x280
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223e965>] ? do_io_submit+0x215/0x430
[Sat Mar 26 08:05:53 2016]  [<ffffffff827bb4c2>] ? mutex_lock+0x12/0x2f
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223d91a>] ? aio_read_events+0x20a/0x2d0
[Sat Mar 26 08:05:53 2016]  [<ffffffff821d3a4b>] ? kmem_cache_alloc+0x14b/0x160
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223e965>] ? do_io_submit+0x215/0x430
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223e861>] do_io_submit+0x111/0x430
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223eb90>] SyS_io_submit+0x10/0x20
[Sat Mar 26 08:05:53 2016]  [<ffffffff827bd3f6>] entry_SYSCALL_64_fastpath+0x16/0x75
[Sat Mar 26 08:05:53 2016] INFO: task fio:26343 blocked for more than 180 seconds.
[Sat Mar 26 08:05:53 2016]       Tainted: P           OE   4.4.3-ssv-i7 #ssv
[Sat Mar 26 08:05:53 2016] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Sat Mar 26 08:05:53 2016] fio             D ffff88068bae7788     0 26343  26290 0x00000000
[Sat Mar 26 08:05:53 2016]  ffff88068bae7788 ffff88081be0a000 ffff8803bc9fa000 ffff88068bae8000
[Sat Mar 26 08:05:53 2016]  ffff8810114f29c8 ffff880818668a40 ffff8810114f29f0 0000000000000000
[Sat Mar 26 08:05:53 2016]  ffff88068bae77a0 ffffffff827b9955 ffff880818668a38 ffff88068bae7800
[Sat Mar 26 08:05:53 2016] Call Trace:
[Sat Mar 26 08:05:53 2016]  [<ffffffff827b9955>] schedule+0x35/0x80
[Sat Mar 26 08:05:53 2016]  [<ffffffffc00e621d>] cv_wait_common+0xed/0x120 [spl]
[Sat Mar 26 08:05:53 2016]  [<ffffffff820bc5f0>] ? prepare_to_wait_event+0xf0/0xf0
[Sat Mar 26 08:05:53 2016]  [<ffffffffc00e6265>] __cv_wait+0x15/0x20 [spl]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0bbe269>] zfs_range_lock+0x219/0x5d0 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0be2b39>] zvol_request+0x259/0x7a0 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffff82363e87>] ? generic_make_request_checks+0x2a7/0x550
[Sat Mar 26 08:05:53 2016]  [<ffffffff82367334>] generic_make_request+0xe4/0x1a0
[Sat Mar 26 08:05:53 2016]  [<ffffffff82367475>] submit_bio+0x85/0x170
[Sat Mar 26 08:05:53 2016]  [<ffffffff8235f63d>] ? bio_alloc_bioset+0x11d/0x200
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222fb3f>] do_blockdev_direct_IO+0x1cef/0x1f10
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222a9a0>] ? I_BDEV+0x20/0x20
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222fda3>] __blockdev_direct_IO+0x43/0x50
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b05c>] blkdev_direct_IO+0x4c/0x50
[Sat Mar 26 08:05:53 2016]  [<ffffffff8217778e>] generic_file_direct_write+0x9e/0x150
[Sat Mar 26 08:05:53 2016]  [<ffffffff82177900>] __generic_file_write_iter+0xc0/0x1e0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b2b0>] ? bd_unlink_disk_holder+0xf0/0xf0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b330>] blkdev_write_iter+0x80/0x100
[Sat Mar 26 08:05:53 2016]  [<ffffffff82327e1d>] ? security_file_permission+0x3d/0xc0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223d689>] aio_run_iocb+0x1f9/0x280
[Sat Mar 26 08:05:53 2016]  [<ffffffff82015636>] ? __switch_to+0x1d6/0x550
[Sat Mar 26 08:05:53 2016]  [<ffffffff827bb4c2>] ? mutex_lock+0x12/0x2f
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223d91a>] ? aio_read_events+0x20a/0x2d0
[Sat Mar 26 08:05:53 2016]  [<ffffffff821d3a4b>] ? kmem_cache_alloc+0x14b/0x160
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223e965>] ? do_io_submit+0x215/0x430
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223e861>] do_io_submit+0x111/0x430
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223eb90>] SyS_io_submit+0x10/0x20
[Sat Mar 26 08:05:53 2016]  [<ffffffff827bd3f6>] entry_SYSCALL_64_fastpath+0x16/0x75
[Sat Mar 26 08:05:53 2016] INFO: task fio:26344 blocked for more than 180 seconds.
[Sat Mar 26 08:05:53 2016]       Tainted: P           OE   4.4.3-ssv-i7 #ssv
[Sat Mar 26 08:05:53 2016] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Sat Mar 26 08:05:53 2016] fio             D ffff88057ce4f788     0 26344  26290 0x00000000
[Sat Mar 26 08:05:53 2016]  ffff88057ce4f788 ffff88081be0e000 ffff880414dde000 ffff88057ce50000
[Sat Mar 26 08:05:53 2016]  ffff8810114f29c8 ffff880818668a40 ffff8810114f29f0 0000000000000000
[Sat Mar 26 08:05:53 2016]  ffff88057ce4f7a0 ffffffff827b9955 ffff880818668a38 ffff88057ce4f800
[Sat Mar 26 08:05:53 2016] Call Trace:
[Sat Mar 26 08:05:53 2016]  [<ffffffff827b9955>] schedule+0x35/0x80
[Sat Mar 26 08:05:53 2016]  [<ffffffffc00e621d>] cv_wait_common+0xed/0x120 [spl]
[Sat Mar 26 08:05:53 2016]  [<ffffffff820bc5f0>] ? prepare_to_wait_event+0xf0/0xf0
[Sat Mar 26 08:05:53 2016]  [<ffffffffc00e6265>] __cv_wait+0x15/0x20 [spl]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0bbe269>] zfs_range_lock+0x219/0x5d0 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0be2b39>] zvol_request+0x259/0x7a0 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffff82363e87>] ? generic_make_request_checks+0x2a7/0x550
[Sat Mar 26 08:05:53 2016]  [<ffffffff82367334>] generic_make_request+0xe4/0x1a0
[Sat Mar 26 08:05:53 2016]  [<ffffffff82367475>] submit_bio+0x85/0x170
[Sat Mar 26 08:05:53 2016]  [<ffffffff8235f63d>] ? bio_alloc_bioset+0x11d/0x200
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222fb3f>] do_blockdev_direct_IO+0x1cef/0x1f10
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222a9a0>] ? I_BDEV+0x20/0x20
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222fda3>] __blockdev_direct_IO+0x43/0x50
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b05c>] blkdev_direct_IO+0x4c/0x50
[Sat Mar 26 08:05:53 2016]  [<ffffffff8217778e>] generic_file_direct_write+0x9e/0x150
[Sat Mar 26 08:05:53 2016]  [<ffffffff82177900>] __generic_file_write_iter+0xc0/0x1e0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b2b0>] ? bd_unlink_disk_holder+0xf0/0xf0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b330>] blkdev_write_iter+0x80/0x100
[Sat Mar 26 08:05:53 2016]  [<ffffffff82327e1d>] ? security_file_permission+0x3d/0xc0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223d689>] aio_run_iocb+0x1f9/0x280
[Sat Mar 26 08:05:53 2016]  [<ffffffff82015636>] ? __switch_to+0x1d6/0x550
[Sat Mar 26 08:05:53 2016]  [<ffffffff827bb4c2>] ? mutex_lock+0x12/0x2f
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223d91a>] ? aio_read_events+0x20a/0x2d0
[Sat Mar 26 08:05:53 2016]  [<ffffffff821d3a4b>] ? kmem_cache_alloc+0x14b/0x160
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223e965>] ? do_io_submit+0x215/0x430
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223e861>] do_io_submit+0x111/0x430
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223eb90>] SyS_io_submit+0x10/0x20
[Sat Mar 26 08:05:53 2016]  [<ffffffff827bd3f6>] entry_SYSCALL_64_fastpath+0x16/0x75
[Sat Mar 26 08:05:53 2016] INFO: task fio:26345 blocked for more than 180 seconds.
[Sat Mar 26 08:05:53 2016]       Tainted: P           OE   4.4.3-ssv-i7 #ssv
[Sat Mar 26 08:05:53 2016] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Sat Mar 26 08:05:53 2016] fio             D ffff8804862875a8     0 26345  26290 0x00000000
[Sat Mar 26 08:05:53 2016]  ffff8804862875a8 ffff88081c2f0000 ffff88081c28e000 ffff880486288000
[Sat Mar 26 08:05:53 2016]  0000000000000000 7fffffffffffffff ffff88052b3ba590 0000000000000001
[Sat Mar 26 08:05:53 2016]  ffff8804862875c0 ffffffff827b9955 ffff88101f2d7c40 ffff880486287638
[Sat Mar 26 08:05:53 2016] Call Trace:
[Sat Mar 26 08:05:53 2016]  [<ffffffff827b9955>] schedule+0x35/0x80
[Sat Mar 26 08:05:53 2016]  [<ffffffff827bc2b0>] schedule_timeout+0x200/0x260
[Sat Mar 26 08:05:53 2016]  [<ffffffff82368c57>] ? blk_flush_plug_list+0xc7/0x210
[Sat Mar 26 08:05:53 2016]  [<ffffffff820f7d2a>] ? ktime_get+0x3a/0x90
[Sat Mar 26 08:05:53 2016]  [<ffffffff827b9016>] io_schedule_timeout+0xa6/0x110
[Sat Mar 26 08:05:53 2016]  [<ffffffffc00e61dd>] cv_wait_common+0xad/0x120 [spl]
[Sat Mar 26 08:05:53 2016]  [<ffffffff820bc5f0>] ? prepare_to_wait_event+0xf0/0xf0
[Sat Mar 26 08:05:53 2016]  [<ffffffffc00e62a8>] __cv_wait_io+0x18/0x20 [spl]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0bd89a4>] zio_wait+0xc4/0x150 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0b38fa6>] dbuf_read+0x2f6/0x6e0 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0b3b833>] dmu_buf_will_dirty+0x113/0x130 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0b4248f>] dmu_write_uio_dnode+0x5f/0x120 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0b4391c>] dmu_write_uio_dbuf+0x4c/0x70 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0be2bcb>] zvol_request+0x2eb/0x7a0 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffff82363e87>] ? generic_make_request_checks+0x2a7/0x550
[Sat Mar 26 08:05:53 2016]  [<ffffffff82367334>] generic_make_request+0xe4/0x1a0
[Sat Mar 26 08:05:53 2016]  [<ffffffff82367475>] submit_bio+0x85/0x170
[Sat Mar 26 08:05:53 2016]  [<ffffffff8235f63d>] ? bio_alloc_bioset+0x11d/0x200
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222fb3f>] do_blockdev_direct_IO+0x1cef/0x1f10
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222a9a0>] ? I_BDEV+0x20/0x20
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222fda3>] __blockdev_direct_IO+0x43/0x50
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b05c>] blkdev_direct_IO+0x4c/0x50
[Sat Mar 26 08:05:53 2016]  [<ffffffff8217778e>] generic_file_direct_write+0x9e/0x150
[Sat Mar 26 08:05:53 2016]  [<ffffffff82177900>] __generic_file_write_iter+0xc0/0x1e0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b2b0>] ? bd_unlink_disk_holder+0xf0/0xf0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b330>] blkdev_write_iter+0x80/0x100
[Sat Mar 26 08:05:53 2016]  [<ffffffff82327e1d>] ? security_file_permission+0x3d/0xc0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223d689>] aio_run_iocb+0x1f9/0x280
[Sat Mar 26 08:05:53 2016]  [<ffffffff827bb4c2>] ? mutex_lock+0x12/0x2f
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223d91a>] ? aio_read_events+0x20a/0x2d0
[Sat Mar 26 08:05:53 2016]  [<ffffffff821d3a4b>] ? kmem_cache_alloc+0x14b/0x160
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223e965>] ? do_io_submit+0x215/0x430
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223e861>] do_io_submit+0x111/0x430
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223eb90>] SyS_io_submit+0x10/0x20
[Sat Mar 26 08:05:53 2016]  [<ffffffff827bd3f6>] entry_SYSCALL_64_fastpath+0x16/0x75
[Sat Mar 26 08:05:53 2016] INFO: task fio:26346 blocked for more than 180 seconds.
[Sat Mar 26 08:05:53 2016]       Tainted: P           OE   4.4.3-ssv-i7 #ssv
[Sat Mar 26 08:05:53 2016] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Sat Mar 26 08:05:53 2016] fio             D ffff8803d7d4b788     0 26346  26290 0x00000000
[Sat Mar 26 08:05:53 2016]  ffff8803d7d4b788 ffff88081c2d6000 ffff88080a48c000 ffff8803d7d4c000
[Sat Mar 26 08:05:53 2016]  ffff8810114f29c8 ffff880818668a40 ffff8810114f29f0 0000000000000000
[Sat Mar 26 08:05:53 2016]  ffff8803d7d4b7a0 ffffffff827b9955 ffff880818668a38 ffff8803d7d4b800
[Sat Mar 26 08:05:53 2016] Call Trace:
[Sat Mar 26 08:05:53 2016]  [<ffffffff827b9955>] schedule+0x35/0x80
[Sat Mar 26 08:05:53 2016]  [<ffffffffc00e621d>] cv_wait_common+0xed/0x120 [spl]
[Sat Mar 26 08:05:53 2016]  [<ffffffff820bc5f0>] ? prepare_to_wait_event+0xf0/0xf0
[Sat Mar 26 08:05:53 2016]  [<ffffffffc00e6265>] __cv_wait+0x15/0x20 [spl]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0bbe269>] zfs_range_lock+0x219/0x5d0 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0be2b39>] zvol_request+0x259/0x7a0 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffff82363e87>] ? generic_make_request_checks+0x2a7/0x550
[Sat Mar 26 08:05:53 2016]  [<ffffffff82367334>] generic_make_request+0xe4/0x1a0
[Sat Mar 26 08:05:53 2016]  [<ffffffff82367475>] submit_bio+0x85/0x170
[Sat Mar 26 08:05:53 2016]  [<ffffffff8235f63d>] ? bio_alloc_bioset+0x11d/0x200
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222fb3f>] do_blockdev_direct_IO+0x1cef/0x1f10
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222a9a0>] ? I_BDEV+0x20/0x20
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222fda3>] __blockdev_direct_IO+0x43/0x50
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b05c>] blkdev_direct_IO+0x4c/0x50
[Sat Mar 26 08:05:53 2016]  [<ffffffff8217778e>] generic_file_direct_write+0x9e/0x150
[Sat Mar 26 08:05:53 2016]  [<ffffffff82177900>] __generic_file_write_iter+0xc0/0x1e0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b2b0>] ? bd_unlink_disk_holder+0xf0/0xf0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b330>] blkdev_write_iter+0x80/0x100
[Sat Mar 26 08:05:53 2016]  [<ffffffff82327e1d>] ? security_file_permission+0x3d/0xc0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223d689>] aio_run_iocb+0x1f9/0x280
[Sat Mar 26 08:05:53 2016]  [<ffffffff827bb4c2>] ? mutex_lock+0x12/0x2f
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223d91a>] ? aio_read_events+0x20a/0x2d0
[Sat Mar 26 08:05:53 2016]  [<ffffffff821d3a4b>] ? kmem_cache_alloc+0x14b/0x160
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223e965>] ? do_io_submit+0x215/0x430
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223e861>] do_io_submit+0x111/0x430
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223eb90>] SyS_io_submit+0x10/0x20
[Sat Mar 26 08:05:53 2016]  [<ffffffff827bd3f6>] entry_SYSCALL_64_fastpath+0x16/0x75
[Sat Mar 26 08:05:53 2016] INFO: task fio:26347 blocked for more than 180 seconds.
[Sat Mar 26 08:05:53 2016]       Tainted: P           OE   4.4.3-ssv-i7 #ssv
[Sat Mar 26 08:05:53 2016] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Sat Mar 26 08:05:53 2016] fio             D ffff880499e47788     0 26347  26290 0x00000000
[Sat Mar 26 08:05:53 2016]  ffff880499e47788 ffff88081c2d2000 ffff88081beae000 ffff880499e48000
[Sat Mar 26 08:05:53 2016]  ffff8810114f29c8 ffff880818668a40 ffff8810114f29f0 0000000000000000
[Sat Mar 26 08:05:53 2016]  ffff880499e477a0 ffffffff827b9955 ffff880818668a38 ffff880499e47800
[Sat Mar 26 08:05:53 2016] Call Trace:
[Sat Mar 26 08:05:53 2016]  [<ffffffff827b9955>] schedule+0x35/0x80
[Sat Mar 26 08:05:53 2016]  [<ffffffffc00e621d>] cv_wait_common+0xed/0x120 [spl]
[Sat Mar 26 08:05:53 2016]  [<ffffffff820bc5f0>] ? prepare_to_wait_event+0xf0/0xf0
[Sat Mar 26 08:05:53 2016]  [<ffffffffc00e6265>] __cv_wait+0x15/0x20 [spl]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0bbe269>] zfs_range_lock+0x219/0x5d0 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0be2b39>] zvol_request+0x259/0x7a0 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffff82363e87>] ? generic_make_request_checks+0x2a7/0x550
[Sat Mar 26 08:05:53 2016]  [<ffffffff82367334>] generic_make_request+0xe4/0x1a0
[Sat Mar 26 08:05:53 2016]  [<ffffffff82367475>] submit_bio+0x85/0x170
[Sat Mar 26 08:05:53 2016]  [<ffffffff8235f63d>] ? bio_alloc_bioset+0x11d/0x200
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222fb3f>] do_blockdev_direct_IO+0x1cef/0x1f10
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222a9a0>] ? I_BDEV+0x20/0x20
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222fda3>] __blockdev_direct_IO+0x43/0x50
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b05c>] blkdev_direct_IO+0x4c/0x50
[Sat Mar 26 08:05:53 2016]  [<ffffffff8217778e>] generic_file_direct_write+0x9e/0x150
[Sat Mar 26 08:05:53 2016]  [<ffffffff82177900>] __generic_file_write_iter+0xc0/0x1e0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b2b0>] ? bd_unlink_disk_holder+0xf0/0xf0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b330>] blkdev_write_iter+0x80/0x100
[Sat Mar 26 08:05:53 2016]  [<ffffffff82327e1d>] ? security_file_permission+0x3d/0xc0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223d689>] aio_run_iocb+0x1f9/0x280
[Sat Mar 26 08:05:53 2016]  [<ffffffff827bb4c2>] ? mutex_lock+0x12/0x2f
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223d91a>] ? aio_read_events+0x20a/0x2d0
[Sat Mar 26 08:05:53 2016]  [<ffffffff821d3a4b>] ? kmem_cache_alloc+0x14b/0x160
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223e965>] ? do_io_submit+0x215/0x430
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223e861>] do_io_submit+0x111/0x430
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223eb90>] SyS_io_submit+0x10/0x20
[Sat Mar 26 08:05:53 2016]  [<ffffffff827bd3f6>] entry_SYSCALL_64_fastpath+0x16/0x75
[Sat Mar 26 08:05:53 2016] INFO: task fio:26348 blocked for more than 180 seconds.
[Sat Mar 26 08:05:53 2016]       Tainted: P           OE   4.4.3-ssv-i7 #ssv
[Sat Mar 26 08:05:53 2016] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Sat Mar 26 08:05:53 2016] fio             D ffff88066b78b788     0 26348  26290 0x00000000
[Sat Mar 26 08:05:53 2016]  ffff88066b78b788 ffff88081be0c000 ffff8806e3d74000 ffff88066b78c000
[Sat Mar 26 08:05:53 2016]  ffff8810114f29c8 ffff880818668a40 ffff8810114f29f0 0000000000000000
[Sat Mar 26 08:05:53 2016]  ffff88066b78b7a0 ffffffff827b9955 ffff880818668a38 ffff88066b78b800
[Sat Mar 26 08:05:53 2016] Call Trace:
[Sat Mar 26 08:05:53 2016]  [<ffffffff827b9955>] schedule+0x35/0x80
[Sat Mar 26 08:05:53 2016]  [<ffffffffc00e621d>] cv_wait_common+0xed/0x120 [spl]
[Sat Mar 26 08:05:53 2016]  [<ffffffff820bc5f0>] ? prepare_to_wait_event+0xf0/0xf0
[Sat Mar 26 08:05:53 2016]  [<ffffffffc00e6265>] __cv_wait+0x15/0x20 [spl]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0bbe269>] zfs_range_lock+0x219/0x5d0 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0be2b39>] zvol_request+0x259/0x7a0 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffff82363e87>] ? generic_make_request_checks+0x2a7/0x550
[Sat Mar 26 08:05:53 2016]  [<ffffffff82367334>] generic_make_request+0xe4/0x1a0
[Sat Mar 26 08:05:53 2016]  [<ffffffff82367475>] submit_bio+0x85/0x170
[Sat Mar 26 08:05:53 2016]  [<ffffffff8235f63d>] ? bio_alloc_bioset+0x11d/0x200
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222fb3f>] do_blockdev_direct_IO+0x1cef/0x1f10
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222a9a0>] ? I_BDEV+0x20/0x20
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222fda3>] __blockdev_direct_IO+0x43/0x50
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b05c>] blkdev_direct_IO+0x4c/0x50
[Sat Mar 26 08:05:53 2016]  [<ffffffff8217778e>] generic_file_direct_write+0x9e/0x150
[Sat Mar 26 08:05:53 2016]  [<ffffffff82177900>] __generic_file_write_iter+0xc0/0x1e0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b2b0>] ? bd_unlink_disk_holder+0xf0/0xf0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b330>] blkdev_write_iter+0x80/0x100
[Sat Mar 26 08:05:53 2016]  [<ffffffff82327e1d>] ? security_file_permission+0x3d/0xc0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223d689>] aio_run_iocb+0x1f9/0x280
[Sat Mar 26 08:05:53 2016]  [<ffffffff827bb4c2>] ? mutex_lock+0x12/0x2f
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223d91a>] ? aio_read_events+0x20a/0x2d0
[Sat Mar 26 08:05:53 2016]  [<ffffffff821d3a4b>] ? kmem_cache_alloc+0x14b/0x160
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223e965>] ? do_io_submit+0x215/0x430
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223e861>] do_io_submit+0x111/0x430
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223eb90>] SyS_io_submit+0x10/0x20
[Sat Mar 26 08:05:53 2016]  [<ffffffff827bd3f6>] entry_SYSCALL_64_fastpath+0x16/0x75
[Sat Mar 26 08:05:53 2016] INFO: task fio:26349 blocked for more than 180 seconds.
[Sat Mar 26 08:05:53 2016]       Tainted: P           OE   4.4.3-ssv-i7 #ssv
[Sat Mar 26 08:05:53 2016] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Sat Mar 26 08:05:53 2016] fio             D ffff88063f2ff788     0 26349  26290 0x00000000
[Sat Mar 26 08:05:53 2016]  ffff88063f2ff788 ffff88081c2d4000 ffff8806e3d72000 ffff88063f300000
[Sat Mar 26 08:05:53 2016]  ffff8810114f29c8 ffff880818668a40 ffff8810114f29f0 0000000000000000
[Sat Mar 26 08:05:53 2016]  ffff88063f2ff7a0 ffffffff827b9955 ffff880818668a38 ffff88063f2ff800
[Sat Mar 26 08:05:53 2016] Call Trace:
[Sat Mar 26 08:05:53 2016]  [<ffffffff827b9955>] schedule+0x35/0x80
[Sat Mar 26 08:05:53 2016]  [<ffffffffc00e621d>] cv_wait_common+0xed/0x120 [spl]
[Sat Mar 26 08:05:53 2016]  [<ffffffff820bc5f0>] ? prepare_to_wait_event+0xf0/0xf0
[Sat Mar 26 08:05:53 2016]  [<ffffffffc00e6265>] __cv_wait+0x15/0x20 [spl]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0bbe269>] zfs_range_lock+0x219/0x5d0 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffffc0be2b39>] zvol_request+0x259/0x7a0 [zfs]
[Sat Mar 26 08:05:53 2016]  [<ffffffff82363e87>] ? generic_make_request_checks+0x2a7/0x550
[Sat Mar 26 08:05:53 2016]  [<ffffffff82367334>] generic_make_request+0xe4/0x1a0
[Sat Mar 26 08:05:53 2016]  [<ffffffff82367475>] submit_bio+0x85/0x170
[Sat Mar 26 08:05:53 2016]  [<ffffffff8235f63d>] ? bio_alloc_bioset+0x11d/0x200
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222fb3f>] do_blockdev_direct_IO+0x1cef/0x1f10
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222a9a0>] ? I_BDEV+0x20/0x20
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222fda3>] __blockdev_direct_IO+0x43/0x50
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b05c>] blkdev_direct_IO+0x4c/0x50
[Sat Mar 26 08:05:53 2016]  [<ffffffff8217778e>] generic_file_direct_write+0x9e/0x150
[Sat Mar 26 08:05:53 2016]  [<ffffffff82177900>] __generic_file_write_iter+0xc0/0x1e0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b2b0>] ? bd_unlink_disk_holder+0xf0/0xf0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8222b330>] blkdev_write_iter+0x80/0x100
[Sat Mar 26 08:05:53 2016]  [<ffffffff82327e1d>] ? security_file_permission+0x3d/0xc0
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223d689>] aio_run_iocb+0x1f9/0x280
[Sat Mar 26 08:05:53 2016]  [<ffffffff82015636>] ? __switch_to+0x1d6/0x550
[Sat Mar 26 08:05:53 2016]  [<ffffffff827bb4c2>] ? mutex_lock+0x12/0x2f
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223d91a>] ? aio_read_events+0x20a/0x2d0
[Sat Mar 26 08:05:53 2016]  [<ffffffff821d3a4b>] ? kmem_cache_alloc+0x14b/0x160
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223e965>] ? do_io_submit+0x215/0x430
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223e861>] do_io_submit+0x111/0x430
[Sat Mar 26 08:05:53 2016]  [<ffffffff8223eb90>] SyS_io_submit+0x10/0x20
[Sat Mar 26 08:05:53 2016]  [<ffffffff827bd3f6>] entry_SYSCALL_64_fastpath+0x16/0x75
[Sat Mar 26 08:08:53 2016] INFO: task txg_quiesce:30035 blocked for more than 180 seconds.
[Sat Mar 26 08:08:53 2016]       Tainted: P           OE   4.4.3-ssv-i7 #ssv
[Sat Mar 26 08:08:53 2016] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Sat Mar 26 08:08:53 2016] txg_quiesce     D ffff8807c6803d48     0 30035      2 0x00000000
[Sat Mar 26 08:08:53 2016]  ffff8807c6803d48 ffff88081c2f0000 ffff8807dfa82000 ffff8807c6804000
[Sat Mar 26 08:08:53 2016]  ffff880f9f640fc0 ffff880f9f641000 ffff880f9f640fe8 0000000000000000
[Sat Mar 26 08:08:53 2016]  ffff8807c6803d60 ffffffff827b9955 ffff880f9f640ff8 ffff8807c6803dc0
[Sat Mar 26 08:08:53 2016] Call Trace:
[Sat Mar 26 08:08:53 2016]  [<ffffffff827b9955>] schedule+0x35/0x80
[Sat Mar 26 08:08:53 2016]  [<ffffffffc00e621d>] cv_wait_common+0xed/0x120 [spl]
[Sat Mar 26 08:08:53 2016]  [<ffffffff820bc5f0>] ? prepare_to_wait_event+0xf0/0xf0
[Sat Mar 26 08:08:53 2016]  [<ffffffffc00e6265>] __cv_wait+0x15/0x20 [spl]
[Sat Mar 26 08:08:53 2016]  [<ffffffffc0b9248f>] txg_quiesce_thread+0x2cf/0x3e0 [zfs]
[Sat Mar 26 08:08:53 2016]  [<ffffffffc0b921c0>] ? txg_delay+0x160/0x160 [zfs]
[Sat Mar 26 08:08:53 2016]  [<ffffffffc00e12f1>] thread_generic_wrapper+0x71/0x80 [spl]
[Sat Mar 26 08:08:53 2016]  [<ffffffffc00e1280>] ? __thread_exit+0x20/0x20 [spl]
[Sat Mar 26 08:08:53 2016]  [<ffffffff82096f69>] kthread+0xc9/0xe0
[Sat Mar 26 08:08:53 2016]  [<ffffffff82096ea0>] ? kthread_park+0x60/0x60
[Sat Mar 26 08:08:53 2016]  [<ffffffff827bd78f>] ret_from_fork+0x3f/0x70
[Sat Mar 26 08:08:53 2016]  [<ffffffff82096ea0>] ? kthread_park+0x60/0x60

The kernel version used here uses BFQ for IO scheduling, but without the BFS CPU scheduler. ZFS is atop dm-crypt in both pools, all disks are on identical SAS HBAs. All VDEVs are ashift=12 according to zdb.

dweeezil commented 8 years ago

@sempervictus Addressing dynamic taskqs only: I wonder if your load is running afoul of the behavior caused by the spl_taskq_thread_sequential parameter? By default, it's set to 4 which means a dynamic taskq has slightly different semantics than a non-dynamic taskq. Specifically, they'll run that many requests sequentially, potentially reducing concurrency, before spawning a new handler thread. Non-dynamic taskqs on the other hand, in which the full set of threads are pre-spawned will always provide for additional concurrency if a thread is available. I'm fairly certain it's safe to set spl_taskq_thread_sequential to zero which will cause the concurrency behavior of dynamic taskqs to more closely match that of non-dynamic taskqs.

sempervictus commented 8 years ago

@dweeezil: thank you, will try that next. However, i first have to get the pool to import safely, and it seems to crash during ZIL replay.

Far as i can tell, when this error occurs, all subsequent writes go in to the ZIL instead of disk, and when the pool finally grinds to a halt, the host is hosed - ipmitool chassis power reset hosed. When the host reboots, and i import the pool, it hangs, for hours, usually resulting in the following crash:

[22871.132146] INFO: task txg_quiesce:29465 blocked for more than 180 seconds.
[22871.132864]       Tainted: P           OE   4.4.3-ssv-i7 #ssv
[22871.133463] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[22871.134271] txg_quiesce     D ffff8800b83b3d48     0 29465      2 0x00000000
[22871.134276]  ffff8800b83b3d48 ffffffff82c22500 ffff8800ba058000 ffff8800b83b4000
[22871.134279]  ffff880bdf3b0918 ffff880bdf3b09e8 ffff880bdf3b0940 0000000000000000
[22871.134282]  ffff8800b83b3d60 ffffffff827b9955 ffff880bdf3b09e0 ffff8800b83b3dc0
[22871.134285] Call Trace:
[22871.134293]  [<ffffffff827b9955>] schedule+0x35/0x80
[22871.134306]  [<ffffffffc009a16d>] cv_wait_common+0xed/0x120 [spl]
[22871.134311]  [<ffffffff820bc5f0>] ? prepare_to_wait_event+0xf0/0xf0
[22871.134320]  [<ffffffffc009a1b5>] __cv_wait+0x15/0x20 [spl]
[22871.134388]  [<ffffffffc045d21e>] txg_quiesce_thread+0x2ce/0x3e0 [zfs]
[22871.134436]  [<ffffffffc045cf50>] ? txg_delay+0x160/0x160 [zfs]
[22871.134443]  [<ffffffffc00952f1>] thread_generic_wrapper+0x71/0x80 [spl]
[22871.134450]  [<ffffffffc0095280>] ? __thread_exit+0x20/0x20 [spl]
[22871.134453]  [<ffffffff82096f69>] kthread+0xc9/0xe0
[22871.134455]  [<ffffffff82096ea0>] ? kthread_park+0x60/0x60
[22871.134459]  [<ffffffff827bd78f>] ret_from_fork+0x3f/0x70
[22871.134461]  [<ffffffff82096ea0>] ? kthread_park+0x60/0x60
[23051.218809] INFO: task txg_quiesce:29465 blocked for more than 180 seconds.
[23051.219528]       Tainted: P           OE   4.4.3-ssv-i7 #ssv
[23051.220133] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[23051.220948] txg_quiesce     D ffff8800b83b3d48     0 29465      2 0x00000000
[23051.220953]  ffff8800b83b3d48 ffffffff82c22500 ffff8800ba058000 ffff8800b83b4000
[23051.220956]  ffff880bdf3b0918 ffff880bdf3b09e8 ffff880bdf3b0940 0000000000000000
[23051.220959]  ffff8800b83b3d60 ffffffff827b9955 ffff880bdf3b09e0 ffff8800b83b3dc0
[23051.220962] Call Trace:
[23051.220971]  [<ffffffff827b9955>] schedule+0x35/0x80
[23051.220984]  [<ffffffffc009a16d>] cv_wait_common+0xed/0x120 [spl]
[23051.220989]  [<ffffffff820bc5f0>] ? prepare_to_wait_event+0xf0/0xf0
[23051.220998]  [<ffffffffc009a1b5>] __cv_wait+0x15/0x20 [spl]
[23051.221063]  [<ffffffffc045d21e>] txg_quiesce_thread+0x2ce/0x3e0 [zfs]
[23051.221115]  [<ffffffffc045cf50>] ? txg_delay+0x160/0x160 [zfs]
[23051.221123]  [<ffffffffc00952f1>] thread_generic_wrapper+0x71/0x80 [spl]
[23051.221131]  [<ffffffffc0095280>] ? __thread_exit+0x20/0x20 [spl]
[23051.221134]  [<ffffffff82096f69>] kthread+0xc9/0xe0
[23051.221137]  [<ffffffff82096ea0>] ? kthread_park+0x60/0x60
[23051.221140]  [<ffffffff827bd78f>] ret_from_fork+0x3f/0x70
[23051.221143]  [<ffffffff82096ea0>] ? kthread_park+0x60/0x60
[23051.221148] INFO: task mount.zfs:29611 blocked for more than 180 seconds.
[23051.221855]       Tainted: P           OE   4.4.3-ssv-i7 #ssv
[23051.222444] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[23051.223247] mount.zfs       D ffff8805e32dfbc8     0 29611  29610 0x00000002
[23051.223251]  ffff8805e32dfbc8 ffff880c23e74000 ffff8800be100000 ffff8805e32e0000
[23051.223257]  ffff880bf4b9b220 ffff880bf4b9b2e0 ffff880bf4b9b248 0000000000000000
[23051.223261]  ffff8805e32dfbe0 ffffffff827b9955 ffff880bf4b9b2d8 ffff8805e32dfc40
[23051.223264] Call Trace:
[23051.223268]  [<ffffffff827b9955>] schedule+0x35/0x80
[23051.223278]  [<ffffffffc009a16d>] cv_wait_common+0xed/0x120 [spl]
[23051.223281]  [<ffffffff820bc5f0>] ? prepare_to_wait_event+0xf0/0xf0
[23051.223290]  [<ffffffffc009a1b5>] __cv_wait+0x15/0x20 [spl]
[23051.223342]  [<ffffffffc045ccb9>] txg_wait_synced+0xe9/0x130 [zfs]
[23051.223398]  [<ffffffffc049f05a>] zil_replay+0xca/0x100 [zfs]
[23051.223453]  [<ffffffffc048cb68>] zfs_sb_setup+0x158/0x170 [zfs]
[23051.223508]  [<ffffffffc048d7c7>] zfs_domount+0x2a7/0x330 [zfs]
[23051.223512]  [<ffffffff821f5ac0>] ? get_anon_bdev+0xf0/0xf0
[23051.223568]  [<ffffffffc04aa9a0>] ? zpl_kill_sb+0x20/0x20 [zfs]
[23051.223626]  [<ffffffffc04aa9cc>] zpl_fill_super+0x2c/0x40 [zfs]
[23051.223640]  [<ffffffff821f651d>] mount_nodev+0x4d/0xa0
[23051.223700]  [<ffffffffc04aae12>] zpl_mount+0x52/0x80 [zfs]
[23051.223708]  [<ffffffff821f6ff9>] mount_fs+0x39/0x160
[23051.223717]  [<ffffffff82211737>] vfs_kern_mount+0x67/0x110
[23051.223720]  [<ffffffff82213cc0>] do_mount+0x220/0xdd0
[23051.223725]  [<ffffffff821c20e8>] ? alloc_pages_current+0x88/0x120
[23051.223730]  [<ffffffff82179efe>] ? __get_free_pages+0xe/0x40
[23051.223733]  [<ffffffff82213976>] ? copy_mount_options+0x36/0x140
[23051.223736]  [<ffffffff82214b5b>] SyS_mount+0x8b/0xe0
[23051.223739]  [<ffffffff827bd3f6>] entry_SYSCALL_64_fastpath+0x16/0x75
[23231.308478] INFO: task txg_quiesce:29465 blocked for more than 180 seconds.
[23231.309193]       Tainted: P           OE   4.4.3-ssv-i7 #ssv
[23231.309790] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[23231.310594] txg_quiesce     D ffff8800b83b3d48     0 29465      2 0x00000000
[23231.310599]  ffff8800b83b3d48 ffffffff82c22500 ffff8800ba058000 ffff8800b83b4000
[23231.310603]  ffff880bdf3b0918 ffff880bdf3b09e8 ffff880bdf3b0940 0000000000000000
[23231.310606]  ffff8800b83b3d60 ffffffff827b9955 ffff880bdf3b09e0 ffff8800b83b3dc0
[23231.310609] Call Trace:
[23231.310617]  [<ffffffff827b9955>] schedule+0x35/0x80
[23231.310631]  [<ffffffffc009a16d>] cv_wait_common+0xed/0x120 [spl]
[23231.310636]  [<ffffffff820bc5f0>] ? prepare_to_wait_event+0xf0/0xf0
[23231.310646]  [<ffffffffc009a1b5>] __cv_wait+0x15/0x20 [spl]
[23231.310715]  [<ffffffffc045d21e>] txg_quiesce_thread+0x2ce/0x3e0 [zfs]
[23231.310767]  [<ffffffffc045cf50>] ? txg_delay+0x160/0x160 [zfs]
[23231.310775]  [<ffffffffc00952f1>] thread_generic_wrapper+0x71/0x80 [spl]
[23231.310782]  [<ffffffffc0095280>] ? __thread_exit+0x20/0x20 [spl]
[23231.310786]  [<ffffffff82096f69>] kthread+0xc9/0xe0
[23231.310789]  [<ffffffff82096ea0>] ? kthread_park+0x60/0x60
[23231.310792]  [<ffffffff827bd78f>] ret_from_fork+0x3f/0x70
[23231.310794]  [<ffffffff82096ea0>] ? kthread_park+0x60/0x60
[23231.310799] INFO: task mount.zfs:29611 blocked for more than 180 seconds.
[23231.311493]       Tainted: P           OE   4.4.3-ssv-i7 #ssv
[23231.312078] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[23231.312894] mount.zfs       D ffff8805e32dfbc8     0 29611  29610 0x00000002
[23231.312898]  ffff8805e32dfbc8 ffff880c23e74000 ffff8800be100000 ffff8805e32e0000
[23231.312903]  ffff880bf4b9b220 ffff880bf4b9b2e0 ffff880bf4b9b248 0000000000000000
[23231.312907]  ffff8805e32dfbe0 ffffffff827b9955 ffff880bf4b9b2d8 ffff8805e32dfc40
[23231.312910] Call Trace:
[23231.312914]  [<ffffffff827b9955>] schedule+0x35/0x80
[23231.312923]  [<ffffffffc009a16d>] cv_wait_common+0xed/0x120 [spl]
[23231.312927]  [<ffffffff820bc5f0>] ? prepare_to_wait_event+0xf0/0xf0
[23231.312936]  [<ffffffffc009a1b5>] __cv_wait+0x15/0x20 [spl]
[23231.312988]  [<ffffffffc045ccb9>] txg_wait_synced+0xe9/0x130 [zfs]
[23231.313044]  [<ffffffffc049f05a>] zil_replay+0xca/0x100 [zfs]
[23231.313099]  [<ffffffffc048cb68>] zfs_sb_setup+0x158/0x170 [zfs]
[23231.313154]  [<ffffffffc048d7c7>] zfs_domount+0x2a7/0x330 [zfs]
[23231.313159]  [<ffffffff821f5ac0>] ? get_anon_bdev+0xf0/0xf0
[23231.313214]  [<ffffffffc04aa9a0>] ? zpl_kill_sb+0x20/0x20 [zfs]
[23231.313273]  [<ffffffffc04aa9cc>] zpl_fill_super+0x2c/0x40 [zfs]
[23231.313286]  [<ffffffff821f651d>] mount_nodev+0x4d/0xa0
[23231.313347]  [<ffffffffc04aae12>] zpl_mount+0x52/0x80 [zfs]
[23231.313354]  [<ffffffff821f6ff9>] mount_fs+0x39/0x160
[23231.313363]  [<ffffffff82211737>] vfs_kern_mount+0x67/0x110
[23231.313369]  [<ffffffff82213cc0>] do_mount+0x220/0xdd0
[23231.313374]  [<ffffffff821c20e8>] ? alloc_pages_current+0x88/0x120
[23231.313379]  [<ffffffff82179efe>] ? __get_free_pages+0xe/0x40
[23231.313382]  [<ffffffff82213976>] ? copy_mount_options+0x36/0x140
[23231.313385]  [<ffffffff82214b5b>] SyS_mount+0x8b/0xe0
[23231.313388]  [<ffffffff827bd3f6>] entry_SYSCALL_64_fastpath+0x16/0x75
[23411.398143] INFO: task txg_quiesce:29465 blocked for more than 180 seconds.
[23411.398848]       Tainted: P           OE   4.4.3-ssv-i7 #ssv
[23411.399439] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[23411.400253] txg_quiesce     D ffff8800b83b3d48     0 29465      2 0x00000000
[23411.400258]  ffff8800b83b3d48 ffffffff82c22500 ffff8800ba058000 ffff8800b83b4000
[23411.400261]  ffff880bdf3b0918 ffff880bdf3b09e8 ffff880bdf3b0940 0000000000000000
[23411.400264]  ffff8800b83b3d60 ffffffff827b9955 ffff880bdf3b09e0 ffff8800b83b3dc0
[23411.400267] Call Trace:
[23411.400276]  [<ffffffff827b9955>] schedule+0x35/0x80
[23411.400289]  [<ffffffffc009a16d>] cv_wait_common+0xed/0x120 [spl]
[23411.400294]  [<ffffffff820bc5f0>] ? prepare_to_wait_event+0xf0/0xf0
[23411.400303]  [<ffffffffc009a1b5>] __cv_wait+0x15/0x20 [spl]
[23411.400367]  [<ffffffffc045d21e>] txg_quiesce_thread+0x2ce/0x3e0 [zfs]
[23411.400419]  [<ffffffffc045cf50>] ? txg_delay+0x160/0x160 [zfs]
[23411.400427]  [<ffffffffc00952f1>] thread_generic_wrapper+0x71/0x80 [spl]
[23411.400435]  [<ffffffffc0095280>] ? __thread_exit+0x20/0x20 [spl]
[23411.400438]  [<ffffffff82096f69>] kthread+0xc9/0xe0
[23411.400441]  [<ffffffff82096ea0>] ? kthread_park+0x60/0x60
[23411.400444]  [<ffffffff827bd78f>] ret_from_fork+0x3f/0x70
[23411.400447]  [<ffffffff82096ea0>] ? kthread_park+0x60/0x60
[23411.400452] INFO: task mount.zfs:29611 blocked for more than 180 seconds.
[23411.401161]       Tainted: P           OE   4.4.3-ssv-i7 #ssv
[23411.419618] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[23411.457333] mount.zfs       D ffff8805e32dfbc8     0 29611  29610 0x00000002
[23411.457337]  ffff8805e32dfbc8 ffff880c23e74000 ffff8800be100000 ffff8805e32e0000
[23411.457340]  ffff880bf4b9b220 ffff880bf4b9b2e0 ffff880bf4b9b248 0000000000000000
[23411.457345]  ffff8805e32dfbe0 ffffffff827b9955 ffff880bf4b9b2d8 ffff8805e32dfc40
[23411.457349] Call Trace:
[23411.457356]  [<ffffffff827b9955>] schedule+0x35/0x80
[23411.457366]  [<ffffffffc009a16d>] cv_wait_common+0xed/0x120 [spl]
[23411.457370]  [<ffffffff820bc5f0>] ? prepare_to_wait_event+0xf0/0xf0
[23411.457379]  [<ffffffffc009a1b5>] __cv_wait+0x15/0x20 [spl]
[23411.457432]  [<ffffffffc045ccb9>] txg_wait_synced+0xe9/0x130 [zfs]
[23411.457487]  [<ffffffffc049f05a>] zil_replay+0xca/0x100 [zfs]
[23411.457543]  [<ffffffffc048cb68>] zfs_sb_setup+0x158/0x170 [zfs]
[23411.457598]  [<ffffffffc048d7c7>] zfs_domount+0x2a7/0x330 [zfs]
[23411.457602]  [<ffffffff821f5ac0>] ? get_anon_bdev+0xf0/0xf0
[23411.457657]  [<ffffffffc04aa9a0>] ? zpl_kill_sb+0x20/0x20 [zfs]
[23411.457713]  [<ffffffffc04aa9cc>] zpl_fill_super+0x2c/0x40 [zfs]
[23411.457716]  [<ffffffff821f651d>] mount_nodev+0x4d/0xa0
[23411.457772]  [<ffffffffc04aae12>] zpl_mount+0x52/0x80 [zfs]
[23411.457775]  [<ffffffff821f6ff9>] mount_fs+0x39/0x160
[23411.457780]  [<ffffffff82211737>] vfs_kern_mount+0x67/0x110
[23411.457784]  [<ffffffff82213cc0>] do_mount+0x220/0xdd0
[23411.457789]  [<ffffffff821c20e8>] ? alloc_pages_current+0x88/0x120
[23411.457793]  [<ffffffff82179efe>] ? __get_free_pages+0xe/0x40
[23411.457796]  [<ffffffff82213976>] ? copy_mount_options+0x36/0x140
[23411.457800]  [<ffffffff82214b5b>] SyS_mount+0x8b/0xe0
[23411.457803]  [<ffffffff827bd3f6>] entry_SYSCALL_64_fastpath+0x16/0x75
[23591.541839] INFO: task txg_quiesce:29465 blocked for more than 180 seconds.
[23591.561287]       Tainted: P           OE   4.4.3-ssv-i7 #ssv
[23591.580486] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[23591.618601] txg_quiesce     D ffff8800b83b3d48     0 29465      2 0x00000000
[23591.618606]  ffff8800b83b3d48 ffffffff82c22500 ffff8800ba058000 ffff8800b83b4000
[23591.618610]  ffff880bdf3b0918 ffff880bdf3b09e8 ffff880bdf3b0940 0000000000000000
[23591.618612]  ffff8800b83b3d60 ffffffff827b9955 ffff880bdf3b09e0 ffff8800b83b3dc0
[23591.618615] Call Trace:
[23591.618624]  [<ffffffff827b9955>] schedule+0x35/0x80
[23591.618637]  [<ffffffffc009a16d>] cv_wait_common+0xed/0x120 [spl]
[23591.618643]  [<ffffffff820bc5f0>] ? prepare_to_wait_event+0xf0/0xf0
[23591.618655]  [<ffffffffc009a1b5>] __cv_wait+0x15/0x20 [spl]
[23591.618735]  [<ffffffffc045d21e>] txg_quiesce_thread+0x2ce/0x3e0 [zfs]
[23591.618790]  [<ffffffffc045cf50>] ? txg_delay+0x160/0x160 [zfs]
[23591.618801]  [<ffffffffc00952f1>] thread_generic_wrapper+0x71/0x80 [spl]
[23591.618810]  [<ffffffffc0095280>] ? __thread_exit+0x20/0x20 [spl]
[23591.618814]  [<ffffffff82096f69>] kthread+0xc9/0xe0
[23591.618817]  [<ffffffff82096ea0>] ? kthread_park+0x60/0x60
[23591.618820]  [<ffffffff827bd78f>] ret_from_fork+0x3f/0x70
[23591.618822]  [<ffffffff82096ea0>] ? kthread_park+0x60/0x60
[23591.618828] INFO: task mount.zfs:29611 blocked for more than 180 seconds.
[23591.638089]       Tainted: P           OE   4.4.3-ssv-i7 #ssv
[23591.657257] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[23591.695309] mount.zfs       D ffff8805e32dfbc8     0 29611  29610 0x00000002
[23591.695313]  ffff8805e32dfbc8 ffff880c23e74000 ffff8800be100000 ffff8805e32e0000
[23591.695316]  ffff880bf4b9b220 ffff880bf4b9b2e0 ffff880bf4b9b248 0000000000000000
[23591.695319]  ffff8805e32dfbe0 ffffffff827b9955 ffff880bf4b9b2d8 ffff8805e32dfc40
[23591.695322] Call Trace:
[23591.695326]  [<ffffffff827b9955>] schedule+0x35/0x80
[23591.695336]  [<ffffffffc009a16d>] cv_wait_common+0xed/0x120 [spl]
[23591.695340]  [<ffffffff820bc5f0>] ? prepare_to_wait_event+0xf0/0xf0
[23591.695349]  [<ffffffffc009a1b5>] __cv_wait+0x15/0x20 [spl]
[23591.695401]  [<ffffffffc045ccb9>] txg_wait_synced+0xe9/0x130 [zfs]
[23591.695457]  [<ffffffffc049f05a>] zil_replay+0xca/0x100 [zfs]
[23591.695512]  [<ffffffffc048cb68>] zfs_sb_setup+0x158/0x170 [zfs]
[23591.695567]  [<ffffffffc048d7c7>] zfs_domount+0x2a7/0x330 [zfs]
[23591.695571]  [<ffffffff821f5ac0>] ? get_anon_bdev+0xf0/0xf0
[23591.695627]  [<ffffffffc04aa9a0>] ? zpl_kill_sb+0x20/0x20 [zfs]
[23591.695682]  [<ffffffffc04aa9cc>] zpl_fill_super+0x2c/0x40 [zfs]
[23591.695700]  [<ffffffff821f651d>] mount_nodev+0x4d/0xa0
[23591.695761]  [<ffffffffc04aae12>] zpl_mount+0x52/0x80 [zfs]
[23591.695769]  [<ffffffff821f6ff9>] mount_fs+0x39/0x160
[23591.695777]  [<ffffffff82211737>] vfs_kern_mount+0x67/0x110
[23591.695783]  [<ffffffff82213cc0>] do_mount+0x220/0xdd0
[23591.695788]  [<ffffffff821c20e8>] ? alloc_pages_current+0x88/0x120
[23591.695793]  [<ffffffff82179efe>] ? __get_free_pages+0xe/0x40
[23591.695796]  [<ffffffff82213976>] ? copy_mount_options+0x36/0x140
[23591.695799]  [<ffffffff82214b5b>] SyS_mount+0x8b/0xe0
[23591.695802]  [<ffffffff827bd3f6>] entry_SYSCALL_64_fastpath+0x16/0x75
[23771.780584] INFO: task txg_quiesce:29465 blocked for more than 180 seconds.
[23771.799927]       Tainted: P           OE   4.4.3-ssv-i7 #ssv
[23771.819108] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[23771.857347] txg_quiesce     D ffff8800b83b3d48     0 29465      2 0x00000000
[23771.857353]  ffff8800b83b3d48 ffffffff82c22500 ffff8800ba058000 ffff8800b83b4000
[23771.857356]  ffff880bdf3b0918 ffff880bdf3b09e8 ffff880bdf3b0940 0000000000000000
[23771.857358]  ffff8800b83b3d60 ffffffff827b9955 ffff880bdf3b09e0 ffff8800b83b3dc0
[23771.857361] Call Trace:
[23771.857370]  [<ffffffff827b9955>] schedule+0x35/0x80
[23771.857383]  [<ffffffffc009a16d>] cv_wait_common+0xed/0x120 [spl]
[23771.857388]  [<ffffffff820bc5f0>] ? prepare_to_wait_event+0xf0/0xf0
[23771.857409]  [<ffffffffc009a1b5>] __cv_wait+0x15/0x20 [spl]
[23771.857478]  [<ffffffffc045d21e>] txg_quiesce_thread+0x2ce/0x3e0 [zfs]
[23771.857528]  [<ffffffffc045cf50>] ? txg_delay+0x160/0x160 [zfs]
[23771.857536]  [<ffffffffc00952f1>] thread_generic_wrapper+0x71/0x80 [spl]
[23771.857543]  [<ffffffffc0095280>] ? __thread_exit+0x20/0x20 [spl]
[23771.857546]  [<ffffffff82096f69>] kthread+0xc9/0xe0
[23771.857548]  [<ffffffff82096ea0>] ? kthread_park+0x60/0x60
[23771.857552]  [<ffffffff827bd78f>] ret_from_fork+0x3f/0x70
[23771.857554]  [<ffffffff82096ea0>] ? kthread_park+0x60/0x60

Last time i ran into this, i was able to install upstream ZFS (without ABD) and it replayed the ZIL over ~4 hours or so. This was after several import attempts, so not sure if the upstream version had anything to do with success or that the pool was just able to replay enough data to work again.

sempervictus commented 8 years ago

@dweeezil: All of these bugs seem to end up in cv_wait_common to schedule, directly after which cv_wait_common has this pleasant commented snippet in it. If i'm reading the stack trace correctly, schedule doesn't return, but we've already dropped the mutex (mp), and can potentially have the race condition start during the evaluation of the conditional after line 105 (if there are other threads contending for the same resources). Any validity to this or am i looking down the wrong rabbit hole?

105         mutex_exit(mp);
106         if (io)
107                 io_schedule();
108         else
109                 schedule();
110 
111         /* No more waiters a different mutex could be used */
112         if (atomic_dec_and_test(&cvp->cv_waiters)) {
113                 /*
114                  * This is set without any lock, so it's racy. But this is
115                  * just for debug anyway, so make it best-effort
116                  */
117                 cvp->cv_mutex = NULL;
118                 wake_up(&cvp->cv_destroy);
119         }

Any chance that the "racy condition" is in play here? I believe i saw the actual wake_up ca