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

Another ZFS deadlock with 0.6.3-1, sysrq-t included #2864

Closed
snajpa opened this issue Nov 4, 2014 · 13 comments
Closed

Another ZFS deadlock with 0.6.3-1, sysrq-t included #2864

snajpa opened this issue Nov 4, 2014 · 13 comments

Comments

@snajpa
Copy link
Contributor

snajpa commented Nov 4, 2014

[root@node5.prg.vpsfree.cz]
 ~ # modinfo zfs | head
filename:       /lib/modules/2.6.32-042stab093.4/extra/zfs/zfs/zfs.ko
version:        0.6.3-1
license:        CDDL
author:         Sun Microsystems/Oracle, Lawrence Livermore National Laboratory
description:    ZFS
srcversion:     C29A443E3D2B93F605A540B
depends:        spl,znvpair,zcommon,zunicode,zavl
vermagic:       2.6.32-042stab093.4 SMP mod_unload modversions 
parm:           zvol_inhibit_dev:Do not create zvol device nodes (uint)
parm:           zvol_major:Major number for zvol device (uint)
[root@node5.prg.vpsfree.cz]
 ~ # uname -a
Linux node5.prg.vpsfree.cz 2.6.32-042stab093.4 #1 SMP Mon Aug 11 18:47:39 MSK 2014 x86_64 x86_64 x86_64 GNU/Linux

https://gist.github.com/anonymous/718e6a1aa6c99bc21a1d

Setting spl_kmem_cache_slab_limit=16384 or spl_kmem_cache_reclaim=0 with ZFS already stuck didn't help.

@snajpa
Copy link
Contributor Author

snajpa commented Nov 4, 2014

Two more interesting facts - spl_kmem_cache was spinning at 80-100% CPU, but what surprised me more, kswapd0/1 CPU usage was high as well, though I have no swap enabled on that machine. That one I would probably associate with OpenVZ VSwap functionality, which is probably unrelated, though.

@snajpa
Copy link
Contributor Author

snajpa commented Nov 4, 2014

Might I dare to ask, are you guys @behlendorf or @ryao any closer to chasing this? As load on our machines progressively increases, we're running into these issues almost on daily basis now. Which is really, really bad :( What surprises me though is, that during the day, during the normal (heavy) workload it works all OK, but things change when the containers start running cron jobs during the night - it's loadavg > 1000 almost every night on at least one server.
Most of the time it does recover from it after a while (10-20 minutes usually) but sometimes it stays stuck for too long, requiring a reset.

@behlendorf
Copy link
Contributor

@snajpa I've seen similar issues under specific workloads and getting to the bottom of them is high on my priority list. I suspect that the small patch in #2826 might help but I haven't had a chance to personally verify it. If you're in a position to try and it I'd appreciate the feedback.

@snajpa
Copy link
Contributor Author

snajpa commented Nov 6, 2014

OK, I'll try applying those changes on 0.6.3 tag

I can't move on to the HEAD, as it reports AIO as supported, but there's no direct IO support yet - this breaks mysql innodb engine, it tries to use both AIO and Direct IO, but only detects if AIO support is present. Effectively this nukes all MySQL instances and as we're OpenVZ based container host, people would kill me.

@behlendorf
Copy link
Contributor

Sounds like a good plan. I've opened #2872 for the MySQL issue you mentioned, if the addition of AIO support but lack of DIO support causes MySQL problems we may for forced to address that before the next tag.

@snajpa
Copy link
Contributor Author

snajpa commented Nov 12, 2014

@behlendorf thanks for opening 2872. I've deployed patched versions of 0.6.3-1 (https://github.com/vpsfreecz/zfs) on all of our nodes but haven't rebooted them yet; I'm essentially waiting for a deadlock on a particular node to shoot it in the head, so the it will come up with the patched kmod-zfs.
So far it's been only one node and it seems to be running OK since - it's got 8 days of uptime at this moment, I haven't seen any alerts from monitoring complaining about the loadavg thus far. I'll keep you posted if there's any news.

@snajpa
Copy link
Contributor Author

snajpa commented Nov 12, 2014

Sorry I've mistaken it for the other one where I've seen that happening pretty often (node5). Node6 is the one with this patch and it's got 2 and 1/2 days of uptime now.

@snajpa
Copy link
Contributor Author

