hung tasks (umount) after accessing snaphost

[ghost]

After accessing a snapshot the umount hangs. This is on rc12.

INFO: task events/0:7 blocked for more than 300 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
events/0      D 0000000000000000     0     7      2 0x00000000
 ffff8800ccdd9b20 0000000000000046 ffff8800ccdd9ad0 ffffffff810096f0
 ffff8800ccdd6078 0000000000000000 0000000000dd9ae0 ffff880002214200
 ffff8800ccdd7ab8 ffff8800ccdd9fd8 000000000000fb88 ffff8800ccdd7ab8
Call Trace:
 [<ffffffff810096f0>] ? __switch_to+0xd0/0x320
 [<ffffffff814fe0a0>] ? thread_return+0x4e/0x76e
 [<ffffffff814fef15>] schedule_timeout+0x215/0x2e0
 [<ffffffff8104e379>] ? __wake_up_common+0x59/0x90
 [<ffffffff814feb93>] wait_for_common+0x123/0x180
 [<ffffffff810602c0>] ? default_wake_function+0x0/0x20
 [<ffffffff8108cdf1>] ? __queue_work+0x41/0x50
 [<ffffffff814fecad>] wait_for_completion+0x1d/0x20
 [<ffffffff8108b340>] call_usermodehelper_exec+0xe0/0xf0
 [<ffffffffa0430585>] __zfsctl_unmount_snapshot+0xa5/0x110 [zfs]
 [<ffffffffa043074e>] zfsctl_unmount_snapshot+0x8e/0xf0 [zfs]
 [<ffffffff814fe0a0>] ? thread_return+0x4e/0x76e
 [<ffffffffa04307b0>] ? zfsctl_expire_snapshot+0x0/0x60 [zfs]
 [<ffffffffa04307e1>] zfsctl_expire_snapshot+0x31/0x60 [zfs]
 [<ffffffff8108c800>] worker_thread+0x170/0x2a0
 [<ffffffff81092170>] ? autoremove_wake_function+0x0/0x40
 [<ffffffff8108c690>] ? worker_thread+0x0/0x2a0
 [<ffffffff81091e06>] kthread+0x96/0xa0
 [<ffffffff8100c14a>] child_rip+0xa/0x20
 [<ffffffff81091d70>] ? kthread+0x0/0xa0
 [<ffffffff8100c140>] ? child_rip+0x0/0x20
INFO: task umount:1914 blocked for more than 300 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
umount        D 0000000000000000     0  1914   1913 0x00000080
 ffff88002e8fbbb8 0000000000000082 ffff88002e8fbb38 0000000000000246
 ffff88002e8fbb48 0000000000000001 ffff88002e8fbb48 ffffffff814ff58e
 ffff880034de5058 ffff88002e8fbfd8 000000000000fb88 ffff880034de5058
Call Trace:
 [<ffffffff814ff58e>] ? mutex_lock+0x1e/0x50
 [<ffffffffa03c2417>] ? dbuf_destroy+0x137/0x150 [zfs]
 [<ffffffff814ff6fe>] __mutex_lock_slowpath+0x13e/0x180
 [<ffffffff814ff59b>] mutex_lock+0x2b/0x50
 [<ffffffffa03b98c1>] remove_reference+0x61/0xc0 [zfs]
 [<ffffffffa03bab60>] arc_buf_remove_ref+0xc0/0x120 [zfs]
 [<ffffffffa03c2d1f>] dbuf_rele_and_unlock+0x10f/0x200 [zfs]
 [<ffffffffa03c31b0>] dmu_buf_rele+0x30/0x40 [zfs]
 [<ffffffffa03dae60>] dnode_rele+0x80/0x90 [zfs]
 [<ffffffffa03cf52a>] dmu_objset_evict_dbufs+0x16a/0x180 [zfs]
 [<ffffffffa0444f9f>] zfs_sb_teardown+0x18f/0x390 [zfs]
 [<ffffffffa0445210>] zfs_umount+0x30/0xc0 [zfs]
 [<ffffffffa045fdfe>] zpl_put_super+0xe/0x10 [zfs]
 [<ffffffff8117d84b>] generic_shutdown_super+0x5b/0xe0
 [<ffffffff8117d936>] kill_anon_super+0x16/0x60
 [<ffffffffa045fc5e>] zpl_kill_sb+0x1e/0x30 [zfs]
 [<ffffffff8117e9b0>] deactivate_super+0x70/0x90
 [<ffffffff8119a9ef>] mntput_no_expire+0xbf/0x110
 [<ffffffff8119b48b>] sys_umount+0x7b/0x3a0
 [<ffffffff810d6d42>] ? audit_syscall_entry+0x272/0x2a0
 [<ffffffff8100b0f2>] system_call_fastpath+0x16/0x1b

