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

'zfs list' takes unreasonable long time #4773

Closed
mailinglists35 opened this issue Jun 18, 2016 · 12 comments
Closed

'zfs list' takes unreasonable long time #4773

mailinglists35 opened this issue Jun 18, 2016 · 12 comments
Labels
Type: Performance Performance improvement or performance problem

Comments

@mailinglists35
Copy link

mailinglists35 commented Jun 18, 2016

0.6.5.7
mount -t tmpfs -o size=1G tmpfs /mnt/test/
truncate -s 1GiB /mnt/test/deleteme
zpool create -O mountpoint=none deleteme /mnt/test/deleteme
for i inseq 1 10000; do echo zfs create deleteme/$i; done > /tmp/a; time bash /tmp/a
real 1m41.512s
user 0m10.684s
sys 0m31.452s

time perf record -a zfs list > /dev/null 2>&1
real 0m17.519s
user 0m0.736s
sys 0m16.716s

stack.txt dump during zfs list
perf.data.zip from perf record

free -m

             total       used       free     shared    buffers     cached
Mem:          3875       2460       1414         19        158        494
-/+ buffers/cache:       1806       2068
Swap:         3813          0       3813
@mailinglists35
Copy link
Author

'perf report' if anyone's too lazy to process the perf.data file

Samples: 130K of event 'cycles:p', Event count (approx.): 88000955436
Overhead  Command          Shared Object            Symbol
  33.01%  swapper          [kernel.kallsyms]        [k] poll_idle
   5.93%  swapper          [kernel.kallsyms]        [k] read_hpet
   4.55%  zfs              [kernel.kallsyms]        [k] strlen
   3.18%  zfs              [kernel.kallsyms]        [k] mutex_lock
   2.46%  zfs              [kernel.kallsyms]        [k] __memset
   2.43%  zfs              [kernel.kallsyms]        [k] _raw_spin_lock
   2.14%  zfs              [kernel.kallsyms]        [k] mutex_unlock
   1.87%  zfs              [kernel.kallsyms]        [k] _raw_spin_lock_irqsave
   1.83%  zfs              [kernel.kallsyms]        [k] zprop_name_to_prop_cb
   1.40%  zfs              [kernel.kallsyms]        [k] dmu_zfetch
   1.09%  zfs              [kernel.kallsyms]        [k] kmem_cache_alloc_node_tr
   1.04%  zfs              [kernel.kallsyms]        [k] kfree
   0.89%  zfs              [kernel.kallsyms]        [k] __dbuf_hold_impl
   0.85%  zfs              [kernel.kallsyms]        [k] down_read
   0.83%  zfs              [kernel.kallsyms]        [k] dbuf_read
   0.81%  zfs              [kernel.kallsyms]        [k] arc_state_multilist_inde
   0.79%  zfs              [kernel.kallsyms]        [k] zprop_iter_common
   0.73%  zfs              [kernel.kallsyms]        [k] dbuf_rele_and_unlock
   0.71%  zfs              [kernel.kallsyms]        [k] _raw_spin_unlock_irqrest
   0.70%  zfs              [kernel.kallsyms]        [k] arc_buf_add_ref
   0.69%  zfs              [kernel.kallsyms]        [k] dbuf_find
   0.67%  zfs              [kernel.kallsyms]        [k] arc_buf_remove_ref
   0.66%  zfs              [kernel.kallsyms]        [k] zrl_add
   0.64%  zfs              [kernel.kallsyms]        [k] zio_create
   0.57%  zfs              [kernel.kallsyms]        [k] dnode_hold_impl
   0.56%  zfs              [kernel.kallsyms]        [k] LZ4_uncompress_unknownOu
   0.51%  zfs              [kernel.kallsyms]        [k] up_read
   0.50%  zfs              [kernel.kallsyms]        [k] kmem_cache_alloc
   0.43%  zfs              [kernel.kallsyms]        [k] _cond_resched
   0.40%  zfs              [kernel.kallsyms]        [k] dbuf_hash
   0.38%  zfs              [kernel.kallsyms]        [k] kmem_cache_free
   0.36%  zfs              [kernel.kallsyms]        [k] zap_lockdir
   0.36%  zfs              [kernel.kallsyms]        [k] zap_hash
   0.36%  zfs              [kernel.kallsyms]        [k] zio_wait_for_children
   0.34%  zfs              [kernel.kallsyms]        [k] spl_kmem_cache_alloc
   0.33%  zfs              libc-2.19.so             [.] strlen
   0.32%  zfs              [kernel.kallsyms]        [k] zrl_remove
   0.32%  dbu_evict        [kernel.kallsyms]        [k] _raw_spin_lock_irqsave
   0.29%  zfs              [kernel.kallsyms]        [k] zio_done
   0.27%  zfs              [kernel.kallsyms]        [k] arc_space_return
   0.26%  zfs              [kernel.kallsyms]        [k] arc_space_consume
   0.26%  zfs              [kernel.kallsyms]        [k] spl_kmem_zalloc
   0.25%  zfs              [kernel.kallsyms]        [k] enqueue_entity
   0.25%  zfs              [kernel.kallsyms]        [k] dbuf_create
   0.24%  zfs              [kernel.kallsyms]        [k] add_reference.isra.12
   0.24%  zfs              [kernel.kallsyms]        [k] dnode_rele_and_unlock
   0.24%  zfs              [kernel.kallsyms]        [k] remove_reference.isra.15
   0.24%  zfs              [kernel.kallsyms]        [k] arc_read
   0.20%  zfs              [kernel.kallsyms]        [k] spl_kmem_alloc
   0.20%  swapper          [kernel.kallsyms]        [k] menu_select
   0.20%  zfs              [kernel.kallsyms]        [k] copy_user_generic_string
Tip: To record every process run by an user: perf record -u <user>

@mailinglists35
Copy link
Author

