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

PANIC at zvol.c:1165:zvol_resume() #6263

Closed
MyPod-zz opened this issue Jun 23, 2017 · 6 comments · Fixed by #8371
Closed

PANIC at zvol.c:1165:zvol_resume() #6263

MyPod-zz opened this issue Jun 23, 2017 · 6 comments · Fixed by #8371
Labels
Component: ZVOL ZFS Volumes
Milestone

Comments

@MyPod-zz
Copy link

System information

Type Version/Name
Distribution Name Debian
Distribution Version Stretch
Linux Kernel 4.9.30-2+deb9u1
Architecture amd64
ZFS Version 0.7.0-rc4_64_g0241e491a
SPL Version 0.7.0-rc4_4_gac48361

Describe the problem you're observing

While receiving a zvol from another machine, I obtained this:

[238797.610918] VERIFY3(zv->zv_objset->os_dsl_dataset->ds_owner == zv) failed (          (null) == ffff931c97dc3400)
[238797.612947] PANIC at zvol.c:1165:zvol_resume()
[238797.614940] Showing stack for process 10784
[238797.616951] CPU: 0 PID: 10784 Comm: zfs Tainted: G           O    4.9.0-3-amd64 #1 Debian 4.9.30-2+deb9u1
[238797.619117] Hardware name: Gigabyte Technology Co., Ltd. GA-78LMT-USB3 6.0/GA-78LMT-USB3 6.0, BIOS F2 11/25/2014
[238797.621219]  0000000000000000 ffffffff8dd286e4 ffffffffc0dcbfec ffffb083029079e0
[238797.623331]  ffffffffc052535b ffff931c78582140 ffffffff00000030 ffffb083029079f0
[238797.625468]  ffffb08302907990 2833594649524556 6f5f767a3e2d767a 6f3e2d7465736a62
[238797.627629] Call Trace:
[238797.629779]  [<ffffffff8dd286e4>] ? dump_stack+0x5c/0x78
[238797.631967]  [<ffffffffc052535b>] ? spl_panic+0xbb/0xf0 [spl]
[238797.634118]  [<ffffffff8e00380e>] ? mutex_lock+0xe/0x30
[238797.636379]  [<ffffffffc0cb1bd0>] ? rrw_exit+0x40/0x130 [zfs]
[238797.638516]  [<ffffffff8e00380e>] ? mutex_lock+0xe/0x30
[238797.640741]  [<ffffffffc0c79902>] ? dmu_objset_from_ds+0x62/0x140 [zfs]
[238797.642967]  [<ffffffffc0c79a53>] ? dmu_objset_hold+0x73/0xc0 [zfs]
[238797.645203]  [<ffffffffc0d3a2d8>] ? zvol_resume+0x108/0x1b0 [zfs]
[238797.647449]  [<ffffffffc0d073d8>] ? zfs_ioc_recv_impl+0x828/0x10a0 [zfs]
[238797.649726]  [<ffffffffc0d07e61>] ? zfs_ioc_recv+0x211/0x340 [zfs]
[238797.651991]  [<ffffffffc0cc82da>] ? spa_name_compare+0xa/0x20 [zfs]
[238797.654171]  [<ffffffffc01c1141>] ? avl_find+0x51/0x90 [zavl]
[238797.656408]  [<ffffffffc0cc717e>] ? spa_lookup+0x5e/0x80 [zfs]
[238797.658579]  [<ffffffff8dbdf99e>] ? __kmalloc+0x17e/0x560
[238797.660718]  [<ffffffff8dca2171>] ? security_capable+0x41/0x60
[238797.662876]  [<ffffffff8da80b33>] ? ns_capable_common+0x63/0x80
[238797.665121]  [<ffffffffc0cb08cd>] ? priv_policy.isra.1.part.2+0xd/0x20 [zfs]
[238797.667369]  [<ffffffffc0d052fe>] ? zfsdev_ioctl+0x73e/0x890 [zfs]
[238797.669555]  [<ffffffff8dbb384b>] ? handle_mm_fault+0xf7b/0x1390
[238797.671748]  [<ffffffff8dc161cf>] ? do_vfs_ioctl+0x9f/0x600
[238797.673943]  [<ffffffff8dc167a4>] ? SyS_ioctl+0x74/0x80
[238797.676131]  [<ffffffff8e00627b>] ? system_call_fast_compare_end+0xc/0x9b