[behlendorf]

Strange, it's not at all clear why the umount process is hung on that mutex. Do you have any other stacks which show what process might be holding it?

[ghost]

No, that's all I got. The above showed 5 times in the log (same stacks). I waited two more hours the I rebooted the system.

[greg-hydrogen]

I am also having the same problem and it is very reproducible

I am running Scientific Linux 6.3 with kernel 3.6.11 and spl/zfs rc-13 (git wont compile due to missing symbol cv_wait_io)

I have created a zfs pool using loop back devices for testing, 4x50GB disk image files in RAIDZ2, 2x5GB disk image files for mirrored ZIL (on SSD) and 20GB disk image file for cache (on SSD)

I am able to mount the ZFS pool without and issuse and create/modify delete files as needed, unmounting at this point does not cause an issue, however, if I access the .zfs folder (not visible) and browse the snapshot folder, I am no longer able to unmount the filesystem. I get the following error

umount: /storage/zfsmount: device is busy.
(In some cases useful info about processes that use
the device is found by lsof(8) or fuser(1))
lsof output
zfs_iput_ 6912 root cwd DIR 253,0 4096 2 /
zfs_iput_ 6912 root rtd DIR 253,0 4096 2 /
zfs_iput_ 6912 root txt unknown /proc/6912/exe
flush-zfs 6958 root cwd DIR 253,0 4096 2 /
flush-zfs 6958 root rtd DIR 253,0 4096 2 /
flush-zfs 6958 root txt unknown /proc/6958/exe