snajpa commented Dec 17, 2014

So the patch doesn't seem to make any difference. Stack traces again included from two nodes:

node4
https://gist.github.com/05bc6a247d95bec7d392
https://gist.github.com/fe4ae252052a883eab1c

node8
https://gist.github.com/68c7491964dcc67fa2f0

@behlendorf
Copy link
Contributor

According to the stacks you've provided we've effectively deadlocked the system in memory reclaim. The patches proposed in #2918 should help with this and they'll likely be merged in the next week or so.

@snajpa
Copy link
Contributor Author

snajpa commented Feb 3, 2015

So I've deployed HEAD on most troubled nodes, with a small patch disabling AIO, so that I don't break MySQL.

https://github.com/vpsfreecz/zfs/commits/master

I'll let you know how it goes, I either expect sh*t hitting the fan within one week or possibly(?) now never :)

@snajpa
Copy link
Contributor Author

snajpa commented Feb 4, 2015

Well, it is better, however, I still get load spikes for too long - just now there's been a 10min long window, where any IO request was taking really long time to finish.

I don't limit ARC size and the only deviations from default settings are zfs_txg_timeout=10s and zfs_dirty_data_sync=512M.

I caught this in dmesg:
``
[92959.033703] INFO: task java:199586 blocked for more than 120 seconds.
[92959.033729] Tainted: P --------------- 2.6.32-042stab103.6 #1
[92959.033748] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[92959.033770] java D ffff883682becc80 0 199586 188622 2067 0x00000000
[92959.033780] ffff883642b7fa38 0000000000000082 ffff883642b7f9c8 ffff8813d09e7ac8
[92959.033789] ffff8813d09e7b20 ffff882070c89cc0 ffff882072174980 ffff88206f64bf40
[92959.033792] ffff883642b7fa18 ffffffff8119b1fd 0000000000000000 00000000835a0040
[92959.033801] Call Trace:
[92959.033813] [] ? cache_alloc_refill+0x14d/0x230
[92959.033823] [] __mutex_lock_slowpath+0x96/0x210
[92959.033829] [] mutex_lock+0x2b/0x50
[92959.033939] [] dmu_zfetch+0x424/0xe70 [zfs]
[92959.033974] [] dbuf_read+0x7a9/0x850 [zfs]
[92959.034003] [] dmu_buf_hold_array_by_dnode+0x127/0x530 [zfs]
[92959.034039] [] dmu_buf_hold_array+0x65/0x90 [zfs]
[92959.034067] [] dmu_read_uio+0x41/0xd0 [zfs]
[92959.034118] [] zfs_read+0x140/0x450 [zfs]
[92959.034126] [] ? virtinfo_notifier_call+0x76/0xb0
[92959.034175] [] zpl_read+0xa5/0x140 [zfs]
[92959.034183] [] vfs_read+0xb5/0x1a0
[92959.034194] [] ? call_function_interrupt+0xe/0x20
[92959.034199] [] sys_pread64+0x82/0xa0
[92959.034203] [] system_call_fastpath+0x16/0x1b
[92959.034222] INFO: task java:202274 blocked for more than 120 seconds.
[92959.034243] Tainted: P --------------- 2.6.32-042stab103.6 #1
[92959.034263] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[92959.034285] java D ffff88163a4dc500 0 202274 188622 2067 0x00000000
[92959.034293] ffff88160145da38 0000000000000082 ffff88160145da58 ffffffff81066993
[92959.034299] ffff8816be09f138 ffff882100d1dd80 ffff88160145d9f8 ffffffff8106f0f2
[92959.034308] ffff8816be09f100 ffff882100d1dd80 ffff8816be09f148 ffff883747c36000
[92959.034317] Call Trace:
[92959.034323] [] ? perf_event_task_sched_out+0x33/0x70
[92959.034328] [] ? check_preempt_wakeup+0x1c2/0x260
[92959.034334] [] __mutex_lock_slowpath+0x96/0x210
[92959.034339] [] mutex_lock+0x2b/0x50
[92959.034379] [] dmu_zfetch+0x858/0xe70 [zfs]
[92959.034410] [] dbuf_read+0x7a9/0x850 [zfs]
[92959.034444] [] dmu_buf_hold_array_by_dnode+0x127/0x530 [zfs]
[92959.034480] [] dmu_buf_hold_array+0x65/0x90 [zfs]
[92959.034511] [] dmu_read_uio+0x41/0xd0 [zfs]
[92959.034552] [] zfs_read+0x140/0x450 [zfs]
[92959.034559] [] ? virtinfo_notifier_call+0x76/0xb0
[92959.034596] [] ? __dequeue_entity+0x30/0x50
[92959.034639] [] zpl_read+0xa5/0x140 [zfs]
[92959.034646] [] vfs_read+0xb5/0x1a0
[92959.034649] [] sys_pread64+0x82/0xa0
[92959.034655] [] system_call_fastpath+0x16/0x1b
[93009.183496] Redirect from 172.16.0.14 on venet0 about 37.205.9.100 ignored.
[93009.183501] Advised path = 83.167.228.36 -> 37.205.9.100
[93039.882813] Redirect from 172.16.0.14 on venet0 about 37.205.9.100 ignored.
[93039.882817] Advised path = 83.167.228.36 -> 37.205.9.100
[93079.005218] INFO: task nfsd:9040 blocked for more than 120 seconds.
[93079.005245] Tainted: P --------------- 2.6.32-042stab103.6 #1
[93079.005266] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[93079.005289] nfsd D ffff88203bbac8c0 0 9040 2 0 0x00000000
[93079.005297] ffff88203abc9670 0000000000000046 000412d000000010 ffff882080011640
[93079.005303] ffff882072174480 ffff88206f64bf40 ffff88206f64bf80 ffff8840704d9800
[93079.005307] ffff88207019a020 ffff880610a01348 ffff88207075b080 0000000000000011
[93079.005312] Call Trace:
[93079.005327] [] __mutex_lock_slowpath+0x96/0x210
[93079.005333] [] ? down_read+0x16/0x30
[93079.005337] [] mutex_lock+0x2b/0x50
[93079.005432] [] dmu_zfetch+0x3c3/0xe70 [zfs]
[93079.005459] [] dbuf_read+0x7a9/0x850 [zfs]
[93079.005486] [] dmu_buf_hold_array_by_dnode+0x127/0x530 [zfs]
[93079.005517] [] dmu_buf_hold_array+0x65/0x90 [zfs]
[93079.005542] [] dmu_read_uio+0x41/0xd0 [zfs]
[93079.005592] [] zfs_read+0x140/0x450 [zfs]
[93079.005631] [] zpl_read+0xa5/0x140 [zfs]
[93079.005666] [] ? zpl_read+0x0/0x140 [zfs]
[93079.005672] [] do_loop_readv_writev+0x59/0x90
[93079.005678] [] do_readv_writev+0x1e6/0x1f0
[93079.005714] [] ? zfs_open+0x9e/0x140 [zfs]
[93079.005718] [] vfs_readv+0x43/0x60
[93079.005732] [] nfsd_vfs_read+0x88/0x1d0 [nfsd]
[93079.005739] [] ? getboottime+0x34/0x50
[93079.005749] [] nfsd_read+0x1da/0x320 [nfsd]
[93079.005753] [] ? getboottime+0x34/0x50
[93079.005765] [] nfsd3_proc_read+0xd5/0x180 [nfsd]
[93079.005775] [] nfsd_dispatch+0xe5/0x230 [nfsd]
[93079.005799] [] svc_process_common+0x344/0x640 [sunrpc]
[93079.005809] [] ? default_wake_function+0x0/0x20
[93079.005823] [] svc_process+0x102/0x150 [sunrpc]
[93079.005831] [] nfsd+0xcd/0x180 [nfsd]
[93079.005839] [] ? nfsd+0x0/0x180 [nfsd]
[93079.005845] [] kthread+0x9e/0xc0
[93079.005850] [] child_rip+0xa/0x20
[93079.005854] [] ? kthread+0x0/0xc0
[93079.005858] [] ? child_rip+0x0/0x20
[93079.005862] INFO: task nfsd:9041 blocked for more than 120 seconds.
[93079.005881] Tainted: P --------------- 2.6.32-042stab103.6 #1
[93079.005915] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[93079.006006] nfsd D ffff8820388c5400 0 9041 2 0 0x00000000
[93079.006013] ffff8820388c7670 0000000000000046 ffff8820388c75c0 ffffffffa04b08cc
[93079.006018] ffff8820388c7610 ffffffffa04b0e2b ffffffffffffff03 0000000000000007
[93079.006022] ffff882072e3d4e9 ffff880ef69a7200 ffff88206f515020 ffff882070c6e800
[93079.006027] Call Trace:
[93079.006043] [] ? bond_dev_queue_xmit+0x2c/0x50 [bonding]
[93079.006051] [] ? bond_start_xmit+0x53b/0x5d0 [bonding]
[93079.006059] [] __mutex_lock_slowpath+0x96/0x210
[93079.006063] [] ? down_read+0x16/0x30
[93079.006067] [] mutex_lock+0x2b/0x50
[93079.006107] [] dmu_zfetch+0x3c3/0xe70 [zfs]
[93079.006132] [] dbuf_read+0x7a9/0x850 [zfs]
[93079.006160] [] dmu_buf_hold_array_by_dnode+0x127/0x530 [zfs]
[93079.006191] [] dmu_buf_hold_array+0x65/0x90 [zfs]
[93079.006218] [] dmu_read_uio+0x41/0xd0 [zfs]
[93079.006259] [] zfs_read+0x140/0x450 [zfs]
[93079.006296] [] zpl_read+0xa5/0x140 [zfs]
[93079.006331] [] ? zpl_read+0x0/0x140 [zfs]
[93079.006335] [] do_loop_readv_writev+0x59/0x90
[93079.006340] [] do_readv_writev+0x1e6/0x1f0
[93079.006375] [] ? zfs_open+0x9e/0x140 [zfs]
[93079.006380] [] vfs_readv+0x43/0x60
[93079.006392] [] nfsd_vfs_read+0x88/0x1d0 [nfsd]
[93079.006399] [] ? getboottime+0x34/0x50
[93079.006409] [] nfsd_read+0x1da/0x320 [nfsd]
[93079.006413] [] ? getboottime+0x34/0x50
[93079.006426] [] nfsd3_proc_read+0xd5/0x180 [nfsd]
[93079.006436] [] nfsd_dispatch+0xe5/0x230 [nfsd]
[93079.006458] [] svc_process_common+0x344/0x640 [sunrpc]
[93079.006466] [] ? default_wake_function+0x0/0x20
[93079.006479] [] svc_process+0x102/0x150 [sunrpc]
[93079.006488] [] nfsd+0xcd/0x180 [nfsd]
[93079.006497] [] ? nfsd+0x0/0x180 [nfsd]
[93079.006503] [] kthread+0x9e/0xc0
[93079.006507] [] child_rip+0xa/0x20
[93079.006511] [] ? kthread+0x0/0xc0
[93079.006514] [] ? child_rip+0x0/0x20
[93079.006519] INFO: task nfsd:9042 blocked for more than 120 seconds.
[93079.006602] Tainted: P --------------- 2.6.32-042stab103.6 #1
[93079.006749] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[93079.006906] nfsd D ffff8820388c4900 0 9042 2 0 0x00000000
[93079.006913] ffff8820389c5670 0000000000000046 ffff8820389c55d0 ffffffff810a6c4f
[93079.006918] ffff882df2576b30 ffff882df2576960 ffff8820389c55f0 ffff8840704d9800
[93079.006922] ffff88207019a020 ffff8826d650f7c8 ffff88207075b080 0000000000000017
[93079.006927] Call Trace:
[93079.006933] [] ? wake_up_bit+0x2f/0x40
[93079.006941] [] __mutex_lock_slowpath+0x96/0x210
[93079.006946] [] ? down_read+0x16/0x30
[93079.006950] [] mutex_lock+0x2b/0x50
[93079.007005] [] dmu_zfetch+0x3c3/0xe70 [zfs]
[93079.007031] [] dbuf_read+0x7a9/0x850 [zfs]
[93079.007059] [] dmu_buf_hold_array_by_dnode+0x127/0x530 [zfs]
[93079.007090] [] dmu_buf_hold_array+0x65/0x90 [zfs]
[93079.007116] [] dmu_read_uio+0x41/0xd0 [zfs]
[93079.007162] [] zfs_read+0x140/0x450 [zfs]
[93079.007202] [] zpl_read+0xa5/0x140 [zfs]
[93079.007239] [] ? zpl_read+0x0/0x140 [zfs]
[93079.007245] [] do_loop_readv_writev+0x59/0x90
[93079.007250] [] do_readv_writev+0x1e6/0x1f0
[93079.007286] [] ? zfs_open+0x9e/0x140 [zfs]
[93079.007291] [] vfs_readv+0x43/0x60
[93079.007304] [] nfsd_vfs_read+0x88/0x1d0 [nfsd]
[93079.007312] [] ? getboottime+0x34/0x50
[93079.007322] [] nfsd_read+0x1da/0x320 [nfsd]
[93079.007326] [] ? getboottime+0x34/0x50
[93079.007339] [] nfsd3_proc_read+0xd5/0x180 [nfsd]
[93079.007348] [] nfsd_dispatch+0xe5/0x230 [nfsd]
[93079.007376] [] svc_process_common+0x344/0x640 [sunrpc]
[93079.007385] [] ? default_wake_function+0x0/0x20
[93079.007398] [] svc_process+0x102/0x150 [sunrpc]
[93079.007406] [] nfsd+0xcd/0x180 [nfsd]
[93079.007414] [] ? nfsd+0x0/0x180 [nfsd]
[93079.007418] [] kthread+0x9e/0xc0
[93079.007424] [] child_rip+0xa/0x20
[93079.007428] [] ? kthread+0x0/0xc0
[93079.007431] [] ? child_rip+0x0/0x20
[93079.007436] INFO: task nfsd:9044 blocked for more than 120 seconds.
[93079.007524] Tainted: P --------------- 2.6.32-042stab103.6 #1
[93079.007666] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[93079.007814] nfsd D ffff882038ae2940 0 9044 2 0 0x00000000
[93079.007820] ffff882038be1670 0000000000000046 ffff88206e745d00 000452d0810a6c4f
[93079.007825] ffff88206e745ce0 ffff88206e745cd0 ffff882038be15f0 ffff88204dbb0000
[93079.007830] 00000000000042d0 ffff8820713ad200 00000000000042d0 ffffffff8100ba8e
[93079.007835] Call Trace:
[93079.007841] [] ? common_interrupt+0xe/0x13
[93079.007849] [] __mutex_lock_slowpath+0x96/0x210
[93079.007854] [] mutex_lock+0x2b/0x50
[93079.007904] [] dmu_zfetch+0x3c3/0xe70 [zfs]
[93079.007937] [] ? arc_read+0x31b/0x9c0 [zfs]
[93079.007961] [] dbuf_read+0x4ac/0x850 [zfs]
[93079.007986] [] dmu_buf_hold_array_by_dnode+0x127/0x530 [zfs]
[93079.008017] [] dmu_buf_hold_array+0x65/0x90 [zfs]
[93079.008042] [] dmu_read_uio+0x41/0xd0 [zfs]
[93079.008083] [] zfs_read+0x140/0x450 [zfs]
[93079.008121] [] zpl_read+0xa5/0x140 [zfs]
[93079.008155] [] ? zpl_read+0x0/0x140 [zfs]
[93079.008161] [] do_loop_readv_writev+0x59/0x90
[93079.008166] [] do_readv_writev+0x1e6/0x1f0
[93079.008201] [] ? zfs_open+0x9e/0x140 [zfs]
[93079.008206] [] vfs_readv+0x43/0x60
[93079.008219] [] nfsd_vfs_read+0x88/0x1d0 [nfsd]
[93079.008225] [] ? getboottime+0x34/0x50
[93079.008235] [] nfsd_read+0x1da/0x320 [nfsd]
[93079.008239] [] ? getboottime+0x34/0x50
[93079.008252] [] nfsd3_proc_read+0xd5/0x180 [nfsd]
[93079.008261] [] nfsd_dispatch+0xe5/0x230 [nfsd]
[93079.008289] [] svc_process_common+0x344/0x640 [sunrpc]
[93079.008299] [] ? default_wake_function+0x0/0x20
[93079.008312] [] svc_process+0x102/0x150 [sunrpc]
[93079.008321] [] nfsd+0xcd/0x180 [nfsd]
[93079.008329] [] ? nfsd+0x0/0x180 [nfsd]
[93079.008335] [] kthread+0x9e/0xc0
[93079.008339] [] child_rip+0xa/0x20
[93079.008343] [] ? kthread+0x0/0xc0
[93079.008346] [] ? child_rip+0x0/0x20
[93079.009356] INFO: task java:184115 blocked for more than 120 seconds.
[93079.009444] Tainted: P --------------- 2.6.32-042stab103.6 #1
[93079.009589] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[93079.009741] java D ffff8817ac041180 0 184115 184079 1917 0x00000000
[93079.009749] ffff881793bc5a38 0000000000000086 ffff881ffad12d00 0000000000000010
[93079.009754] 000000000001dd80 ffff881ffad12d00 0000000000000010 ffff881ffad12d00
[93079.009759] ffff881793bc5a78 ffffffff81531a60 ffff8817ff144000 ffff883869722eb8
[93079.009764] Call Trace:
[93079.009779] [] ? thread_return+0xbe/0x8ee
[93079.009785] [] __mutex_lock_slowpath+0x96/0x210
[93079.009789] [] mutex_lock+0x2b/0x50
[93079.009874] [] dmu_zfetch+0x3c3/0xe70 [zfs]
[93079.009899] [] dbuf_read+0x7a9/0x850 [zfs]
[93079.009934] [] dmu_buf_hold_array_by_dnode+0x127/0x530 [zfs]
[93079.009965] [] dmu_buf_hold_array+0x65/0x90 [zfs]
[93079.009990] [] dmu_read_uio+0x41/0xd0 [zfs]
[93079.010037] [] zfs_read+0x140/0x450 [zfs]
[93079.010044] [] ? virtinfo_notifier_call+0x76/0xb0
[93079.010081] [] zpl_read+0xa5/0x140 [zfs]
[93079.010088] [] vfs_read+0xb5/0x1a0
[93079.010092] [] ? fget_light+0x83/0xa0
[93079.010096] [] sys_pread64+0x82/0xa0
[93079.010103] [] ? call_function_interrupt+0xe/0x20
[93079.010108] [] system_call_fastpath+0x16/0x1b
[93079.010117] INFO: task java:460242 blocked for more than 120 seconds.
[93079.010201] Tainted: P --------------- 2.6.32-042stab103.6 #1
[93079.010348] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[93079.010493] java D ffff880b9ddbf380 0 460242 184079 1917 0x00000000
[93079.010499] ffff8818b729ba38 0000000000000086 ffff88012c09dd80 ffff8817ac0411b8
[93079.010505] ffff8817ff144200 ffff88012c09dde8 ffff88203a8293c8 ffff88012c09dde8
[93079.010510] ffff8818b729b9c8 ffffffff81060130 ffff88203a8293b8 ffff880b9ddbf380
[93079.010515] Call Trace:
[93079.010524] [] ? __dequeue_entity+0x30/0x50
[93079.010530] [] ? finish_task_switch+0xc8/0x120
[93079.010538] [] __mutex_lock_slowpath+0x96/0x210
[93079.010543] [] mutex_lock+0x2b/0x50
[93079.010602] [] dmu_zfetch+0x3c3/0xe70 [zfs]
[93079.010630] [] dbuf_read+0x7a9/0x850 [zfs]
[93079.010656] [] dmu_buf_hold_array_by_dnode+0x127/0x530 [zfs]
[93079.010682] [] dmu_buf_hold_array+0x65/0x90 [zfs]
[93079.010715] [] ? zfs_range_proxify+0x95/0xb0 [zfs]
[93079.010742] [] dmu_read_uio+0x41/0xd0 [zfs]
[93079.010779] [] zfs_read+0x140/0x450 [zfs]
[93079.010784] [] ? virtinfo_notifier_call+0x76/0xb0
[93079.010788] [] ? __dequeue_entity+0x30/0x50
[93079.010823] [] zpl_read+0xa5/0x140 [zfs]
[93079.010830] [] vfs_read+0xb5/0x1a0
[93079.010834] [] ? fget_light+0x65/0xa0
[93079.010837] [] sys_pread64+0x82/0xa0
[93079.010842] [] system_call_fastpath+0x16/0x1b
[93079.140605] INFO: task java:199585 blocked for more than 120 seconds.
[93079.140705] Tainted: P --------------- 2.6.32-042stab103.6 #1
[93079.140871] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[93079.141030] java D ffff8836ee4b03c0 0 199585 188622 2067 0x00000000
[93079.141039] ffff883642b7d9c0 0000000000000082 0000000000000000 ffff883642b7d9a8
[93079.141044] ffffffffa02a4e65 ffff883642b7d968 0000000000000286 ffff883642b7d978
[93079.141047] ffff8824f8075000 ffff883642b7d958 ffffffff8153350e 0000000000000000
[93079.141052] Call Trace:
[93079.141182] [] ? dbuf_rele_and_unlock+0x235/0x360 [zfs]
[93079.141196] [] ? mutex_lock+0x1e/0x50
[93079.141207] [] rwsem_down_failed_common+0x95/0x1d0
[93079.141215] [] ? update_curr+0xe1/0x1f0
[93079.141221] [] rwsem_down_read_failed+0x26/0x30
[93079.141228] [] call_rwsem_down_read_failed+0x14/0x30
[93079.141234] [] ? down_read+0x24/0x30
[93079.141277] [] dmu_zfetch+0xb9/0xe70 [zfs]
[93079.141310] [] dbuf_read+0x7a9/0x850 [zfs]
[93079.141343] [] dmu_buf_hold_array_by_dnode+0x127/0x530 [zfs]
[93079.141382] [] dmu_buf_hold_array+0x65/0x90 [zfs]
[93079.141414] [] dmu_read_uio+0x41/0xd0 [zfs]
[93079.141472] [] zfs_read+0x140/0x450 [zfs]
[93079.141480] [] ? virtinfo_notifier_call+0x76/0xb0
[93079.141488] [] ? __dequeue_entity+0x30/0x50
[93079.141533] [] zpl_read+0xa5/0x140 [zfs]
[93079.141540] [] vfs_read+0xb5/0x1a0
[93079.141547] [] ? call_function_interrupt+0xe/0x20
[93079.141551] [] sys_pread64+0x82/0xa0
[93079.141554] [] system_call_fastpath+0x16/0x1b
[93079.141559] INFO: task java:199586 blocked for more than 120 seconds.
[93079.141657] Tainted: P --------------- 2.6.32-042stab103.6 #1
[93079.141815] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[93079.141980] java D ffff883682becc80 0 199586 188622 2067 0x00000000
[93079.141987] ffff883642b7fa38 0000000000000082 ffff883642b7f9c8 ffff8813d09e7ac8
[93079.141991] ffff8813d09e7b20 ffff882070c89cc0 ffff882072174980 ffff88206f64bf40
[93079.141995] ffff883642b7fa18 ffffffff8119b1fd 0000000000000000 00000000835a0040
[93079.141999] Call Trace:
[93079.142012] [] ? cache_alloc_refill+0x14d/0x230
[93079.142021] [] __mutex_lock_slowpath+0x96/0x210
[93079.142026] [] mutex_lock+0x2b/0x50
[93079.142105] [] dmu_zfetch+0x424/0xe70 [zfs]
[93079.142135] [] dbuf_read+0x7a9/0x850 [zfs]
[93079.142167] [] dmu_buf_hold_array_by_dnode+0x127/0x530 [zfs]
[93079.142205] [] dmu_buf_hold_array+0x65/0x90 [zfs]
[93079.142237] [] dmu_read_uio+0x41/0xd0 [zfs]
[93079.142293] [] zfs_read+0x140/0x450 [zfs]
[93079.142301] [] ? virtinfo_notifier_call+0x76/0xb0
[93079.142346] [] zpl_read+0xa5/0x140 [zfs]
[93079.142354] [] vfs_read+0xb5/0x1a0
[93079.142360] [] ? call_function_interrupt+0xe/0x20
[93079.142364] [] sys_pread64+0x82/0xa0
[93079.142368] [] system_call_fastpath+0x16/0x1b

@snajpa
Copy link
Contributor Author

snajpa commented Feb 4, 2015

Another interesting observation: when ARC is shrinking, kswapd0/1 spike up in CPU usage, IO seems to stall a bit and after reclaim is done, everything continues to normal. Funny thing is, that the system reports about 20G of absolutely free memory (of 256G total, ARC oscilates around 100G, no swap configured at all).

@behlendorf
Copy link
Contributor

Closing. This is believed to be resolved.

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

No branches or pull requests

2 participants