Describe how to reproduce the problem

This seems to happen infrequently on zfs receive. I don't have a 100% way to reproduce it, but it has happened a few times and forced me to reboot the machine involved as the pool affected would become unresponsive (zfs and zpool commands becoming unresponsive, no I/O possible from VMs running on the same pool)

The command used was
zfs send -Rv mov/stretch-git@send | ssh root@192.168.2.7 zfs recv -uv data/virt/git
however I have had this happen even locally (between two different pools on the same machine)

If anything else is needed, I have not yet rebooted this system, but will have to soon.

@behlendorf
Copy link
Contributor

Potentially the locking changesin #6226 will resolve this although it's difficult to say for certain.

@MyPod-zz
Copy link
Author

MyPod-zz commented Jun 28, 2017

I have hit the same issue even with a more recent zfs version that includes that PR.

version: 0.7.0-rc4_75_g5b7bb9838

[72124.250848] VERIFY3(zv->zv_objset->os_dsl_dataset->ds_owner == zv) failed (          (null) == ffffa0e7bd485c00)
[72124.252046] PANIC at zvol.c:1165:zvol_resume()
[72124.253219] Showing stack for process 12608
[72124.254215] CPU: 5 PID: 12608 Comm: zfs Tainted: G        W  O    4.9.0-3-amd64 #1 Debian 4.9.30-2+deb9u1
[72124.255128] Hardware name: ASUS All Series/X99-DELUXE, BIOS 3701 03/30/2017
[72124.256026]  0000000000000000 ffffffff99b286e4 ffffffffc07a2fec ffffb9f0c8c779d0
[72124.256900]  ffffffffc03eb35b ffffa0e331b2a140 ffffffff00000030 ffffb9f0c8c779e0
[72124.257770]  ffffb9f0c8c77980 2833594649524556 6f5f767a3e2d767a 6f3e2d7465736a62
[72124.258633] Call Trace:
[72124.259457]  [<ffffffff99b286e4>] ? dump_stack+0x5c/0x78
[72124.260278]  [<ffffffffc03eb35b>] ? spl_panic+0xbb/0xf0 [spl]
[72124.261088]  [<ffffffff99e0380e>] ? mutex_lock+0xe/0x30
[72124.261888]  [<ffffffffc0688bd0>] ? rrw_exit+0x40/0x130 [zfs]
[72124.262658]  [<ffffffff99e0380e>] ? mutex_lock+0xe/0x30
[72124.263468]  [<ffffffffc0650902>] ? dmu_objset_from_ds+0x62/0x140 [zfs]
[72124.264265]  [<ffffffffc0650a53>] ? dmu_objset_hold+0x73/0xc0 [zfs]
[72124.265050]  [<ffffffffc07112d8>] ? zvol_resume+0x108/0x1b0 [zfs]
[72124.265819]  [<ffffffffc06de3d8>] ? zfs_ioc_recv_impl+0x828/0x10a0 [zfs]
[72124.266610]  [<ffffffffc06dee61>] ? zfs_ioc_recv+0x211/0x340 [zfs]
[72124.267402]  [<ffffffffc069f2da>] ? spa_name_compare+0xa/0x20 [zfs]
[72124.268166]  [<ffffffffc02db141>] ? avl_find+0x51/0x90 [zavl]
[72124.268959]  [<ffffffffc069e17e>] ? spa_lookup+0x5e/0x80 [zfs]
[72124.269699]  [<ffffffff999df99e>] ? __kmalloc+0x17e/0x560
[72124.270469]  [<ffffffff99aa2171>] ? security_capable+0x41/0x60
[72124.271215]  [<ffffffff99880b33>] ? ns_capable_common+0x63/0x80
[72124.271966]  [<ffffffffc06878cd>] ? priv_policy.isra.1.part.2+0xd/0x20 [zfs]
[72124.272712]  [<ffffffffc06dc2fe>] ? zfsdev_ioctl+0x73e/0x890 [zfs]
[72124.273440]  [<ffffffff99a161cf>] ? do_vfs_ioctl+0x9f/0x600
[72124.274160]  [<ffffffff9991e95d>] ? __audit_syscall_entry+0xad/0xf0
[72124.274869]  [<ffffffff99803441>] ? syscall_trace_enter+0x1b1/0x2c0
[72124.275590]  [<ffffffff99a167a4>] ? SyS_ioctl+0x74/0x80
[72124.276319]  [<ffffffff99803b1c>] ? do_syscall_64+0x7c/0xf0
[72124.277068]  [<ffffffff99e0632f>] ? entry_SYSCALL64_slow_path+0x25/0x25