after about 30 seconds I get a kernel bug dump
BUG: Dentry ffff8803aeaa6900{i=4,n=/} still in use (1) [unmount of zfs zfs]
------------[ cut here ]------------
kernel BUG at fs/dcache.c:967!
invalid opcode: 0000 [#1] SMP
Modules linked in: ebtable_nat ebtables xt_CHECKSUM iptable_mangle bridge stp llc autofs4 sunrpc vboxpci(O) vboxnetadp(O) vboxnetflt(O) vboxdrv(O) ppdev vmnet(O) parport_pc parport fuse vsock(O) vmci(O) vmmon(O) cpufreq_ondemand ipt_REJECT nf_conntrack_ipv4 nf_defrag_ipv4 iptable_filter ip_tables ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 xt_state nf_conntrack ip6table_filter ip6_tables ipv6 zfs(PO) zcommon(PO) znvpair(PO) zavl(PO) zunicode(PO) spl(O) zlib_deflate vhost_net macvtap macvlan tun uinput powernow_k8 freq_table mperf kvm_amd kvm crc32c_intel ghash_clmulni_intel microcode fam15h_power pcspkr serio_raw k10temp edac_core edac_mce_amd sg i2c_piix4 i2c_core wmi xhci_hcd r8168(O) snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_hwdep snd_seq snd_seq_device snd_pcm snd_timer snd soundcore snd_page_alloc fglrx(PO) ext4 mbcache jbd2 sr_mod cdrom sd_mod crc_t10dif aesni_intel ablk_helper cryptd aes_x86_64 ahci libahci dm_mirror dm_region_hash dm_log dm_mod
CPU 5
Pid: 7074, comm: umount Tainted: P O 3.6.11 #3 To be filled by O.E.M. To be filled by O.E.M./M5A97
RIP: 0010:[] [] shrink_dcache_for_umount_subtree+0x17d/0x190
RSP: 0018:ffff8803af05bd78 EFLAGS: 00010292
RAX: 000000000000004b RBX: ffff8803aeaa6900 RCX: 0000000000001c78
RDX: 000000000000da91 RSI: 0000000000000082 RDI: 0000000000000246
RBP: ffff8803af05bd98 R08: ffffffff81cd0b60 R09: 00000000000157a8
R10: 000000000000043d R11: 000000000000043d R12: ffff8803aeaa6900
R13: ffff880412523000 R14: ffff8803aeac2c00 R15: 0000000000000000
FS: 00007fe12db14740(0000) GS:ffff88043ed40000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007fe12d2101a0 CR3: 00000003aed1f000 CR4: 00000000000407e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process umount (pid: 7074, threadinfo ffff8803af05a000, task ffff880429d6ea70)
Stack:
ffff880412523350 ffffffff8108bde2 ffff880412523000 ffffffffa09e48a0
ffff8803af05bdb8 ffffffff811914d7 ffff8803af05bde8 ffff880412523000
ffff8803af05bde8 ffffffff8117d12c 0000000000040000 000000000000001f
Call Trace:
[] ? default_wake_function+0x12/0x20
[] shrink_dcache_for_umount+0x37/0x60
[] generic_shutdown_super+0x2c/0xf0
[] kill_anon_super+0x16/0x30
[] zpl_kill_sb+0x1e/0x30 [zfs]
[] deactivate_locked_super+0x45/0x80
[] deactivate_super+0x4a/0x70
[] mntput_no_expire+0xd2/0x130
[] mntput+0x23/0x40
[] release_mounts+0x7c/0xa0
[] do_umount+0xf7/0x240
[] sys_umount+0xcb/0xe0
[] system_call_fastpath+0x16/0x1b
Code: 50 28 4c 8b 0a 31 d2 48 85 f6 74 04 48 8b 56 40 48 05 50 03 00 00 48 89 de 48 c7 c7 98 af 7c 81 48 89 04 24 31 c0 e8 2c a8 39 00 <0f> 0b eb fe 0f 0b eb fe 66 66 2e 0f 1f 84 00 00 00 00 00 55 48
RIP [] shrink_dcache_for_umount_subtree+0x17d/0x190
RSP
---[ end trace 51c129a53765dbe0 ]---

[behlendorf]

@gunnarbeutner I'd suggest you try the latest master, it will build cleanly if you update both the spl and zfs. There were several snapshot related fixes which went in, however we are still resolving a few regression which snuck in with zfs rollback support.

[greg-hydrogen]

Thanks Behlendorf for the suggestion

I have built the spl and zfs from the latest git. I am now able to browse the .zfs folder and unmount the pool without any issues.

[behlendorf]

@bziller Can you still reproduce issues with the latest master? I'm unable to recrease this issue under RHEL6.3 and after all the .zfs snapshot fixes I'm inclined to think we got the root cause.

[behlendorf]

I'm tentative closing this we can easily reopen it if needed.

[toadicus]

Something similar may have just happened to me. It appears to also be tied to some other zvol access?

I noticed the umount had hung, and went in to troubleshoot. There were a bunch of zvol processes waiting for IO, so I stopped the processes using the zvols (they are backing VMs; I suspended the VMs). When I checked again, umount was done and loadavg was heading back down.

INFO: task z_unmount/0:6879 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
z_unmount/0   D 0000000000000000     0  6879      2 0x00000080
 ffff88081a733b70 0000000000000046 0000000000000000 ffffffff81055f76
 ffff88081a733b00 ffff880834bf7540 ffff88081a733b00 ffffffff810522fd
 ffff8808235d7af8 ffff88081a733fd8 000000000000fb88 ffff8808235d7af8
Call Trace:
 [<ffffffff81055f76>] ? enqueue_task+0x66/0x80
 [<ffffffff810522fd>] ? check_preempt_curr+0x6d/0x90
 [<ffffffff8150e7d5>] schedule_timeout+0x215/0x2e0
 [<ffffffff81096cb6>] ? autoremove_wake_function+0x16/0x40
 [<ffffffff81051419>] ? __wake_up_common+0x59/0x90
 [<ffffffff8150e453>] wait_for_common+0x123/0x180
 [<ffffffff81063310>] ? default_wake_function+0x0/0x20
 [<ffffffff810912d1>] ? __queue_work+0x41/0x50
 [<ffffffff8150e56d>] wait_for_completion+0x1d/0x20
 [<ffffffff8108f7ec>] call_usermodehelper_exec+0x10c/0x120
 [<ffffffffa065a513>] __zfsctl_unmount_snapshot+0xa3/0x110 [zfs]
 [<ffffffffa065a6c6>] zfsctl_unmount_snapshot+0x76/0xc0 [zfs]
 [<ffffffffa065a740>] zfsctl_expire_snapshot+0x30/0x80 [zfs]
 [<ffffffffa03316e8>] taskq_thread+0x218/0x4b0 [spl]
 [<ffffffff8150d960>] ? thread_return+0x4e/0x76e
 [<ffffffff81063310>] ? default_wake_function+0x0/0x20
 [<ffffffffa03314d0>] ? taskq_thread+0x0/0x4b0 [spl]
 [<ffffffff81096936>] kthread+0x96/0xa0
 [<ffffffff8100c0ca>] child_rip+0xa/0x20
 [<ffffffff810968a0>] ? kthread+0x0/0xa0
 [<ffffffff8100c0c0>] ? child_rip+0x0/0x20