Jun 18 04:11:40 homerouter kernel: [ 1708.095018] sysrq: SysRq : Show State
Jun 18 04:11:40 homerouter kernel: [ 1708.095076] task PC stack pid father
Jun 18 04:11:40 homerouter kernel: [ 1708.095120] systemd S 0000000000000000 0 1 0 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.095196] ffff880116b64cc0 ffff8800d8658e00 ffff880116b6c000 ffff880116b6bf10
Jun 18 04:11:40 homerouter kernel: [ 1708.095318] ffff880036c02e20 0000000000000000 ffff880116b64cc0 00007fff30e26d40
Jun 18 04:11:40 homerouter kernel: [ 1708.095440] ffffffff815b4fa1 ffff880036c02dc0 ffffffff815b8283 0000000000000019
Jun 18 04:11:40 homerouter kernel: [ 1708.095563] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.095603] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.095645] [] ? schedule_hrtimeout_range_clock+0x183/0x1a0
Jun 18 04:11:40 homerouter kernel: [ 1708.095701] [] ? ep_ptable_queue_proc+0x90/0x90
Jun 18 04:11:40 homerouter kernel: [ 1708.095743] [] ? ep_scan_ready_list+0x204/0x210
Jun 18 04:11:40 homerouter kernel: [ 1708.095784] [] ? ep_poll+0x287/0x340
Jun 18 04:11:40 homerouter kernel: [ 1708.095824] [] ? wake_up_q+0x60/0x60
Jun 18 04:11:40 homerouter kernel: [ 1708.095865] [] ? SyS_epoll_wait+0xb0/0xd0
Jun 18 04:11:40 homerouter kernel: [ 1708.095906] [] ? system_call_fast_compare_end+0xc/0x67
Jun 18 04:11:40 homerouter kernel: [ 1708.095948] kthreadd S 0000000000000000 0 2 0 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.237943] [] ? taskq_thread+0x3aa/0x3f0 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.237944] [] ? wake_up_q+0x60/0x60
Jun 18 04:11:40 homerouter kernel: [ 1708.237949] [] ? taskq_cancel_id+0x130/0x130 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.237950] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.237952] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.237953] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.237955] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.237957] z_fr_iss_7 S 0000000000000000 0 6060 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.237958] ffff880112436e40 ffff880115489140 ffff880112440000
Jun 18 04:11:40 homerouter kernel: [ 1708.237959] ffff8800ce963f90
Jun 18 04:11:40 homerouter kernel: [ 1708.237960] ffff8800ce963fb0 ffff880112436e40 ffff8800d3bea890 ffff8800ce963f00
Jun 18 04:11:40 homerouter kernel: [ 1708.237962] ffffffff815b4fa1 ffff880115431840 ffffffffc03a2f5a ffff8800d3bea820
Jun 18 04:11:40 homerouter kernel: [ 1708.237962] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.237963] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.237968] [] ? taskq_thread+0x3aa/0x3f0 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.237969] [] ? wake_up_q+0x60/0x60
Jun 18 04:11:40 homerouter kernel: [ 1708.237974] [] ? taskq_cancel_id+0x130/0x130 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.237976] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.237977] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.237978] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.237980] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.237982] z_fr_iss_7 S 0000000000000001 0 6061 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.237984] ffff8801124361c0 ffff880115495180 ffff880112444000 ffff8800ce963f90
Jun 18 04:11:40 homerouter kernel: [ 1708.237986] ffff8800ce963fb0 ffff8801124361c0 ffff8800cdaa3a90 ffff8800ce963f00
Jun 18 04:11:40 homerouter kernel: [ 1708.237987] ffffffff815b4fa1 ffff8801154317c0 ffffffffc03a2f5a
Jun 18 04:11:40 homerouter kernel: [ 1708.237988] ffff8800cdaa3a20
Jun 18 04:11:40 homerouter kernel: [ 1708.237988] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.237989] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.237994] [] ? taskq_thread+0x3aa/0x3f0 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.237995] [] ? wake_up_q+0x60/0x60
Jun 18 04:11:40 homerouter kernel: [ 1708.238000] [] ? taskq_cancel_id+0x130/0x130 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238001] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238003] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238004] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238006] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238008] z_fr_iss_7 S 0000000000000000 0 6062 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238009] ffff880112448e80 ffff8800d835a480 ffff880112450000
Jun 18 04:11:40 homerouter kernel: [ 1708.238010] ffff8800ce963f90
Jun 18 04:11:40 homerouter kernel: [ 1708.238011] ffff8800ce963fb0 ffff880112448e80 ffff8800cd515f30 ffff8800ce963f00
Jun 18 04:11:40 homerouter kernel: [ 1708.238013] ffffffff815b4fa1 ffff880115431740 ffffffffc03a2f5a ffff8800cd515ec0
Jun 18 04:11:40 homerouter kernel: [ 1708.238013] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238015] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238019] [] ? taskq_thread+0x3aa/0x3f0 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238020] [] ? wake_up_q+0x60/0x60
Jun 18 04:11:40 homerouter kernel: [ 1708.238025] [] ? taskq_cancel_id+0x130/0x130 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238027] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238028] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238029] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238031] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238033] z_fr_iss_7 S 0000000000000000 0 6063 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238034] ffff880112448200 ffff8800d835a480 ffff880112454000 ffff8800ce963f90
Jun 18 04:11:40 homerouter kernel: [ 1708.238036] ffff8800ce963fb0 ffff880112448200 ffff88006db7fa90 ffff8800ce963f00
Jun 18 04:11:40 homerouter kernel: [ 1708.238037] ffffffff815b4fa1 ffff8801154316c0 ffffffffc03a2f5a ffff88006db7fa20
Jun 18 04:11:40 homerouter kernel: [ 1708.238037] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238039] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238043] [] ? taskq_thread+0x3aa/0x3f0 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238045] [] ? wake_up_q+0x60/0x60
Jun 18 04:11:40 homerouter kernel: [ 1708.238049] [] ? taskq_cancel_id+0x130/0x130 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238051] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238052] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238054] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238055] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238058] z_fr_iss_7 S ffff88011bc95980 0 6064 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238059] ffff88011244aec0 ffff880116452e00 ffff880112458000
Jun 18 04:11:40 homerouter kernel: [ 1708.238060] ffff8800ce963f90
Jun 18 04:11:40 homerouter kernel: [ 1708.238061] ffff8800ce963fb0 ffff88011244aec0 ffff8800af46d5b0 ffff8800ce963f00
Jun 18 04:11:40 homerouter kernel: [ 1708.238062] ffffffff815b4fa1 ffff880115431640 ffffffffc03a2f5a ffff8800af46d540
Jun 18 04:11:40 homerouter kernel: [ 1708.238063] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238064] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238069] [] ? taskq_thread+0x3aa/0x3f0 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238070] [] ? wake_up_q+0x60/0x60
Jun 18 04:11:40 homerouter kernel: [ 1708.238074] [] ? taskq_cancel_id+0x130/0x130 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238076] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238078] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238079] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238080] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238083] z_fr_int S ffff88011bc95980 0 6065 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238084] ffff8801124060c0 ffff880116452e00 ffff880112460000 ffff8800d0a64090
Jun 18 04:11:40 homerouter kernel: [ 1708.238086] ffff8800d0a640b0 ffff8801124060c0 0000000000000000 ffff8800d0a64000
Jun 18 04:11:40 homerouter kernel: [ 1708.238087] ffffffff815b4fa1 ffff8801154315c0
Jun 18 04:11:40 homerouter kernel: [ 1708.238088] ffffffffc03a2f5a 0000000000015980
Jun 18 04:11:40 homerouter kernel: [ 1708.238088] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238089] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238094] [] ? taskq_thread+0x3aa/0x3f0 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238095] [] ? wake_up_q+0x60/0x60
Jun 18 04:11:40 homerouter kernel: [ 1708.238100] [] ? taskq_cancel_id+0x130/0x130 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238101] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238103] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238106] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238108] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238110] z_cl_iss S ffff88011bc95980 0 6066 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238112] ffff88011245af00 ffff880116452e00 ffff880112464000
Jun 18 04:11:40 homerouter kernel: [ 1708.238112] ffff8800d0a64690
Jun 18 04:11:40 homerouter kernel: [ 1708.238114] ffff8800d0a646b0 ffff88011245af00 0000000000000000 ffff8800d0a64600
Jun 18 04:11:40 homerouter kernel: [ 1708.238115] ffffffff815b4fa1 ffff880115431540 ffffffffc03a2f5a 0000000000015980
Jun 18 04:11:40 homerouter kernel: [ 1708.238115] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238117] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238121] [] ? taskq_thread+0x3aa/0x3f0 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238123] [] ? wake_up_q+0x60/0x60
Jun 18 04:11:40 homerouter kernel: [ 1708.238127] [] ? taskq_cancel_id+0x130/0x130 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238129] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238130] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238132] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238133] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238135] z_cl_int S ffff88011bc95980 0 6067 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238137] ffff88011245a280 ffff880116452e00 ffff880112468000 ffff8800ce9ed690
Jun 18 04:11:40 homerouter kernel: [ 1708.238138] ffff8800ce9ed6b0 ffff88011245a280 0000000000000000 ffff8800ce9ed600
Jun 18 04:11:40 homerouter kernel: [ 1708.238139] ffffffff815b4fa1 ffff8801154314c0 ffffffffc03a2f5a
Jun 18 04:11:40 homerouter kernel: [ 1708.238140] 0000000000015980
Jun 18 04:11:40 homerouter kernel: [ 1708.238140] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238142] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238146] [] ? taskq_thread+0x3aa/0x3f0 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238148] [] ? wake_up_q+0x60/0x60
Jun 18 04:11:40 homerouter kernel: [ 1708.238152] [] ? taskq_cancel_id+0x130/0x130 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238154] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238155] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238156] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238158] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238160] z_ioctl_iss S 0000000000000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238161] 0 6068 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238162] ffff88011246af40 ffff8800cdacce40 ffff880112470000 ffff8800d0b1c590
Jun 18 04:11:40 homerouter kernel: [ 1708.238163] ffff8800d0b1c5b0 ffff88011246af40 ffff88009ccaad30 ffff8800d0b1c500
Jun 18 04:11:40 homerouter kernel: [ 1708.238165] ffffffff815b4fa1 ffff880115431440 ffffffffc03a2f5a ffff88009ccaacc0
Jun 18 04:11:40 homerouter kernel: [ 1708.238165] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238167] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238171] [] ? taskq_thread+0x3aa/0x3f0 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238172] [] ? wake_up_q+0x60/0x60
Jun 18 04:11:40 homerouter kernel: [ 1708.238177] [] ? taskq_cancel_id+0x130/0x130 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238178] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238180] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238181] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238183] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238185] z_ioctl_int S ffff88011bc15980 0 6069 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238187] ffff88011246a2c0 ffffffff81a12500 ffff880112474000 ffff8800d090de90
Jun 18 04:11:40 homerouter kernel: [ 1708.238188] ffff8800d090deb0 ffff88011246a2c0 ffff88009ccaad30 ffff8800d090de00
Jun 18 04:11:40 homerouter kernel: [ 1708.238189] ffffffff815b4fa1
Jun 18 04:11:40 homerouter kernel: [ 1708.238190] ffff8801154313c0 ffffffffc03a2f5a ffff88009ccaacc0
Jun 18 04:11:40 homerouter kernel: [ 1708.238190] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238192] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238196] [] ? taskq_thread+0x3aa/0x3f0 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238198] [] ? wake_up_q+0x60/0x60
Jun 18 04:11:40 homerouter kernel: [ 1708.238202] [] ? taskq_cancel_id+0x130/0x130 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238204] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238205] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238207] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238208] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238210] z_zvol S 0000000000000001 0 6070 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238212] ffff880112476f80 ffff8800cdacce40 ffff88011247c000 ffff8800d6e1d490
Jun 18 04:11:40 homerouter kernel: [ 1708.238213] ffff8800d6e1d4b0 ffff880112476f80 ffff88003642f0b0 ffff8800d6e1d400
Jun 18 04:11:40 homerouter kernel: [ 1708.238214] ffffffff815b4fa1 ffff880115431340 ffffffffc03a2f5a ffff88003642f040
Jun 18 04:11:40 homerouter kernel: [ 1708.238215] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238216] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238221] [] ? taskq_thread+0x3aa/0x3f0 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238222] [] ? wake_up_q+0x60/0x60
Jun 18 04:11:40 homerouter kernel: [ 1708.238226] [] ? taskq_cancel_id+0x130/0x130 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238228] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238230] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238231] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238232] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238235] metaslab_group_ S ffff88011bc15980 0 6071 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238236] ffff880112476300 ffffffff81a12500 ffff880112484000 ffff8800ce9ed090
Jun 18 04:11:40 homerouter kernel: [ 1708.238237] ffff8800ce9ed0b0 ffff880112476300 ffff8800ce9d1fb0 ffff8800ce9ed000
Jun 18 04:11:40 homerouter kernel: [ 1708.238239] ffffffff815b4fa1 ffff8801154312c0 ffffffffc03a2f5a
Jun 18 04:11:40 homerouter kernel: [ 1708.238239] ffff8800ce9d1f40
Jun 18 04:11:40 homerouter kernel: [ 1708.238240] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238241] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238246] [] ? taskq_thread+0x3aa/0x3f0 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238247] [] ? wake_up_q+0x60/0x60
Jun 18 04:11:40 homerouter kernel: [ 1708.238251] [] ? taskq_cancel_id+0x130/0x130 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238253] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238254] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238256] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238258] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238260] z_iput S ffff88011bc95980 0 6075 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238261] ffff8800b5dad000 ffff880116452e00 ffff8800b5db4000
Jun 18 04:11:40 homerouter kernel: [ 1708.238262] ffff8800d3bc4190
Jun 18 04:11:40 homerouter kernel: [ 1708.238263] ffff8800d3bc41b0 ffff8800b5dad000 0000000000000000 ffff8800d3bc4100
Jun 18 04:11:40 homerouter kernel: [ 1708.238265] ffffffff815b4fa1 ffff8801154310c0 ffffffffc03a2f5a 0000000000015980
Jun 18 04:11:40 homerouter kernel: [ 1708.238265] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238266] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238271] [] ? taskq_thread+0x3aa/0x3f0 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238272] [] ? wake_up_q+0x60/0x60
Jun 18 04:11:40 homerouter kernel: [ 1708.238277] [] ? taskq_cancel_id+0x130/0x130 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238278] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238280] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238281] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238283] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238285] z_iput S ffff88011bc15980 0 6076 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238286] ffff8800b5dac380 ffffffff81a12500 ffff8800b5db8000 ffff8800d3bc4190
Jun 18 04:11:40 homerouter kernel: [ 1708.238288] ffff8800d3bc41b0 ffff8800b5dac380 0000000000000000 ffff8800d3bc4100
Jun 18 04:11:40 homerouter kernel: [ 1708.238289] ffffffff815b4fa1 ffff880115431140 ffffffffc03a2f5a
Jun 18 04:11:40 homerouter kernel: [ 1708.238290] 0000000000015980
Jun 18 04:11:40 homerouter kernel: [ 1708.238290] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238292] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238296] [] ? taskq_thread+0x3aa/0x3f0 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238297] [] ? wake_up_q+0x60/0x60
Jun 18 04:11:40 homerouter kernel: [ 1708.238302] [] ? taskq_cancel_id+0x130/0x130 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238303] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238305] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238306] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238308] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238310] z_iput S ffff88011bc95980 0 6077 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238311] ffff8800b5daf040 ffff880116452e00 ffff8800b5dbc000
Jun 18 04:11:40 homerouter kernel: [ 1708.238312] ffff8800d3bc4190
Jun 18 04:11:40 homerouter kernel: [ 1708.238313] ffff8800d3bc41b0 ffff8800b5daf040 0000000000000000 ffff8800d3bc4100
Jun 18 04:11:40 homerouter kernel: [ 1708.238315] ffffffff815b4fa1 ffff880115e734c0 ffffffffc03a2f5a 0000000000015980
Jun 18 04:11:40 homerouter kernel: [ 1708.238315] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238317] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238321] [] ? taskq_thread+0x3aa/0x3f0 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238322] [] ? wake_up_q+0x60/0x60
Jun 18 04:11:40 homerouter kernel: [ 1708.238327] [] ? taskq_cancel_id+0x130/0x130 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238328] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238330] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238331] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238333] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238336] z_iput S ffff88011bc15980 0 6078 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238337] ffff8800b5dae3c0 ffffffff81a12500 ffff8800b6184000 ffff8800d3bc4190
Jun 18 04:11:40 homerouter kernel: [ 1708.238339] ffff8800d3bc41b0 ffff8800b5dae3c0 0000000000000000 ffff8800d3bc4100
Jun 18 04:11:40 homerouter kernel: [ 1708.238340] ffffffff815b4fa1 ffff880115e73540 ffffffffc03a2f5a 0000000000015980
Jun 18 04:11:40 homerouter kernel: [ 1708.238340] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238342] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238346] [] ? taskq_thread+0x3aa/0x3f0 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238348] [] ? wake_up_q+0x60/0x60
Jun 18 04:11:40 homerouter kernel: [ 1708.238352] [] ? taskq_cancel_id+0x130/0x130 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238356] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238358] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238359] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238360] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238363] txg_quiesce S 0000000000000001 0 6079 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238364] ffff8800b61a9080 ffff8800b61a8400 ffff8800b61b0000 ffff8800d8320a20
Jun 18 04:11:40 homerouter kernel: [ 1708.238365] ffff8800d8320a48 ffff8800d8320b28 0000000000000000 ffff8800d8320800
Jun 18 04:11:40 homerouter kernel: [ 1708.238366] ffffffff815b4fa1 ffff8800d8320b20
Jun 18 04:11:40 homerouter kernel: [ 1708.238367] ffffffffc03a66d2 0000000000000001
Jun 18 04:11:40 homerouter kernel: [ 1708.238368] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238369] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238374] [] ? cv_wait_common+0x102/0x140 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238376] [] ? wake_atomic_t_function+0x60/0x60
Jun 18 04:11:40 homerouter kernel: [ 1708.238411] [] ? txg_quiesce_thread+0x3d5/0x3e0 [zfs]
Jun 18 04:11:40 homerouter kernel: [ 1708.238445] [] ? txg_do_callbacks+0x30/0x30 [zfs]
Jun 18 04:11:40 homerouter kernel: [ 1708.238449] [] ? thread_generic_wrapper+0x6c/0x80 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238453] [] ? __thread_exit+0x20/0x20 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238455] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238456] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238458] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238459] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238462] txg_sync S 0000000000000001 0 6080 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238464] ffff8800b61a8400 ffff8800d8658e00 ffff8800b61b4000
Jun 18 04:11:40 homerouter kernel: [ 1708.238464] ffff8800b61b3d58
Jun 18 04:11:40 homerouter kernel: [ 1708.238465] ffff8800b61b3cd0 ffff88011bc8dd80 ffff88011bc8dd80 ffff8800d8320800
Jun 18 04:11:40 homerouter kernel: [ 1708.238467] ffffffff815b4fa1 000000010005602b ffffffff815b7d89 ffffffffc04b1f1c
Jun 18 04:11:40 homerouter kernel: [ 1708.238467] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238469] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238470] [] ? schedule_timeout+0x129/0x270
Jun 18 04:11:40 homerouter kernel: [ 1708.238503] [] ? spa_config_exit+0x7c/0xc0 [zfs]
Jun 18 04:11:40 homerouter kernel: [ 1708.238504] [] ? trace_event_raw_event_tick_stop+0x100/0x100
Jun 18 04:11:40 homerouter kernel: [ 1708.238510] [] ? __cv_timedwait_common+0xbf/0x160 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238512] [] ? wake_atomic_t_function+0x60/0x60
Jun 18 04:11:40 homerouter kernel: [ 1708.238545] [] ? txg_sync_thread+0x1c5/0x640 [zfs]
Jun 18 04:11:40 homerouter kernel: [ 1708.238546] [] ? __switch_to+0x1bf/0x590
Jun 18 04:11:40 homerouter kernel: [ 1708.238579] [] ? txg_delay+0x180/0x180 [zfs]
Jun 18 04:11:40 homerouter kernel: [ 1708.238583] [] ? thread_generic_wrapper+0x6c/0x80 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238588] [] ? __thread_exit+0x20/0x20 [spl]
Jun 18 04:11:40 homerouter kernel: [ 1708.238589] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238591] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238592] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238594] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238596] sshd R running task 0 7345 2563 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238597] ffff8800b631c4c0 ffff8800d317e140 ffff8800a69cc000
Jun 18 04:11:40 homerouter kernel: [ 1708.238598] ffff8800a69cbd58
Jun 18 04:11:40 homerouter kernel: [ 1708.238599] 0000000000000040 000000000000000f 000000000000000f 000000000000000f
Jun 18 04:11:40 homerouter kernel: [ 1708.238601] ffffffff815b4fa1 ffff8800a69cbab0 ffffffff815b8283 ffffffff815b840a
Jun 18 04:11:40 homerouter kernel: [ 1708.238601] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238603] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238606] [] ? schedule_hrtimeout_range_clock+0x183/0x1a0
Jun 18 04:11:40 homerouter kernel: [ 1708.238607] [] ? ldsem_down_read+0x3a/0x230
Jun 18 04:11:40 homerouter kernel: [ 1708.238609] [] ? add_wait_queue+0x2b/0x40
Jun 18 04:11:40 homerouter kernel: [ 1708.238610] [] ? n_tty_poll+0x183/0x1a0
Jun 18 04:11:40 homerouter kernel: [ 1708.238612] [] ? poll_schedule_timeout+0x40/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238613] [] ? do_select+0x727/0x810
Jun 18 04:11:40 homerouter kernel: [ 1708.238616] [] ? poll_select_copy_remaining+0x150/0x150
Jun 18 04:11:40 homerouter kernel: [ 1708.238617] [] ? poll_select_copy_remaining+0x150/0x150
Jun 18 04:11:40 homerouter kernel: [ 1708.238619] [] ? poll_select_copy_remaining+0x150/0x150
Jun 18 04:11:40 homerouter kernel: [ 1708.238620] [] ? poll_select_copy_remaining+0x150/0x150
Jun 18 04:11:40 homerouter kernel: [ 1708.238622] [] ? poll_select_copy_remaining+0x150/0x150
Jun 18 04:11:40 homerouter kernel: [ 1708.238623] [] ? poll_select_copy_remaining+0x150/0x150
Jun 18 04:11:40 homerouter kernel: [ 1708.238625] [] ? __intel_pmu_enable_all+0x47/0xa0
Jun 18 04:11:40 homerouter kernel: [ 1708.238626] [] ? intel_pmu_handle_irq+0x2bf/0x4a0
Jun 18 04:11:40 homerouter kernel: [ 1708.238628] [] ? sk_reset_timer+0x14/0x30
Jun 18 04:11:40 homerouter kernel: [ 1708.238629] [] ? check_preempt_wakeup+0xe6/0x1f0
Jun 18 04:11:40 homerouter kernel: [ 1708.238630] [] ? check_preempt_curr+0x7b/0x90
Jun 18 04:11:40 homerouter kernel: [ 1708.238632] [] ? core_sys_select+0x19b/0x2a0
Jun 18 04:11:40 homerouter kernel: [ 1708.238634] [] ? n_tty_write+0x290/0x4f0
Jun 18 04:11:40 homerouter kernel: [ 1708.238635] [] ? __wake_up+0x34/0x50
Jun 18 04:11:40 homerouter kernel: [ 1708.238636] [] ? tty_write+0x211/0x2c0
Jun 18 04:11:40 homerouter kernel: [ 1708.238637] [] ? n_tty_open+0xd0/0xd0
Jun 18 04:11:40 homerouter kernel: [ 1708.238639] [] ? SyS_select+0xb7/0x110
Jun 18 04:11:40 homerouter kernel: [ 1708.238640] [] ? posix_get_boottime+0x1f/0x30
Jun 18 04:11:40 homerouter kernel: [ 1708.238642] [] ? system_call_fast_compare_end+0xc/0x67
Jun 18 04:11:40 homerouter kernel: [ 1708.238643] bash R running task 0 7516 7345 0x00000008
Jun 18 04:11:40 homerouter kernel: [ 1708.238645] ffff8800b631d140 00000000621ff7d1 ffffffff810a434f 0000000000000074
Jun 18 04:11:40 homerouter kernel: [ 1708.238645]
Jun 18 04:11:40 homerouter kernel: [ 1708.238647] ffffffff81abbd00 0000000000000007 0000000000000000 ffffffff813e8a1c
Jun 18 04:11:40 homerouter kernel: [ 1708.238648] ffffffff813e90b5 0000000000000002 fffffffffffffffb ffff8800a4977f20
Jun 18 04:11:40 homerouter kernel: [ 1708.238648] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238650] [] ? show_state_filter+0x6f/0xa0
Jun 18 04:11:40 homerouter kernel: [ 1708.238652] [] ? sysrq_handle_showstate+0xc/0x20
Jun 18 04:11:40 homerouter kernel: [ 1708.238653] [] ? __handle_sysrq+0xe5/0x140
Jun 18 04:11:40 homerouter kernel: [ 1708.238654] [] ? write_sysrq_trigger+0x2b/0x30
Jun 18 04:11:40 homerouter kernel: [ 1708.238656] [] ? proc_reg_write+0x3d/0x60
Jun 18 04:11:40 homerouter kernel: [ 1708.238657] [] ? vfs_write+0xa4/0x1a0
Jun 18 04:11:40 homerouter kernel: [ 1708.238658] [] ? SyS_write+0x52/0xc0
Jun 18 04:11:40 homerouter kernel: [ 1708.238660] [] ? SyS_dup2+0x95/0x100
Jun 18 04:11:40 homerouter kernel: [ 1708.238661] [] ? system_call_fast_compare_end+0xc/0x67
Jun 18 04:11:40 homerouter kernel: [ 1708.238664] tail S 0000000000000001 0 9065 7516 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238665] ffff8800a2d5c540 ffff8800d6d0e4c0 ffff880093084000 ffff880093083e10
Jun 18 04:11:40 homerouter kernel: [ 1708.238666] ffff8800a2d5c540 ffff8800cd20f910 000000000000001d 00000000014a4090
Jun 18 04:11:40 homerouter kernel: [ 1708.238668] ffffffff815b4fa1 ffff880093083e70 ffffffff815b7e12 7fffffffffffffff
Jun 18 04:11:40 homerouter kernel: [ 1708.238668] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238669] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238671] [] ? schedule_timeout+0x1b2/0x270
Jun 18 04:11:40 homerouter kernel: [ 1708.238672] [] ? touch_atime+0x33/0xd0
Jun 18 04:11:40 homerouter kernel: [ 1708.238674] [] ? tty_insert_flip_string_fixed_flag+0x85/0xe0
Jun 18 04:11:40 homerouter kernel: [ 1708.238675] [] ? generic_file_read_iter+0x63d/0x790
Jun 18 04:11:40 homerouter kernel: [ 1708.238676] [] ? wait_woken+0x42/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238678] [] ? inotify_read+0x32d/0x440
Jun 18 04:11:40 homerouter kernel: [ 1708.238679] [] ? abort_exclusive_wait+0x90/0x90
Jun 18 04:11:40 homerouter kernel: [ 1708.238681] [] ? vfs_read+0x81/0x120
Jun 18 04:11:40 homerouter kernel: [ 1708.238682] [] ? SyS_read+0x52/0xc0
Jun 18 04:11:40 homerouter kernel: [ 1708.238683] [] ? system_call_fast_compare_end+0xc/0x67
Jun 18 04:11:40 homerouter kernel: [ 1708.238686] kworker/u8:0 S 0000000000000000 0 22639 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238689] ffff8800d6d0e4c0 ffff8800d328e400 ffff8800b01f0000 ffff880116b0ec00
Jun 18 04:11:40 homerouter kernel: [ 1708.238691] 0000000000000088 ffff880116b0ec20 ffff880115ebd280 ffff8800d6d0e4c0
Jun 18 04:11:40 homerouter kernel: [ 1708.238692] ffffffff815b4fa1 ffff880116b0ec00 ffffffff81090ea7 ffff880116b0ec98
Jun 18 04:11:40 homerouter kernel: [ 1708.238692] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238694] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238695] [] ? worker_thread+0xc7/0x480
Jun 18 04:11:40 homerouter kernel: [ 1708.238697] [] ? process_one_work+0x410/0x410
Jun 18 04:11:40 homerouter kernel: [ 1708.238698] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238700] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238701] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238702] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238704] kworker/0:0 R running task 0 23190 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238708] ffff880115ea2580 ffffffff81a12500 ffff8800a8ea0000 ffff88011bc15180
Jun 18 04:11:40 homerouter kernel: [ 1708.238708]
Jun 18 04:11:40 homerouter kernel: [ 1708.238710] 0000000000000008 ffff88011bc151a0 ffff8800d30384c0 ffff880115ea2580
Jun 18 04:11:40 homerouter kernel: [ 1708.238711] ffffffff815b4fa1 ffff88011bc15180 ffffffff81090ea7 ffff8800d6d0f650
Jun 18 04:11:40 homerouter kernel: [ 1708.238711] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238713] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238714] [] ? worker_thread+0xc7/0x480
Jun 18 04:11:40 homerouter kernel: [ 1708.238715] [] ? process_one_work+0x410/0x410
Jun 18 04:11:40 homerouter kernel: [ 1708.238717] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238718] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238719] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238721] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238723] kworker/1:0 S 0000000000000001 0 23191 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238726] ffff8800d3a52d80 ffff880115ef1080 ffff880036ed8000 ffff88011bc95180
Jun 18 04:11:40 homerouter kernel: [ 1708.238728] 0000000000000008 ffff88011bc951a0 ffff8800b579cf40 ffff8800d3a52d80
Jun 18 04:11:40 homerouter kernel: [ 1708.238729] ffffffff815b4fa1 ffff88011bc95180 ffffffff81090ea7 ffff880115d69510
Jun 18 04:11:40 homerouter kernel: [ 1708.238730] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238731] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238732] [] ? worker_thread+0xc7/0x480
Jun 18 04:11:40 homerouter kernel: [ 1708.238734] [] ? process_one_work+0x410/0x410
Jun 18 04:11:40 homerouter kernel: [ 1708.238735] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238737] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238738] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238739] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238742] kworker/0:1 S 0000000000000000 0 23258 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238745] ffff880115ea0240 ffff880115d1edc0 ffff880036f08000 ffff88011bc15180
Jun 18 04:11:40 homerouter kernel: [ 1708.238746] ffffffff81090de0 ffff88011bc151a0 ffff8800abe72b80 ffff880115ea0240
Jun 18 04:11:40 homerouter kernel: [ 1708.238748] ffffffff815b4fa1 ffff88011bc15180 ffffffff81090ea7 ffff8800d6d0f650
Jun 18 04:11:40 homerouter kernel: [ 1708.238748] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238749] [] ? process_one_work+0x410/0x410
Jun 18 04:11:40 homerouter kernel: [ 1708.238750] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238752] [] ? worker_thread+0xc7/0x480
Jun 18 04:11:40 homerouter kernel: [ 1708.238753] [] ? process_one_work+0x410/0x410
Jun 18 04:11:40 homerouter kernel: [ 1708.238754] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238756] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238757] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238759] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238761] kworker/1:1 S 0000000000000001 0 23260 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238764] ffff880115ef1080 ffff880115ea0ec0 ffff8800a8de0000 ffff88011bc95180
Jun 18 04:11:40 homerouter kernel: [ 1708.238765] 0000000000000008 ffff88011bc951a0 ffff8800d0b18880 ffff880115ef1080
Jun 18 04:11:40 homerouter kernel: [ 1708.238766] ffffffff815b4fa1 ffff88011bc95180 ffffffff81090ea7 ffff8800d3a53290
Jun 18 04:11:40 homerouter kernel: [ 1708.238767] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238768] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238769] [] ? worker_thread+0xc7/0x480
Jun 18 04:11:40 homerouter kernel: [ 1708.238771] [] ? process_one_work+0x410/0x410
Jun 18 04:11:40 homerouter kernel: [ 1708.238772] [] ? kthread+0xcd/0xf0
Jun 18 04:11:40 homerouter kernel: [ 1708.238774] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238775] [] ? ret_from_fork+0x3f/0x70
Jun 18 04:11:40 homerouter kernel: [ 1708.238777] [] ? kthread_create_on_node+0x190/0x190
Jun 18 04:11:40 homerouter kernel: [ 1708.238779] kworker/u8:1 S 0000000000000001 0 23268 2 0x00000000
Jun 18 04:11:40 homerouter kernel: [ 1708.238782] ffff8800d317e140 ffff8800368d85c0 ffff8800a94c8000 ffff880116b0ec00
Jun 18 04:11:40 homerouter kernel: [ 1708.238783] 0000000000000088 ffff880116b0ec20 ffff8800abe72a00 ffff8800d317e140
Jun 18 04:11:40 homerouter kernel: [ 1708.238784] ffffffff815b4fa1 ffff880116b0ec00 ffffffff81090ea7 ffff8800d38c1490
Jun 18 04:11:40 homerouter kernel: [ 1708.238785] Call Trace:
Jun 18 04:11:40 homerouter kernel: [ 1708.238786] [] ? schedule+0x31/0x80
Jun 18 04:11:40 homerouter kernel: [ 1708.238787] [] ? worker_thread+0xc7/0x480
Jun 18 04:11:40 homerouter kernel: [ 1708.238789] [] ? process_one_work+0x410/0x410
Jun 18 04:11:40 homerouter kernel: [ 1708.238790] [

@mailinglists35
Copy link
Author

no

@mailinglists35
Copy link
Author

6 1 0x01 91 4368 3090901245 11480873125780
name                            type data
hits                            4    6561949
misses                          4    1182929
demand_data_hits                4    0
demand_data_misses              4    0
demand_metadata_hits            4    6561949
demand_metadata_misses          4    1182927
prefetch_data_hits              4    0
prefetch_data_misses            4    0
prefetch_metadata_hits          4    0
prefetch_metadata_misses        4    2
mru_hits                        4    285306
mru_ghost_hits                  4    1227
mfu_hits                        4    6276643
mfu_ghost_hits                  4    0
deleted                         4    0
mutex_miss                      4    0
evict_skip                      4    0
evict_not_enough                4    0
evict_l2_cached                 4    0
evict_l2_eligible               4    166555648
evict_l2_ineligible             4    0
evict_l2_skip                   4    0
hash_elements                   4    124511
hash_elements_max               4    124511
hash_collisions                 4    70496
hash_chains                     4    12379
hash_chain_max                  4    4
p                               4    1428932608
c                               4    2031835136
c_min                           4    33554432
c_max                           4    2031835136
size                            4    1523871888
hdr_size                        4    51634176
data_size                       4    0
metadata_size                   4    1400038400
other_size                      4    72199312
anon_size                       4    16384
anon_evictable_data             4    0
anon_evictable_metadata         4    0
mru_size                        4    1347721728
mru_evictable_data              4    0
mru_evictable_metadata          4    1346785792
mru_ghost_size                  4    161361920
mru_ghost_evictable_data        4    0
mru_ghost_evictable_metadata    4    161361920
mfu_size                        4    52300288
mfu_evictable_data              4    0
mfu_evictable_metadata          4    52300288
mfu_ghost_size                  4    0
mfu_ghost_evictable_data        4    0
mfu_ghost_evictable_metadata    4    0
l2_hits                         4    0
l2_misses                       4    0
l2_feeds                        4    0
l2_rw_clash                     4    0
l2_read_bytes                   4    0
l2_write_bytes                  4    0
l2_writes_sent                  4    0
l2_writes_done                  4    0
l2_writes_error                 4    0
l2_writes_lock_retry            4    0
l2_evict_lock_retry             4    0
l2_evict_reading                4    0
l2_evict_l1cached               4    0
l2_free_on_write                4    0
l2_cdata_free_on_write          4    0
l2_abort_lowmem                 4    0
l2_cksum_bad                    4    0
l2_io_error                     4    0
l2_size                         4    0
l2_asize                        4    0
l2_hdr_size                     4    0
l2_compress_successes           4    0
l2_compress_zeros               4    0
l2_compress_failures            4    0
memory_throttle_count           4    0
duplicate_buffers               4    0
duplicate_buffers_size          4    0
duplicate_reads                 4    0
memory_direct_count             4    0
memory_indirect_count           4    0
arc_no_grow                     4    0
arc_tempreserve                 4    0
arc_loaned_bytes                4    0
arc_prune                       4    0
arc_meta_used                   4    1523871888
arc_meta_limit                  4    1523876352
arc_meta_max                    4    1539803576
arc_meta_min                    4    16777216
arc_need_free                   4    0
arc_sys_free                    4    63492096

@mailinglists35
Copy link
Author

so... is it normal to take so long?
cpu core2duo E8200 @ 2.66GHz, 4gb ram

@mailinglists35
Copy link
Author

i'm getting similar times on freebsd with lots of ioctls to "5a14" when zfs is spinning 100% cpu

19199 zfs CALL ioctl(0x3,0xc0185a14,0x7fffffff3bb0)
19199 zfs RET ioctl -1 errno 3 No such process
19199 zfs CALL ioctl(0x3,0xc0185a14,0x7fffffff4e00)
19199 zfs RET ioctl 0

on linux strace says

ioctl(3, 0x5a14, 0x7ffd116bb330) = 0
ioctl(3, 0x5a14, 0x7ffd116b7d00) = -1 ESRCH (No such process)
ioctl(3, 0x5a14, 0x7ffd116bb330) = -1 ENOMEM (Cannot allocate memory)
ioctl(3, 0x5a14, 0x7ffd116bb330) = 0
ioctl(3, 0x5a14, 0x7ffd116b7d00) = -1 ESRCH (No such process)
ioctl(3, 0x5a14, 0x7ffd116bb330) = -1 ENOMEM (Cannot allocate memory)

@mailinglists35
Copy link
Author

update to kernel 4.6, first line of perf report now says reschedule_interrupt instead of poll_idle

@behlendorf behlendorf added the Type: Performance Performance improvement or performance problem label Jul 11, 2016
@behlendorf behlendorf added this to the 0.8.0 milestone Jul 11, 2016
@behlendorf
Copy link
Contributor

As suggested by @mailinglists35 it appears zfs list -H -o name -s name could be sped up by extending the zc_simple flag from 0cee240 to apply to filesystems when just the name is needed.

@behlendorf behlendorf modified the milestones: 0.7.0, 0.8.0 Jul 15, 2016
behlendorf pushed a commit to behlendorf/zfs that referenced this issue Jul 26, 2016
Metadata-intensive workloads can cause the ARC to become permanently
filled with dnode_t objects as they're pinned by the VFS layer.
Subsequent data-intensive workloads may only benefit from about
25% of the potential ARC (arc_c_max - arc_meta_limit).

In order to help track metadata usage more precisely, the other_size
metadata arcstat has replaced with dbuf_size, dnode_size and bonus_size.

The new zfs_arc_dnode_limit tunable, which defaults to 10% of
zfs_arc_meta_limit, defines the minimum number of bytes which is desirable
to be consumed by dnodes.  Attempts to evict non-metadata will trigger
async prune tasks if the space used by dnodes exceeds this limit.

The new zfs_arc_dnode_reduce_percent tunable specifies the amount by
which the excess dnode space is attempted to be pruned as a percentage of
the amount by which zfs_arc_dnode_limit is being exceeded.  By default,
it tries to unpin 10% of the dnodes.

The problem of dnode metadata pinning was observed with the following
testing procedure (in this example, zfs_arc_max is set to 4GiB):

    - Create a large number of small files until arc_meta_used exceeds
      arc_meta_limit (3GiB with default tuning) and arc_prune
      starts increasing.

    - Create a 3GiB file with dd.  Observe arc_mata_used.  It will still
      be around 3GiB.

    - Repeatedly read the 3GiB file and observe arc_meta_limit as before.
      It will continue to stay around 3GiB.

With this modification, space for the 3GiB file is gradually made
available as subsequent demands on the ARC are made.  The previous behavior
can be restored by setting zfs_arc_dnode_limit to the same value as the
zfs_arc_meta_limit.

Signed-off-by: Tim Chase <[email protected]>
Signed-off-by: Brian Behlendorf <[email protected]>
Issue openzfs#4345
Issue openzfs#4512
Issue openzfs#4773
Closes openzfs#4858
@behlendorf behlendorf removed this from the 0.7.0 milestone Oct 11, 2016
@rageagainstthebugs
Copy link

Maybe this be fix in 2e5dc44

@behlendorf
Copy link
Contributor

Performance should be considerably improved in master due to the referenced commit.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Type: Performance Performance improvement or performance problem
Projects
None yet
Development

No branches or pull requests

4 participants
@behlendorf @mailinglists35 @rageagainstthebugs and others