Edit: zpool status didn't stall either time, zfs commands affecting the pool did though. The pools were reported as online.

@behlendorf
Copy link
Contributor

@MyPod thanks for posting. We should get @tuxoko and @bprotopopov's thoughts on this.

@bprotopopov
Copy link
Contributor

bprotopopov commented Jul 11, 2017

I took a look at the code, and I believe the locks are held across suspend/resume properly, such that a suspended zvol cannot be disowned as a result of zvol_last_close(). By code analysis, it appears that if a zvol is suspended with zv_open_count of 0, then it cannot be resumed with zv_open_count > 0 because the zv_first_open() is called with zv_suspend_lock held (there are assertions to that affect). So, it might be possible that the ownership tag is being reset by some code other than the proper owner. Perhaps it would be helpful to run with ASSERT()s enabled ?

Also, while reviewing the zvol_open() and zvol_release() code, I found that these functions might take zv_suspend_lock needlessly (although for a very brief time); this might result in interference with zvol suspend/resume (hangs when opening/closing zvols with zv_open_count > 0), and it is not hard to refine, I believe. Hopefully, by improving open()/close() concurrency, the issue reported here might be more readily reproducible. I'll post a PR with the fix.

@bprotopopov
Copy link
Contributor

@MyPod can you please describe the structure of the filesystem that you are replicating, in particular, w.r.t. zvols ?

@MyPod-zz
Copy link
Author

MyPod-zz commented Jul 12, 2017

