crabique
commented
3 years ago This happened again on another server with ZFS 0.8.1 this time
[Sat Jul 31 05:50:14 2021] BUG: Dentry 000000009dee592c{i=1a5de,n=handlebars} still in use (1) [unmount of zfs zfs]
[Sat Jul 31 05:50:14 2021] ------------[ cut here ]------------
[Sat Jul 31 05:50:14 2021] WARNING: CPU: 8 PID: 76888 at /build/linux-hwe-NVnjsY/linux-hwe-5.3.0/fs/dcache.c:1596 umount_check+0x69/0x80
[Sat Jul 31 05:50:14 2021] Modules linked in: sctp binfmt_misc xt_tcpudp iptable_raw xt_CT nft_counter nft_chain_nat ipt_rpfilter xt_multiport nft_compat nf_tables ip_set_hash_ip ip_set_hash_net veth xt_physdev xt_addrtype xt_set ip_set_hash_ipportnet ip_set_hash_ipportip ip_set_hash_ipport ip_set_bitmap_port ip_set dummy rbd libceph ip6table_nat ip6_tables xt_MASQUERADE xt_comment xt_mark iptable_nat iptable_filter bpfilter xt_conntrack nf_nat nf_conntrack_netlink nfnetlink xfrm_user xfrm_algo aufs overlay zfs(PO) zunicode(PO) zavl(PO) icp(PO) zlua(PO) nls_iso8859_1 zcommon(PO) znvpair(PO) spl(O) kvm_amd ccp kvm irqbypass input_leds joydev serio_raw sch_fq_codel ib_iser rdma_cm iw_cm ib_cm ib_core iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi br_netfilter nfsd bridge auth_rpcgss stp llc nfs_acl lockd ip_vs_sh grace ip_vs_wrr ip_vs_rr sunrpc ip_vs nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 ip_tables x_tables autofs4 btrfs zstd_compress raid10 raid456 async_raid6_recov async_memcpy async_pq
[Sat Jul 31 05:50:14 2021] async_xor async_tx xor raid6_pq libcrc32c raid1 raid0 multipath linear hid_generic usbhid hid crct10dif_pclmul crc32_pclmul ghash_clmulni_intel aesni_intel aes_x86_64 crypto_simd cryptd psmouse glue_helper virtio_net virtio_blk net_failover failover floppy
[Sat Jul 31 05:50:14 2021] CPU: 8 PID: 76888 Comm: umount Tainted: P W O 5.3.0-73-generic #69-Ubuntu
[Sat Jul 31 05:50:14 2021] Hardware name: OpenStack Foundation OpenStack Nova, BIOS 1.13.0-1ubuntu1 04/01/2014
[Sat Jul 31 05:50:14 2021] RIP: 0010:umount_check+0x69/0x80
[Sat Jul 31 05:50:14 2021] Code: 08 48 8b 46 30 48 85 c0 74 27 48 8b 50 40 51 48 c7 c7 88 96 74 99 48 89 f1 e8 16 03 e2 ff 48 c7 c7 b8 5b 70 99 e8 0a 03 e2 ff <0f> 0b 58 31 c0 c9 c3 31 d2 eb d9 66 90 66 2e 0f 1f 84 00 00 00 00
[Sat Jul 31 05:50:14 2021] RSP: 0018:ffffb3063888fd48 EFLAGS: 00010286
[Sat Jul 31 05:50:14 2021] RAX: 0000000000000024 RBX: ffff9a588808de10 RCX: 0000000000000006
[Sat Jul 31 05:50:14 2021] RDX: 0000000000000000 RSI: 0000000000000096 RDI: ffff9a5acfa17440
[Sat Jul 31 05:50:14 2021] RBP: ffffb3063888fd50 R08: 0000000000000ed6 R09: 0000000000000004
[Sat Jul 31 05:50:14 2021] R10: ffffb30667763d68 R11: 0000000000000001 R12: ffff9a588808dd80
[Sat Jul 31 05:50:14 2021] R13: ffff9a4fc652dca0 R14: ffff9a4fc652dc00 R15: ffff9a588808ddd8
[Sat Jul 31 05:50:14 2021] FS: 00007fc1a44ecb48(0000) GS:ffff9a5acfa00000(0000) knlGS:0000000000000000
[Sat Jul 31 05:50:14 2021] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[Sat Jul 31 05:50:14 2021] CR2: 00007f44aba35fe8 CR3: 00000006726fc000 CR4: 0000000000340ee0
[Sat Jul 31 05:50:14 2021] Call Trace:
[Sat Jul 31 05:50:14 2021] d_walk+0xd5/0x270
[Sat Jul 31 05:50:14 2021] ? shrink_lock_dentry.part.18+0xf0/0xf0
[Sat Jul 31 05:50:14 2021] do_one_tree+0x24/0x40
[Sat Jul 31 05:50:14 2021] shrink_dcache_for_umount+0x2d/0x90
[Sat Jul 31 05:50:14 2021] generic_shutdown_super+0x1f/0x120
[Sat Jul 31 05:50:14 2021] kill_anon_super+0x12/0x30
[Sat Jul 31 05:50:14 2021] zpl_kill_sb+0x1a/0x20 [zfs]
[Sat Jul 31 05:50:14 2021] deactivate_locked_super+0x48/0x80
[Sat Jul 31 05:50:14 2021] deactivate_super+0x40/0x60
[Sat Jul 31 05:50:14 2021] cleanup_mnt+0xbd/0x160
[Sat Jul 31 05:50:14 2021] __cleanup_mnt+0x12/0x20
[Sat Jul 31 05:50:14 2021] task_work_run+0x9d/0xc0
[Sat Jul 31 05:50:14 2021] exit_to_usermode_loop+0x109/0x130
[Sat Jul 31 05:50:14 2021] do_syscall_64+0x115/0x130
[Sat Jul 31 05:50:14 2021] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[Sat Jul 31 05:50:14 2021] RIP: 0033:0x7fc1a4476189
[Sat Jul 31 05:50:14 2021] Code: 05 48 89 c7 e8 a5 eb ff ff 5a c3 31 f6 50 b8 a6 00 00 00 0f 05 48 89 c7 e8 91 eb ff ff 5a c3 48 63 f6 50 b8 a6 00 00 00 0f 05 <48> 89 c7 e8 7c eb ff ff 5a c3 49 89 ca 50 48 63 ff 4d 63 c0 b8 2f
[Sat Jul 31 05:50:14 2021] RSP: 002b:00007ffc6ea67e10 EFLAGS: 00000246 ORIG_RAX: 00000000000000a6
[Sat Jul 31 05:50:14 2021] RAX: 0000000000000000 RBX: 00007fc1a44ed1c0 RCX: 00007fc1a4476189
[Sat Jul 31 05:50:14 2021] RDX: 0000000000000000 RSI: 0000000000000003 RDI: 00007fc1a44ed6f0
[Sat Jul 31 05:50:14 2021] RBP: 00007fc1a4454970 R08: 0000000000000004 R09: 00007fc1a44549bc
[Sat Jul 31 05:50:14 2021] R10: 0000000000000000 R11: 0000000000000246 R12: 00007fc1a44544f0
[Sat Jul 31 05:50:14 2021] R13: 00007fc1a44ed6f0 R14: 0000000000000000 R15: 00007ffc6ea67f70
[Sat Jul 31 05:50:14 2021] ---[ end trace 645483d18c6a6aec ]---
wdoekes
stale[bot]
behlendorf
Describe the problem you're observing
For our backup system, we create a recursive ZFS snapshot and iterate the child snapshots, mounting them with
mount -t zfsinto a directory, running a process on them and then doingumount -fl. There is about ~10000 snapshots we go through every time, the processes are reasonably parallelized and mountpoints do not collide.Sometimes, a ZFS snapshot can't be unmounted with
umount -fl, an error is shown in dmesg output. This happens very randomly, so far it happened 3 times on 3 separate servers with different minor versions of ZFS 0.8, the details above are from the live case right now before we reboot it.The process does not react to kill signals or anything except for full system reboot.
Initially, we were using the
.zfs/snapshotvirtual directory to interface with files and the issue was also present there with some snapshots getting stuck, but in a different way, there was a D-state process like this one:Additionally, using the
.zfsdirectory caused frequent NFS issues and elevated system load, so we decided the automount was the root of the issue and we would kill two birds with one stone if we just mount snapshots elsewhere, because we would be also able to unmount them "lazily".Unfortunately, even though it helped with the load and NFS issues aspects, the umount issue manifested again in another way.
Describe how to reproduce the problem
10000 datasets under a single parent dataset, a recursive snapshot, then mount and unmount them until the trace below is shown in dmesg.
Include any warning/errors/backtraces from the system logs