Bug #8857
closed
zio_remove_child() panic due to already destroyed parent zio
100%
Description
This is the e-mail I posted to the mailing list:
I had an OS panic on one of our servers:
ffffff01809128c0 vpanic()
ffffff01809128e0 mutex_panic+0x58(fffffffffb94c904, ffffff597dde7f80)
ffffff0180912950 mutex_vector_enter+0x347(ffffff597dde7f80)
ffffff01809129b0 zio_remove_child+0x50(ffffff597dde7c58, ffffff32bd901ac0,
ffffff3373370908)
ffffff0180912a40 zio_done+0x390(ffffff32bd901ac0)
ffffff0180912a70 zio_execute+0x78(ffffff32bd901ac0)
ffffff0180912b30 taskq_thread+0x2d0(ffffff33bae44140)
ffffff0180912b40 thread_start+8()
It panicked here:
http://src.illumos.org/source/xref/illumos-gate/usr/src/uts/common/fs/zfs/zio.c#430
pio->io_lock is DEAD, thus a panic. Further analysis shows the "pio"
(parent zio of "cio") has already been destroyed.
How could this happen? Is this a known issue? Our server is running zfs
dated approx. Feb. 2016.
My crash dump analysis is pasted below. Please advise.
Thanks,
--Youzhong
=== panic stack and status ===
> $C
ffffff01809128c0 vpanic()
ffffff01809128e0 mutex_panic+0x58(fffffffffb94c904, ffffff597dde7f80)
ffffff0180912950 mutex_vector_enter+0x347(ffffff597dde7f80)
ffffff01809129b0 zio_remove_child+0x50(ffffff597dde7c58, ffffff32bd901ac0,
ffffff3373370908)
ffffff0180912a40 zio_done+0x390(ffffff32bd901ac0)
ffffff0180912a70 zio_execute+0x78(ffffff32bd901ac0)
ffffff0180912b30 taskq_thread+0x2d0(ffffff33bae44140)
ffffff0180912b40 thread_start+8()
> ::status
debugging crash dump vmcore.2 (64-bit) from batfs0390
operating system: 5.11 joyent_20170911T171900Z (i86pc)
image uuid: (not set)
panic message: mutex_enter: bad mutex, lp=ffffff597dde7f80
owner=ffffff3c59b39480 thread=ffffff0180912c40
dump content: kernel pages only
=== bad parent zio ffffff597dde7c58 ===
> ffffff597dde7c58::zio -c -p -r
ADDRESS TYPE STAGE WAITER TIME_ELAPSED
ffffff597dde7c58 NULL DONE - -
mdb: failed to read list element at 0xffffffffffffffe0: no mapping for
address
=== child zio ffffff32bd901ac0 ===
> ffffff32bd901ac0::zio -c -p -r
ADDRESS TYPE STAGE WAITER TIME_ELAPSED
ffffff32bd901ac0 READ DONE - 134909ms
> ffffff32bd901ac0::print -at zio_t io_stage
ffffff32bd901d3c enum zio_stage io_stage = 0x200000 (ZIO_STAGE_DONE)
=== already dead mutex caused panic ===
> ffffff597dde7c58::print -at zio_t io_lock
ffffff597dde7f80 kmutex_t io_lock = {
ffffff597dde7f80 void *[1] io_lock._opaque = [ 0xffffff3c59b39486 ]
}
> ffffff597dde7f80::print -at mutex_impl_t
ffffff597dde7f80 mutex_impl_t {
ffffff597dde7f80 struct adaptive_mutex m_adaptive = {
ffffff597dde7f80 uintptr_t _m_owner = 0xffffff3c59b39486
}
ffffff597dde7f80 struct spin_mutex m_spin = {
ffffff597dde7f80 lock_t m_dummylock = 0x86
ffffff597dde7f81 lock_t m_spinlock = 0x94
ffffff597dde7f82 ushort_t m_filler = 0x59b3
ffffff597dde7f84 ushort_t m_oldspl = 0xff3c
ffffff597dde7f86 ushort_t m_minspl = 0xffff
}
}
> 0xffffff3c59b39480::findstack -v
stack pointer for thread ffffff3c59b39480: ffffff01a1d9eaa0
[ ffffff01a1d9eaa0 _resume_from_idle+0x112() ]
ffffff01a1d9ead0 swtch+0x141()
ffffff01a1d9eaf0 preempt+0xec()
ffffff01a1d9eb20 kpreempt+0x98(1)
ffffff01a1d9eb50 sys_rtt_common+0x1ba(ffffff01a1d9eb60)
ffffff01a1d9eb60 _sys_rtt_ints_disabled+8()
ffffff01a1d9edc0 cstat64_32+0x10d(ffffff33a73cd340, 8045734, 0,
ffffff3af9e9c8a8)
ffffff01a1d9ee60 cstatat64_32+0x87(ffd19553, 8045bc4, 8045734, 1000, 0)
ffffff01a1d9ee90 fstatat64_32+0x42(ffd19553, 8045bc4, 8045734, 1000)
ffffff01a1d9eeb0 lstat64_32+0x25(8045bc4, 8045734)
ffffff01a1d9ef10 _sys_sysenter_post_swapgs+0x153()
> 0xffffff3c59b39480::thread -p
ADDR PROC LWP CRED
ffffff3c59b39480 ffffff3b41849000 ffffff56546f2780 ffffff3af9e9c8a8
> ffffff3b41849000::ps -fl
S PID PPID PGID SID UID FLAGS ADDR NAME
R 85767 85754 85754 85754 0 0x4a004000 ffffff3b41849000
rsync --stats -avHSgp --exclude=.snapshot/ --exclude=.nfs --exclude=.rsync
--de
L 0xffffff56546f2780 ID: 1
=== find parent zio of the child ===
> ffffff32bd901ac0::print -at zio_t io_parent_list io_walk_link
ffffff32bd901bb0 list_t io_parent_list = {
ffffff32bd901bb0 size_t io_parent_list.list_size = 0x30
ffffff32bd901bb8 size_t io_parent_list.list_offset = 0x10
ffffff32bd901bc0 struct list_node io_parent_list.list_head = {
ffffff32bd901bc0 struct list_node *list_next = 0xffffff3373370918
ffffff32bd901bc8 struct list_node *list_prev = 0xffffff3373370918
}
}
ffffff32bd901bf0 zio_link_t *io_walk_link = 0
> 0xffffff3373370918-0x10=J
ffffff3373370908
> ffffff3373370908::print -t zio_link_t zl_parent zl_child
zio_t *zl_parent = 0xffffff597dde7c58
zio_t *zl_child = 0xffffff32bd901ac0
> 0xffffff3373370918::print -at list_node_t list_next
ffffff3373370918 struct list_node *list_next = 0xffffff32bd901bc0
=== parent zio has already been destroyed ===
> ::walk zio_cache ! grep ffffff32bd901ac0
0xffffff32bd901ac0
> ::walk zio_cache ! grep ffffff597dde7c58
> ffffff597dde7c58::print -at zio_t
ffffff597dde7c58 zio_t {
ffffff597dde7c58 zbookmark_phys_t io_bookmark = {
ffffff597dde7c58 uint64_t zb_objset = 0
ffffff597dde7c60 uint64_t zb_object = 0
ffffff597dde7c68 int64_t zb_level = 0
ffffff597dde7c70 uint64_t zb_blkid = 0
}
ffffff597dde7c78 zio_prop_t io_prop = {
ffffff597dde7c78 enum zio_checksum zp_checksum = 0
(ZIO_CHECKSUM_INHERIT)
ffffff597dde7c7c enum zio_compress zp_compress = 0
(ZIO_COMPRESS_INHERIT)
ffffff597dde7c80 dmu_object_type_t zp_type = 0 (DMU_OT_NONE)
ffffff597dde7c84 uint8_t zp_level = 0
ffffff597dde7c85 uint8_t zp_copies = 0
ffffff597dde7c88 boolean_t zp_dedup = 0 (0)
ffffff597dde7c8c boolean_t zp_dedup_verify = 0 (0)
ffffff597dde7c90 boolean_t zp_nopwrite = 0 (0)
}
ffffff597dde7c94 zio_type_t io_type = 0 (ZIO_TYPE_NULL)
ffffff597dde7c98 enum zio_child io_child_type = 3 (ZIO_CHILD_LOGICAL)
ffffff597dde7c9c int io_cmd = 0
ffffff597dde7ca0 zio_priority_t io_priority = 6 (ZIO_PRIORITY_NOW)
ffffff597dde7ca4 uint8_t io_reexecute = 0
ffffff597dde7ca5 uint8_t [2] io_state = [ 0x1, 0x1 ]
ffffff597dde7ca8 uint64_t io_txg = 0
ffffff597dde7cb0 spa_t *io_spa = 0xffffff3355df5000
ffffff597dde7cb8 blkptr_t *io_bp = 0
ffffff597dde7cc0 blkptr_t *io_bp_override = 0
ffffff597dde7cc8 blkptr_t io_bp_copy = {
ffffff597dde7cc8 dva_t [3] blk_dva = [
ffffff597dde7cc8 dva_t {
ffffff597dde7cc8 uint64_t [2] dva_word = [ 0, 0 ]
},
ffffff597dde7cd8 dva_t {
ffffff597dde7cd8 uint64_t [2] dva_word = [ 0, 0 ]
},
ffffff597dde7ce8 dva_t {
ffffff597dde7ce8 uint64_t [2] dva_word = [ 0, 0 ]
},
]
ffffff597dde7cf8 uint64_t blk_prop = 0
ffffff597dde7d00 uint64_t [2] blk_pad = [ 0, 0 ]
ffffff597dde7d10 uint64_t blk_phys_birth = 0
ffffff597dde7d18 uint64_t blk_birth = 0
ffffff597dde7d20 uint64_t blk_fill = 0
ffffff597dde7d28 zio_cksum_t blk_cksum = {
ffffff597dde7d28 uint64_t [4] zc_word = [ 0, 0, 0, 0 ]
}
}
ffffff597dde7d48 list_t io_parent_list = {
ffffff597dde7d48 size_t list_size = 0x30
ffffff597dde7d50 size_t list_offset = 0x10
ffffff597dde7d58 struct list_node list_head = {
ffffff597dde7d58 struct list_node *list_next = 0
ffffff597dde7d60 struct list_node *list_prev = 0
}
}
ffffff597dde7d68 list_t io_child_list = {
ffffff597dde7d68 size_t list_size = 0x30
ffffff597dde7d70 size_t list_offset = 0x20
ffffff597dde7d78 struct list_node list_head = {
ffffff597dde7d78 struct list_node *list_next = 0
ffffff597dde7d80 struct list_node *list_prev = 0
}
}
ffffff597dde7d88 zio_link_t *io_walk_link = 0
ffffff597dde7d90 zio_t *io_logical = 0
ffffff597dde7d98 zio_transform_t *io_transform_stack = 0
ffffff597dde7da0 zio_done_func_t *io_ready = 0
ffffff597dde7da8 zio_done_func_t *io_physdone = 0
ffffff597dde7db0 zio_done_func_t *io_done = 0
ffffff597dde7db8 void *io_private = 0
ffffff597dde7dc0 int64_t io_prev_space_delta = 0
ffffff597dde7dc8 blkptr_t io_bp_orig = {
ffffff597dde7dc8 dva_t [3] blk_dva = [
ffffff597dde7dc8 dva_t {
ffffff597dde7dc8 uint64_t [2] dva_word = [ 0, 0 ]
},
ffffff597dde7dd8 dva_t {
ffffff597dde7dd8 uint64_t [2] dva_word = [ 0, 0 ]
},
ffffff597dde7de8 dva_t {
ffffff597dde7de8 uint64_t [2] dva_word = [ 0, 0 ]
},
]
ffffff597dde7df8 uint64_t blk_prop = 0
ffffff597dde7e00 uint64_t [2] blk_pad = [ 0, 0 ]
ffffff597dde7e10 uint64_t blk_phys_birth = 0
ffffff597dde7e18 uint64_t blk_birth = 0
ffffff597dde7e20 uint64_t blk_fill = 0
ffffff597dde7e28 zio_cksum_t blk_cksum = {
ffffff597dde7e28 uint64_t [4] zc_word = [ 0, 0, 0, 0 ]
}
}
ffffff597dde7e48 void *io_data = 0
ffffff597dde7e50 void *io_orig_data = 0
ffffff597dde7e58 uint64_t io_size = 0
ffffff597dde7e60 uint64_t io_orig_size = 0
ffffff597dde7e68 vdev_t *io_vd = 0
ffffff597dde7e70 void *io_vsd = 0
ffffff597dde7e78 const zio_vsd_ops_t *io_vsd_ops = 0
ffffff597dde7e80 uint64_t io_offset = 0
ffffff597dde7e88 hrtime_t io_timestamp = 0
ffffff597dde7e90 hrtime_t io_target_timestamp = 0
ffffff597dde7e98 hrtime_t io_dispatched = 0
ffffff597dde7ea0 avl_node_t io_queue_node = {
ffffff597dde7ea0 struct avl_node *[2] avl_child = [ 0, 0 ]
ffffff597dde7eb0 uintptr_t avl_pcb = 0
}
ffffff597dde7eb8 avl_node_t io_offset_node = {
ffffff597dde7eb8 struct avl_node *[2] avl_child = [ 0, 0 ]
ffffff597dde7ec8 uintptr_t avl_pcb = 0
}
ffffff597dde7ed0 enum zio_flag io_flags = 0x80 (ZIO_FLAG_CANFAIL)
ffffff597dde7ed4 enum zio_stage io_stage = 0x200000 (ZIO_STAGE_DONE)
ffffff597dde7ed8 enum zio_stage io_pipeline = 0x210000
(ZIO_STAGE_{READY|DONE})
ffffff597dde7edc enum zio_flag io_orig_flags = 0x80 (ZIO_FLAG_CANFAIL)
ffffff597dde7ee0 enum zio_stage io_orig_stage = 0x1 (ZIO_STAGE_OPEN)
ffffff597dde7ee4 enum zio_stage io_orig_pipeline = 0x210000
(ZIO_STAGE_{READY|DONE})
ffffff597dde7ee8 int io_error = 0
ffffff597dde7eec int [4] io_child_error = [ 0, 0, 0, 0 ]
ffffff597dde7f00 uint64_t [4][2] io_children = [
ffffff597dde7f00 uint64_t [2] [ 0, 0x1 ]
ffffff597dde7f10 uint64_t [2] [ 0, 0 ]
ffffff597dde7f20 uint64_t [2] [ 0, 0 ]
ffffff597dde7f30 uint64_t [2] [ 0, 0 ]
]
ffffff597dde7f40 uint64_t io_child_count = 0x1
ffffff597dde7f48 uint64_t io_phys_children = 0
ffffff597dde7f50 uint64_t io_parent_count = 0
ffffff597dde7f58 uint64_t *io_stall = 0
ffffff597dde7f60 zio_t *io_gang_leader = 0
ffffff597dde7f68 zio_gang_node_t *io_gang_tree = 0
ffffff597dde7f70 void *io_executor = 0xffffff3c59b39480
ffffff597dde7f78 void *io_waiter = 0
ffffff597dde7f80 kmutex_t io_lock = {
ffffff597dde7f80 void *[1] _opaque = [ 0xffffff3c59b39486 ]
}
ffffff597dde7f88 kcondvar_t io_cv = {
ffffff597dde7f88 ushort_t _opaque = 0
}
ffffff597dde7f90 zio_cksum_report_t *io_cksum_report = 0
ffffff597dde7f98 uint64_t io_ena = 0
ffffff597dde7fa0 zoneid_t io_zoneid = 0x2
ffffff597dde7fa8 taskq_ent_t io_tqent = {
ffffff597dde7fa8 struct taskq_ent *tqent_next = 0
ffffff597dde7fb0 struct taskq_ent *tqent_prev = 0
ffffff597dde7fb8 task_func_t *tqent_func = 0
ffffff597dde7fc0 void *tqent_arg = 0
ffffff597dde7fc8 union tqent_un = {
ffffff597dde7fc8 taskq_bucket_t *tqent_bucket = 0
ffffff597dde7fc8 uintptr_t tqent_flags = 0
}
ffffff597dde7fd0 kthread_t *tqent_thread = 0
ffffff597dde7fd8 kcondvar_t tqent_cv = {
ffffff597dde7fd8 ushort_t _opaque = 0
}
}
}
Updated by Shiva Bhanujan over 5 years ago
We have this crash on a daily basis in FreeBSD. The issue occurs when we turn on snapshot tranfers between 2 FreeBSD instances. Each instance is a VM running on XenServer 6.5 SP1.
In our current setup, the source Filer sends snapshots to the target Filer periodically, about 20-50 per day. The crash is quite reproducible, although not guaranteed to show up after X number of snapshots.
Setting the 'secondarycache' to 'metadata', as opposed to 'ALL' does prevent the frequent crashes. But obviously, the L2ARC isn't caching user data, as a result of which, reads end up on disk. ZFS performance w/o L2ARC is rather abysmal.
Restricting the secondarycache=metadata param setting to the ZFS where the snapshots are being received doesn't help this issue. FreeBSD still crashes w/ the same traceback.
zfs send -v -i <src><from_snap> <src><to_snap> | zfs receive -Fuvs <dst>
we're setting secondarycache on <dst>
zfs set secondarycache=metadata <dst>
Setting secondarycache to metadata on the entire pool makes the system prohibitively slower. this is a real showstopper for us, as we can't transfer snapshots for more than a day.
Updated by George Wilson over 5 years ago
- Assignee set to George Wilson
I've been testing a fix and have supplied a patch to Andriy to build on FreeBSD. Please let me know if the patch fixes your issue.
Updated by George Wilson over 5 years ago
Normally, consumers of the zio will create logical zios which then can create logical, gang, or vdev children. When a zio complete we perform this check in zio_done:
/*
* If our children haven't all completed,
* wait for them and then repeat this pipeline stage.
*/
if (zio_wait_for_children(zio, ZIO_CHILD_VDEV, ZIO_WAIT_DONE) ||
zio_wait_for_children(zio, ZIO_CHILD_GANG, ZIO_WAIT_DONE) ||
zio_wait_for_children(zio, ZIO_CHILD_DDT, ZIO_WAIT_DONE) ||
zio_wait_for_children(zio, ZIO_CHILD_LOGICAL, ZIO_WAIT_DONE))
return (ZIO_PIPELINE_STOP);
Each invocation will grab the io_lock and check to see if the io_children value for the specific chid type is 0. If it's not then it returns true and we stop the pipeline. In between each invocation, we drop and reacquire the io_lock. This works for most cases since we check the lowest level child type first which follows the typical model of creating a logical zio which then creates a child vdev zio. But what if the logical zio created a child vdev zio which then created a logical zio which then creates a child vdev zio. Normally this would look like this:
pio
|----- cio
|----- lio
|----- cio
In this tree the pio can't complete until the entire tree below it completes since at every level we will perform the check above (zio_wait_for_children()). What if we created the same set of children but use the same parent. The tree would look like this:
pio |----- cio |----- lio |----- cio
Again, the pio should not complete until all the children are finished. But what if the children in this last example weren't created at the same time but were created sequentially (i.e. as one completes the next child is created)? This is very rare case as it would require the callback of the child to create a new zio using the same parent zio. Interestingly, this only happens in one place:
/*
* Called when an indirect block above our prefetch target is read in. This
* will either read in the next indirect block down the tree or issue the actual
* prefetch if the next block down is our target.
*/
static void
dbuf_prefetch_indirect_done(zio_t *zio, arc_buf_t *abuf, void *private)
{
<snip>
arc_flags_t iter_aflags = ARC_FLAG_NOWAIT;
zbookmark_phys_t zb;
ASSERT3U(dpa->dpa_curlevel, ==, BP_GET_LEVEL(bp));
SET_BOOKMARK(&zb, dpa->dpa_zb.zb_objset,
dpa->dpa_zb.zb_object, dpa->dpa_curlevel, nextblkid);
(void) arc_read(dpa->dpa_zio, dpa->dpa_spa,
bp, dbuf_prefetch_indirect_done, dpa, dpa->dpa_prio,
ZIO_FLAG_CANFAIL | ZIO_FLAG_SPECULATIVE,
&iter_aflags, &zb);
}
In this case the dpa->dpa_zio is the parent I/O of the zio that just completed and called this callback. This would result in the scenario of a single parent with children that are added sequentially. Now this on its own is not a problem but it's the different children types that are created which causes a problem. In the example above, we created a child vdev zio, then a logical zio, then a child vdev zio. Why is that a problem? Here's the problematic scenario:
1. the pio reaches zio_done() and blocks waiting for the the child vdev zio to complete.
2. the child vdev zio, cio, reaches zio_done() and calls its callback which happens to be dbuf_prefetch_indirect_done()
3. the callback creates a logical zio using pio as the parent
So at this point the zio tree would look like this:
pio |----- cio |----- lio
4. Now the cio calls zio_notify_parent() which will decrement the io_children value and dispatch the pio to run again. Now the lio begins to run and cio exits and is destroyed. The zio tree now looks like this:
pio |----- lio
5. Now pio calls zio_wait_for_children(zio, ZIO_CHILD_VDEV, ZIO_WAIT_DONE). It grabs the io_lock and checks the io_children to see if there are any child vdev zios. As we see from the tree above, there aren't any. So it drops the io_lock and returns.
6. In the meantime, the lio has completed and call its callback, dbuf_prefetch_indirect_done()
7. The lio in its callback creates a new child vdev zio using the same pio
The zio tree now looks like this:
pio |----- lio |----- cio
8. the lio calls zio_notify_parent() which will decrement the io_children value. It doesn't dispatch pio since it's already running.
At this point the zio tree looks like this:
pio |----- cio
9. The pio continues to run (recall that is just completed calling zio_wait_for_children(zio, ZIO_CHILD_VDEV, ZIO_WAIT_DONE)) and had returned false. It then calls zio_wait_for_children(zio, ZIO_CHILD_GANG, ZIO_WAIT_DONE), which return false, then calls zio_wait_for_children(zio, ZIO_CHILD_DDT, ZIO_WAIT_DONE) which returns false, and finally calls zio_wait_for_children(zio, ZIO_CHILD_LOGICAL, ZIO_WAIT_DONE) which again returns false.
10. the pio now believes that all the children are complete and exits. Unfortunately, the cio created at step 7 is now a rogue torpedo that will result in the panic.
The next question is how do we create this funky looking zio tree? Enter into the scene an l2arc. This is the only way we can create this scenario since each l2arc read is a child vdev zio. In the scenario I painted above the logical flow would look like this:
- start to prefetch (creates pio)
- read an indirect and we find it in the l2arc (creates cio)
- read the next level which is not in the l2arc (creates lio)
- read the next level and it's in the l2arc (creates cio)
Disabling prefetch or l2arc should prevent this panic (unless I'm totally wrong in this analysis).
Updated by George Wilson over 5 years ago
Pull Request for openzfs has been posted: https://github.com/openzfs/openzfs/pull/505
Updated by Shiva Bhanujan over 5 years ago
Thanks to George for the patch. Patch has been applied to FreeBSD 10.3, and as of now, the patch does look promising. If FreeBSD stays up for a couple of days, I think we'd know for certain that this patch has addressed the crash.
Updated by Electric Monk about 5 years ago
- Status changed from New to Closed
- % Done changed from 0 to 100
git commit d6e1c446d7897003fd9fd36ef5aa7da350b7f6af
commit d6e1c446d7897003fd9fd36ef5aa7da350b7f6af
Author: George Wilson <george.wilson@delphix.com>
Date: 2018-02-13T20:40:28.000Z
8857 zio_remove_child() panic due to already destroyed parent zio
Reviewed by: Matthew Ahrens <mahrens@delphix.com>
Reviewed by: Andriy Gapon <avg@FreeBSD.org>
Reviewed by: Youzhong Yang <youzhong@gmail.com>
Approved by: Dan McDonald <danmcd@omniti.com>