in the first case, the sending side had several zvols under mov/, used for testing purposes. The receiving side has zvols in data/virt/*. The sending zpool is used exclusively for VM zvols, the receiving side has also a few NFS shares (that don't use the zfs share feature) and other miscellaneous datasets i.e. for /srv and /home.
In the second case, the source pool was another testing-purposed zpool created similarly to the first case, with only zvols under staging/. The receiving side was a zpool on the same machine, with zvols under vz/*. I don't think it had datasets, but can't check as that system is not currently available to me.

For zvols, the only parameters that is set is volblocksize, to 8K. The pool themselves have the following properties deviating from the default values:

data  ashift                         12                             local
data  feature@async_destroy          enabled                        local
data  feature@empty_bpobj            active                         local
data  feature@lz4_compress           active                         local
data  feature@multi_vdev_crash_dump  disabled                       local
data  feature@spacemap_histogram     active                         local
data  feature@enabled_txg            active                         local
data  feature@hole_birth             disabled                       local
data  feature@extensible_dataset     enabled                        local
data  feature@embedded_data          active                         local
data  feature@bookmarks              enabled                        local
data  feature@filesystem_limits      enabled                        local
data  feature@large_blocks           enabled                        local
data  feature@large_dnode            disabled                       local
data  feature@sha512                 disabled                       local
data  feature@skein                  disabled                       local
data  feature@edonr                  disabled                       local
data  feature@userobj_accounting     disabled                       local

data  mountpoint            /mnt/zfs               local
data  checksum              sha256                 local
data  compression           lz4                    local
data  atime                 off                    local
data  canmount              off                    local
data  xattr                 sa                     local
data  primarycache          metadata               local

Sample zvol:

data/virt/git  type                  volume                 -
data/virt/git  creation              Wed Jun 21  6:35 2017  -
data/virt/git  used                  46.1G                  -
data/virt/git  available             1.53T                  -
data/virt/git  referenced            4.57G                  -
data/virt/git  compressratio         1.27x                  -
data/virt/git  reservation           none                   default
data/virt/git  volsize               40G                    local
data/virt/git  volblocksize          8K                     default
data/virt/git  checksum              sha256                 inherited from data
data/virt/git  compression           lz4                    inherited from data
data/virt/git  readonly              off                    default
data/virt/git  createtxg             148                    -
data/virt/git  copies                1                      default
data/virt/git  refreservation        41.3G                  received
data/virt/git  guid                  3150058532176053808    -
data/virt/git  primarycache          metadata               inherited from data
data/virt/git  secondarycache        all                    default
data/virt/git  usedbysnapshots       301M                   -
data/virt/git  usedbydataset         4.57G                  -
data/virt/git  usedbychildren        0B                     -
data/virt/git  usedbyrefreservation  41.3G                  -
data/virt/git  logbias               latency                default
data/virt/git  dedup                 off                    default
data/virt/git  mlslabel              none                   default
data/virt/git  sync                  standard               default
data/virt/git  refcompressratio      1.26x                  -
data/virt/git  written               0                      -
data/virt/git  logicalused           6.17G                  -
data/virt/git  logicalreferenced     5.74G                  -
data/virt/git  snapshot_limit        none                   default
data/virt/git  snapshot_count        none                   default
data/virt/git  snapdev               hidden                 default
data/virt/git  context               none                   default
data/virt/git  fscontext             none                   default
data/virt/git  defcontext            none                   default
data/virt/git  rootcontext           none                   default
data/virt/git  redundant_metadata    all                    default

All the zvols were pretty small at the time they were sent, being fresh installations of minimal Debian Jessie/Stretch, so 1-5GB each

@loli10K loli10K added the Component: ZVOL ZFS Volumes label Nov 18, 2017
@behlendorf behlendorf added this to the 0.8.0 milestone Feb 6, 2019
behlendorf pushed a commit that referenced this issue Feb 22, 2019
While ZFS allow renaming of in use ZVOLs at the DSL level without issues
the ZVOL layer does not correctly update the renamed dataset if the
device node is open (zv->zv_open_count > 0): trying to access the stale
dataset name, for instance during a zfs receive, will cause the
following failure:

VERIFY3(zv->zv_objset->os_dsl_dataset->ds_owner == zv) failed ((null) == ffff8800dbb6fc00)
PANIC at zvol.c:1255:zvol_resume()
Showing stack for process 1390
CPU: 0 PID: 1390 Comm: zfs Tainted: P           O  3.16.0-4-amd64 #1 Debian 3.16.51-3
Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
 0000000000000000 ffffffff8151ea00 ffffffffa0758a80 ffff88028aefba30
 ffffffffa0417219 ffff880037179220 ffffffff00000030 ffff88028aefba40
 ffff88028aefb9e0 2833594649524556 6f5f767a3e2d767a 6f3e2d7465736a62
Call Trace:
 [<0>] ? dump_stack+0x5d/0x78
 [<0>] ? spl_panic+0xc9/0x110 [spl]
 [<0>] ? mutex_lock+0xe/0x2a
 [<0>] ? zfs_refcount_remove_many+0x1ad/0x250 [zfs]
 [<0>] ? rrw_exit+0xc8/0x2e0 [zfs]
 [<0>] ? mutex_lock+0xe/0x2a
 [<0>] ? dmu_objset_from_ds+0x9a/0x250 [zfs]
 [<0>] ? dmu_objset_hold_flags+0x71/0xc0 [zfs]
 [<0>] ? zvol_resume+0x178/0x280 [zfs]
 [<0>] ? zfs_ioc_recv_impl+0x88b/0xf80 [zfs]
 [<0>] ? zfs_refcount_remove_many+0x1ad/0x250 [zfs]
 [<0>] ? zfs_ioc_recv+0x1c2/0x2a0 [zfs]
 [<0>] ? dmu_buf_get_user+0x13/0x20 [zfs]
 [<0>] ? __alloc_pages_nodemask+0x166/0xb50
 [<0>] ? zfsdev_ioctl+0x896/0x9c0 [zfs]
 [<0>] ? handle_mm_fault+0x464/0x1140
 [<0>] ? do_vfs_ioctl+0x2cf/0x4b0
 [<0>] ? __do_page_fault+0x177/0x410
 [<0>] ? SyS_ioctl+0x81/0xa0
 [<0>] ? async_page_fault+0x28/0x30
 [<0>] ? system_call_fast_compare_end+0x10/0x15

Reviewed by: Tom Caputi <tcaputi@datto.com>
Reviewed-by: Brian Behlendorf <behlendorf1@llnl.gov>
Signed-off-by: loli10K <ezomori.nozomu@gmail.com>
Closes #6263 
Closes #8371
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Component: ZVOL ZFS Volumes
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants