SPLError: 1121:0:(dnode_sync.c:484:dnode_sync_free()) VERIFY3(dn->dn_bonus == ((void *)0)) failed (ffff880812c9f1c0 =

[seletskiy]

zfs recv and zfs snapshot workload caused this to happend.

SPLError: 1121:0:(dnode_sync.c:484:dnode_sync_free()) VERIFY3(dn->dn_bonus == ((void *)0)) failed (ffff880812c9f1c0 ==
SPLError: 1121:0:(dnode_sync.c:484:dnode_sync_free()) SPL PANIC
SPL: Showing stack for process 1121
CPU: 5 PID: 1121 Comm: txg_sync Tainted: P           O  3.16.1-1-apparmor #1
Hardware name: Cisco Systems Inc R200-1120402W/R200-1120402W, BIOS C200.1.4.1.0.071320110702 07/13/2011
 0000000000000000 000000004506b11a ffff88008604f990 ffffffff81547eac
 0000000000000000 ffff88008604f9a0 ffffffffa01e5897 ffff88008604f9c8
 ffffffffa01e6b10 ffffffffa01fbd21 ffffc9003a22cfa0 0000000000000002
Call Trace:
 [<ffffffff81547eac>] dump_stack+0x4d/0x6f
 [<ffffffffa01e5897>] spl_debug_dumpstack+0x27/0x40 [spl]
 [<ffffffffa01e6b10>] spl_debug_bug+0x80/0xe0 [spl]
 [<ffffffffa0427193>] dnode_sync+0x1f13/0x2300 [zfs]
 [<ffffffffa0425c9f>] ? dnode_sync+0xa1f/0x2300 [zfs]
 [<ffffffffa04de1c1>] ? zio_write+0x111/0x1c0 [zfs]
 [<ffffffffa040aaa5>] dmu_objset_sync_dnodes+0xc5/0x2c0 [zfs]
 [<ffffffffa040aeae>] dmu_objset_sync+0x20e/0x580 [zfs]
 [<ffffffffa0407bd0>] ? primary_cache_changed_cb+0x80/0x80 [zfs]
 [<ffffffffa040b220>] ? dmu_objset_sync+0x580/0x580 [zfs]
 [<ffffffffa043b936>] dsl_pool_sync+0x476/0x7c0 [zfs]
 [<ffffffffa045eea5>] spa_sync+0x435/0xdb0 [zfs]
 [<ffffffff810da948>] ? ktime_get_ts+0x48/0xf0
 [<ffffffffa0476e0f>] txg_sync_thread+0x3af/0x710 [zfs]
 [<ffffffffa0476a60>] ? txg_thread_wait+0x120/0x120 [zfs]
 [<ffffffffa01ee2ca>] thread_generic_wrapper+0x7a/0x90 [spl]
 [<ffffffffa01ee250>] ? __thread_exit+0xa0/0xa0 [spl]
 [<ffffffff81091eca>] kthread+0xea/0x100
 [<ffffffff81091de0>] ? kthread_create_on_node+0x1b0/0x1b0
 [<ffffffff8154db7c>] ret_from_fork+0x7c/0xb0
 [<ffffffff81091de0>] ? kthread_create_on_node+0x1b0/0x1b0

After that stacktrace system becomes unstable and I see following stacktraces (multiple times, so it's probably not a deadlock):

INFO: task txg_sync:1121 blocked for more than 120 seconds.
      Tainted: P           O  3.16.1-1-apparmor #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
txg_sync        D 0000000000000005     0  1121      2 0x00000000
 ffff88008604f990 0000000000000046 ffff8808365ebd20 00000000000145c0
 ffff88008604ffd8 00000000000145c0 ffff8808365ebd20 ffff88008604f978
 ffff88008604f8f8 ffffffff8101898d ffff88008604f9c0 0000000000000000
Call Trace:
 [<ffffffff8101898d>] ? show_trace_log_lvl+0x4d/0x60
 [<ffffffff810175af>] ? show_stack_log_lvl+0xaf/0x1c0
 [<ffffffff81549d79>] schedule+0x29/0x70
 [<ffffffffa01e6b45>] spl_debug_bug+0xb5/0xe0 [spl]
 [<ffffffffa0427193>] dnode_sync+0x1f13/0x2300 [zfs]
 [<ffffffffa0425c9f>] ? dnode_sync+0xa1f/0x2300 [zfs]
 [<ffffffffa04de1c1>] ? zio_write+0x111/0x1c0 [zfs]
 [<ffffffffa040aaa5>] dmu_objset_sync_dnodes+0xc5/0x2c0 [zfs]
 [<ffffffffa040aeae>] dmu_objset_sync+0x20e/0x580 [zfs]
 [<ffffffffa0407bd0>] ? primary_cache_changed_cb+0x80/0x80 [zfs]
 [<ffffffffa040b220>] ? dmu_objset_sync+0x580/0x580 [zfs]
 [<ffffffffa043b936>] dsl_pool_sync+0x476/0x7c0 [zfs]
 [<ffffffffa045eea5>] spa_sync+0x435/0xdb0 [zfs]
 [<ffffffff810da948>] ? ktime_get_ts+0x48/0xf0
 [<ffffffffa0476e0f>] txg_sync_thread+0x3af/0x710 [zfs]
 [<ffffffffa0476a60>] ? txg_thread_wait+0x120/0x120 [zfs]
 [<ffffffffa01ee2ca>] thread_generic_wrapper+0x7a/0x90 [spl]
 [<ffffffffa01ee250>] ? __thread_exit+0xa0/0xa0 [spl]
 [<ffffffff81091eca>] kthread+0xea/0x100
 [<ffffffff81091de0>] ? kthread_create_on_node+0x1b0/0x1b0
 [<ffffffff8154db7c>] ret_from_fork+0x7c/0xb0
 [<ffffffff81091de0>] ? kthread_create_on_node+0x1b0/0x1b0
INFO: task zfs:3666 blocked for more than 120 seconds.
      Tainted: P           O  3.16.1-1-apparmor #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
zfs             D 0000000000000004     0  3666   2492 0x00000000
 ffff8808135d3c18 0000000000000082 ffff8803e18b7010 00000000000145c0
 ffff8808135d3fd8 00000000000145c0 ffff8803e18b7010 0000000000000005
 ffff8808135d3b88 ffffffff8109ca1e 00000000135d3b68 ffff8808365ebd20
Call Trace:
 [<ffffffff8109ca1e>] ? ttwu_stat+0x9e/0x110
 [<ffffffff810a2cdf>] ? try_to_wake_up+0x1ff/0x380
 [<ffffffff81549d79>] schedule+0x29/0x70
 [<ffffffffa01f61d5>] cv_wait_common+0x125/0x1b0 [spl]
 [<ffffffff810b6d10>] ? __wake_up_sync+0x20/0x20
 [<ffffffffa01f6275>] __cv_wait+0x15/0x20 [spl]
 [<ffffffffa0476303>] txg_wait_synced+0xe3/0x2b0 [zfs]
 [<ffffffffa04f5ff0>] ? dsl_destroy_head_check_impl+0x130/0x130 [zfs]
 [<ffffffffa04459be>] dsl_sync_task+0x16e/0x2b0 [zfs]
 [<ffffffffa0499ea6>] ? zap_lookup_norm+0xe6/0x1c0 [zfs]
 [<ffffffffa04f5dc0>] ? dsl_destroy_head_sync_impl+0x13e0/0x13e0 [zfs]
 [<ffffffffa04f5ff0>] ? dsl_destroy_head_check_impl+0x130/0x130 [zfs]
 [<ffffffffa04f5dc0>] ? dsl_destroy_head_sync_impl+0x13e0/0x13e0 [zfs]
 [<ffffffffa04f324c>] dsl_destroy_head+0xec/0x170 [zfs]
 [<ffffffffa01edd06>] ? strdup+0x106/0x110 [spl]
 [<ffffffffa04b2a40>] zfs_ioc_destroy+0x70/0x90 [zfs]
 [<ffffffffa04b3269>] zfsdev_ioctl+0x4e9/0x570 [zfs]
 [<ffffffff810b683d>] ? remove_wait_queue+0x4d/0x60
 [<ffffffff811e1480>] do_vfs_ioctl+0x2d0/0x4b0
 [<ffffffff81071886>] ? SyS_wait4+0x86/0x100
 [<ffffffff811e16e1>] SyS_ioctl+0x81/0xa0
 [<ffffffff8154dc29>] system_call_fastpath+0x16/0x1b

Using zfs 0.6.3.

[behlendorf]

@seletskiy You've hit an assertion in the code which by design basically halts the thread for further debugging. Normally these are disabled in production builds but you've clearly enabled them. In this case the ASSERT looks like it's uncovered a subtle inconsistency in the code.

The dnode_evict_dbufs() function is written to handle the case when a dnode's bonus buffer can still be in use and have an reference. However, the caller dnode_sync_free() uses an ASSERT to make it explicit that when dnode_evict_dbufs() returns dn->dn_bonus == NULL.

Someone will need to spend some time with the code to determine if these is a real issue here or if the assertion is just wrong. But after a quick glance I suspect the ASSERT is just wrong. There may still be remaining holds on the bonus block and dnodes which would cause this. The XXX comment in dnode_sync_free() says as much. My suggestion would be to comment out the ASSERT for now or just build without debugging.

SPLError: 1121:0:(dnode_sync.c:484:dnode_sync_free()) VERIFY3(dn->dn_bonus == ((void *)0)) failed (ffff880812c9f1c0 ==
dnode_sync+0x1f13/0x2300 [zfs]
dmu_objset_sync_dnodes+0xc5/0x2c0 [zfs]
dmu_objset_sync+0x20e/0x580 [zfs]
dsl_pool_sync+0x476/0x7c0 [zfs]
spa_sync+0x435/0xdb0 [zfs]
...

[seletskiy]

@behlendorf: Thanks for the answer!

Yep, we are using debug version on some of the servers (maybe it will bring some good for the project).

I've came to the similar conclusions regarding dn_bonus field, but without prior knowledge of the domain area it's difficult to debug it down to the roots. So, yes, we are disabling debug on this particular server, but if I can do something to reveal cause of the issue, please, let me know (it appears to be reproduceable with some effort).

[behlendorf]

@seletskiy I think the debugging provides us enough to go on. We just need to determine how we should reconcile this inconsistency in the code.

[seletskiy]

I think there is a bug and assertion is correct.

We are doing some heavy zfs send | zfs recv operation which completes in about of 30 minutes.
After reverting to non-debug build and running same operations as before we've got same error in userspace as before ("cannot restore to zdata/mysql@blahblah: destination already exists") at the end of receive operation (approximately after 30 minutes from start). And no trace in kernel log (obviously).

But there is a problem. Inspecting zfs list -t all shows that there is no snapshot with that name (like with debug build). Running zfs destroy zdata/mysql cause ZFS to lockup on debug build but runs fine on non-debug.

It's still unclear why ZFS complaining about already exist snapshot on the end of recieve operation (looks like invalid order of commiting changes for me).

[seletskiy]

Oh, sorry. I think you can ignore my latest comment on this issue. Looks like this userspace error and that stacktrace are not linked together. Please, see: #2739.

[nedbass]

I throw in a "me too". I hit this assertion during some Lustre testing. I took a snapshot of the Lustre MDT, wrote some files to the Lustre filesystem, unmounted Lustre, rolled back the MDT to the snapshot, restarted Lustre, and crashed:

SPLError: 1239:0:(dnode_sync.c:484:dnode_sync_free()) VERIFY3(dn->dn_bonus == ((void *)0)) failed (ffff88004a64ef70 == (null))
SPLError: 1239:0:(dnode_sync.c:484:dnode_sync_free()) SPL PANIC
SPL: Showing stack for process 1239
Pid: 1239, comm: txg_sync Tainted: P           ---------------    2.6.32-431.23.3.1chaos.ch5.2.x86_64 #1
Call Trace:
 [<ffffffffa02e5657>] ? spl_debug_dumpstack+0x27/0x40 [spl]
 [<ffffffffa02e6db1>] ? spl_debug_bug+0x81/0xd0 [spl]
 [<ffffffffa02f664a>] ? spl_PANIC+0xba/0xf0 [spl]
 [<ffffffffa04057a4>] ? dnode_diduse_space+0x114/0x350 [zfs]
 [<ffffffff8152cf91>] ? mutex_lock+0x31/0x60
 [<ffffffffa043281f>] ? refcount_remove_many+0x14f/0x220 [zfs]
 [<ffffffffa0432906>] ? refcount_remove+0x16/0x20 [zfs]
 [<ffffffffa040c728>] ? dnode_undirty_dbufs+0xb8/0x1d0 [zfs]
 [<ffffffffa040db98>] ? dnode_sync_free+0xe8/0x380 [zfs]
 [<ffffffffa040ee5b>] ? dnode_sync+0x102b/0x1a20 [zfs]
 [<ffffffffa040e844>] ? dnode_sync+0xa14/0x1a20 [zfs]
 [<ffffffffa0432538>] ? refcount_add_many+0x88/0x140 [zfs]
 [<ffffffffa03f6b07>] ? dmu_objset_sync_dnodes+0x77/0x1d0 [zfs]
 [<ffffffffa03f6e0d>] ? dmu_objset_sync+0x1ad/0x4c0 [zfs]
 [<ffffffffa03f4160>] ? dmu_objset_write_ready+0x0/0x100 [zfs]
 [<ffffffffa03f5500>] ? dmu_objset_write_done+0x0/0x150 [zfs]
 [<ffffffffa04aed0a>] ? zio_create+0x4ba/0x760 [zfs]
 [<ffffffffa0410d91>] ? dsl_dataset_sync+0x71/0x110 [zfs]
 [<ffffffffa04204e1>] ? dsl_pool_sync+0xe1/0x630 [zfs]
 [<ffffffffa0439d4b>] ? spa_sync+0x44b/0xc40 [zfs]
 [<ffffffff8103f9d8>] ? pvclock_clocksource_read+0x58/0xd0
 [<ffffffffa0453aec>] ? txg_sync_thread+0x39c/0x6b0 [zfs]
 [<ffffffff810592b9>] ? set_user_nice+0xc9/0x130
 [<ffffffffa0453750>] ? txg_sync_thread+0x0/0x6b0 [zfs]
 [<ffffffffa02efcb1>] ? thread_generic_wrapper+0x71/0xb0 [spl]
 [<ffffffffa02efc40>] ? thread_generic_wrapper+0x0/0xb0 [spl]
 [<ffffffff8109b4d6>] ? kthread+0x96/0xa0
 [<ffffffff8100c24a>] ? child_rip+0xa/0x20
 [<ffffffff8109b440>] ? kthread+0x0/0xa0
 [<ffffffff8100c240>] ? child_rip+0x0/0x20

[ofaaland]

I encountered this ASSERT while running the lustre sanity test 22: unpack tar archive as non-root user.

SPLError: 14243:0:(dnode_sync.c:484:dnode_sync_free()) VERIFY3(dn->dn_bonus == ((void *)0)) failed (ffff88000becf2d0 == (null))
SPLError: 14243:0:(dnode_sync.c:484:dnode_sync_free()) SPL PANIC
SPL: Showing stack for process 14243
Pid: 14243, comm: txg_sync Tainted: P           ---------------    2.6.32-431.29.2.1chaos.ch5.2.x86_64 #1
Call Trace:
 [<ffffffffa0190657>] ? spl_debug_dumpstack+0x27/0x40 [spl]
 [<ffffffffa0191db1>] ? spl_debug_bug+0x81/0xd0 [spl]
 [<ffffffffa02c7cd4>] ? dnode_sync+0xe24/0x1910 [zfs]
 [<ffffffff8152d1a1>] ? mutex_lock+0x31/0x60
 [<ffffffffa02c78a9>] ? dnode_sync+0x9f9/0x1910 [zfs]
 [<ffffffffa02bd23d>] ? dnode_add_ref+0x7d/0x160 [zfs]
 [<ffffffffa02acf87>] ? dmu_objset_sync_dnodes+0x77/0x270 [zfs]
 [<ffffffffa02ad32d>] ? dmu_objset_sync+0x1ad/0x540 [zfs]
 [<ffffffffa02a8e10>] ? dmu_objset_write_ready+0x0/0x180 [zfs]
 [<ffffffffa02aa470>] ? dmu_objset_write_done+0x0/0x170 [zfs]
 [<ffffffffa02ca011>] ? dsl_dataset_sync+0x71/0x160 [zfs]
 [<ffffffffa02dc1cc>] ? dsl_pool_sync+0xfc/0x730 [zfs]
 [<ffffffffa037ea4d>] ? zio_wait+0x24d/0x4c0 [zfs]
 [<ffffffffa02f8fb3>] ? spa_sync+0x473/0xd70 [zfs]
 [<ffffffff8103f9d8>] ? pvclock_clocksource_read+0x58/0xd0
 [<ffffffffa0316bcc>] ? txg_sync_thread+0x39c/0x6f0 [zfs]
 [<ffffffff810592b9>] ? set_user_nice+0xc9/0x130
 [<ffffffffa0316830>] ? txg_sync_thread+0x0/0x6f0 [zfs]
 [<ffffffffa019b691>] ? thread_generic_wrapper+0x71/0xd0 [spl]
 [<ffffffffa019b620>] ? thread_generic_wrapper+0x0/0xd0 [spl]
 [<ffffffff8109b4d6>] ? kthread+0x96/0xa0
 [<ffffffff8100c24a>] ? child_rip+0xa/0x20
 [<ffffffff8109b440>] ? kthread+0x0/0xa0
 [<ffffffff8100c240>] ? child_rip+0x0/0x20
SPLError: 14628:0:(dnode_sync.c:484:dnode_sync_free()) VERIFY3(dn->dn_bonus == ((void *)0)) failed (ffff88000e5252d0 == (null))

[ofaaland]

Crash's version of the above stack, cleaned up

PID: 14243 TASK: ffff8800269ecae0 CPU: 0 COMMAND: "txg_sync"
#0 [ffff880020983890] schedule at ffffffff8152bb00
#1 [ffff880020983958] spl_debug_bug at ffffffffa0191dd5 [spl]
#2 [ffff880020983988] dnode_sync at ffffffffa02c7cd4 [zfs]
#3 [ffff880020983a88] dmu_objset_sync_dnodes at ffffffffa02acf87 [zfs]
#4 [ffff880020983af8] dmu_objset_sync at ffffffffa02ad32d [zfs]
#5 [ffff880020983be8] dsl_dataset_sync at ffffffffa02ca011 [zfs]
#6 [ffff880020983c28] dsl_pool_sync at ffffffffa02dc1cc [zfs]
#7 [ffff880020983cc8] spa_sync at ffffffffa02f8fb3 [zfs]
#8 [ffff880020983da8] txg_sync_thread at ffffffffa0316bcc [zfs]
#9 [ffff880020983ea8] thread_generic_wrapper at ffffffffa019b691 [spl]
#10 [ffff880020983ee8] kthread at ffffffff8109b4d6
#11 [ffff880020983f48] kernel_thread at ffffffff8100c24a

[ofaaland]

More information from the sanity test 22 instance above:

dnode_sync stack frame:

 #2 [ffff880020983988] dnode_sync at ffffffffa02c7cd4 [zfs]
    ffff880020983990: ffffffffa03b0fc8 ffff88000becf2d0
    ffff8800209839a0: 0000000000000000 ffffffff8152d1a1
    ffff8800209839b0: ffffc9000be1a310 0000000000000001
    ffff8800209839c0: ffff880020983a20 ffff8800269ecae0
    ffff8800209839d0: 0000000000000000 ffff8800269ecae0
    ffff8800209839e0: ffffc9000ac89400 ffffc9000be1a100
    ffff8800209839f0: ffff880020983af0 ffffffffa02c78a9
    ffff880020983a00: 0000000000000000 ffffc9000be1a188
    ffff880020983a10: ffff880017337d40 ffffc9000be1a0e8
    ffff880020983a20: 0000000120983a30 0000000000000001
    ffff880020983a30: ffffc9000be19ff8 ffffffffa02bd23d
    ffff880020983a40: 0000000000020000 ffff8800269ecae0
    ffff880020983a50: ffffc90001fedc00 ffffc9000be19ff0
    ffff880020983a60: ffff8800185823a8 ffff8800185822b8
    ffff880020983a70: ffff8800185823b8 ffff880017337d40
    ffff880020983a80: ffff880020983af0 ffffffffa02acf87

dnode passed to dnode_sync(); note the dn_zfetch.zf_dnode points back to the dnode, and dn_bonus value below matches the dn_bonus value in the VERIFY3 output.

p (*(dnode_t *) 0xffffc9000be19ff0)
$68 = {
  dn_struct_rwlock = {
    rw_rwlock = {
      count = 0,
      wait_lock = {
        raw_lock = {
          slock = 0
        }
      },
      wait_list = {
        next = 0xffffc9000be1a000,
        prev = 0xffffc9000be1a000
      }
    },
    rw_owner = 0x0
  },
  dn_link = {
    next = 0xffffc9000be1a4c8,
    prev = 0xffffc9000bf69b68
  },
  dn_objset = 0xffff880018582000,
  dn_object = 226,
  dn_dbuf = 0xffff88000d11b2d0,
  dn_handle = 0xffff880009e2c128,
  dn_phys = 0xffffc9000ac89400,
  dn_type = DMU_OT_PLAIN_FILE_CONTENTS,
  dn_bonuslen = 220,
  dn_bonustype = 44 ',',
  dn_nblkptr = 1 '\001',
  dn_checksum = 0 '\000',
  dn_compress = 0 '\000',
  dn_nlevels = 1 '\001',
  dn_indblkshift = 14 '\016',
  dn_datablkshift = 17 '\021',
  dn_moved = 0 '\000',
  dn_datablkszsec = 256,
  dn_datablksz = 131072,
  dn_maxblkid = 0,
  dn_next_nblkptr = "\000\000\000",
  dn_next_nlevels = "\000\000\000",
  dn_next_indblkshift = "\000\000\000",
  dn_next_bonustype = "\000\000\000",
  dn_rm_spillblk = "\000\000\000",
  dn_next_bonuslen = {0, 0, 0, 0},
  dn_next_blksz = {0, 0, 0, 0},
  dn_dbufs_count = 1,
  dn_unlisted_l0_blkid = 0,
  dn_dirty_link = {{
      next = 0xffff8800185822c8,
      prev = 0xffffc90008679cc8
    }, {
      next = 0xdead000000100100,
      prev = 0xdead000000200200
    }, {
      next = 0xdead000000100100,
      prev = 0xdead000000200200
    }, {
      next = 0xdead000000100100,
      prev = 0xdead000000200200
    }},
  dn_mtx = {
    m = {
      count = {
        counter = 1
      },
      wait_lock = {
        raw_lock = {
          slock = 0
        }
      },
      wait_list = {
        next = 0xffffc9000be1a0f0,
        prev = 0xffffc9000be1a0f0
      },
      owner = 0x0
    }
  },
  dn_dirty_records = {{
      list_size = 216,
      list_offset = 0,
      list_head = {
        next = 0xffffc9000be1a118,
        prev = 0xffffc9000be1a118
      }
    }, {
      list_size = 216,
      list_offset = 0,
      list_head = {
        next = 0xffffc9000be1a138,
        prev = 0xffffc9000be1a138
      }
    }, {
      list_size = 216,
      list_offset = 0,
      list_head = {
        next = 0xffffc9000be1a158,
        prev = 0xffffc9000be1a158
      }
    }, {
      list_size = 216,
      list_offset = 0,
      list_head = {
        next = 0xffffc9000be1a178,
        prev = 0xffffc9000be1a178
      }
    }},
  dn_ranges = {{
      avl_root = 0x0,
      avl_compar = 0xffffffffa02bbc40 <free_range_compar>,
      avl_offset = 0,
      avl_numnodes = 0,
      avl_size = 40
    }, {
      avl_root = 0x0,
      avl_compar = 0xffffffffa02bbc40 <free_range_compar>,
      avl_offset = 0,
      avl_numnodes = 0,
      avl_size = 40
    }, {
      avl_root = 0x0,
      avl_compar = 0xffffffffa02bbc40 <free_range_compar>,
      avl_offset = 0,
      avl_numnodes = 0,
      avl_size = 40
    }, {
      avl_root = 0x0,
      avl_compar = 0xffffffffa02bbc40 <free_range_compar>,
      avl_offset = 0,
      avl_numnodes = 0,
      avl_size = 40
    }},
  dn_allocated_txg = 40,
  dn_free_txg = 40,
  dn_assigned_txg = 0,
  dn_notxholds = {
    cv_magic = 879052276,
    cv_event = {
      lock = {
        raw_lock = {
          slock = 0
        }
      },
      task_list = {
        next = 0xffffc9000be1a250,
        prev = 0xffffc9000be1a250
      }
    },
    cv_destroy = {
      lock = {
        raw_lock = {
          slock = 0
        }
      },
      task_list = {
        next = 0xffffc9000be1a268,
        prev = 0xffffc9000be1a268
      }
    },
    cv_refs = {
      counter = 1
    },
    cv_waiters = {
      counter = 0
    },
    cv_mutex = 0x0
  },
  dn_dirtyctx = DN_DIRTY_OPEN,
  dn_dirtyctx_firstset = 0xffff880020e20260 "\005",
  dn_tx_holds = {
    rc_mtx = {
      m = {
        count = {
          counter = 1
        },
        wait_lock = {
          raw_lock = {
            slock = 0
          }
        },
        wait_list = {
          next = 0xffffc9000be1a2a0,
          prev = 0xffffc9000be1a2a0
        },
        owner = 0x0
      }
    },
    rc_tracked = B_FALSE,
    rc_list = {
      list_size = 40,
      list_offset = 0,
      list_head = {
        next = 0xffffc9000be1a2d0,
        prev = 0xffffc9000be1a2d0
      }
    },
    rc_removed = {
      list_size = 40,
      list_offset = 0,
      list_head = {
        next = 0xffffc9000be1a2f0,
        prev = 0xffffc9000be1a2f0
      }
    },
    rc_count = 0,
    rc_removed_count = 0
  },
  dn_holds = {
    rc_mtx = {
      m = {
        count = {
          counter = 1
        },
        wait_lock = {
          raw_lock = {
            slock = 0
          }
        },
        wait_list = {
          next = 0xffffc9000be1a318,
          prev = 0xffffc9000be1a318
        },
        owner = 0x0
      }
    },
    rc_tracked = B_FALSE,
    rc_list = {
      list_size = 40,
      list_offset = 0,
      list_head = {
        next = 0xffffc9000be1a348,
        prev = 0xffffc9000be1a348
      }
    },
    rc_removed = {
      list_size = 40,
      list_offset = 0,
      list_head = {
        next = 0xffffc9000be1a368,
        prev = 0xffffc9000be1a368
      }
    },
    rc_count = 3,
    rc_removed_count = 0
  },
  dn_dbufs_mtx = {
    m = {
      count = {
        counter = 1
      },
      wait_lock = {
        raw_lock = {
          slock = 0
        }
      },
      wait_list = {
        next = 0xffffc9000be1a390,
        prev = 0xffffc9000be1a390
      },
      owner = 0x0
    }
  },
  dn_dbufs = {
    list_size = 392,
    list_offset = 344,
    list_head = {
      next = 0xffffc9000be1a3b8,
      prev = 0xffffc9000be1a3b8
    }
  },
  dn_bonus = 0xffff88000becf2d0,
  dn_have_spill = B_FALSE,
  dn_zio = 0xffffc9000cf3e168,
  dn_oldused = 0,
  dn_oldflags = 0,
  dn_olduid = 0,
  dn_oldgid = 0,
  dn_newuid = 0,
  dn_newgid = 0,
  dn_id_flags = 13,
  dn_zfetch = {
    zf_rwlock = {
      rw_rwlock = {
        count = 0,
        wait_lock = {
          raw_lock = {
            slock = 0
          }
        },
        wait_list = {
          next = 0xffffc9000be1a428,
          prev = 0xffffc9000be1a428
        }
      },
      rw_owner = 0x0
    },
    zf_stream = {
      list_size = 104,
      list_offset = 88,
      list_head = {
        next = 0xffffc9000be1a450,
        prev = 0xffffc9000be1a450
      }
    },
    zf_dnode = 0xffffc9000be19ff0,
    zf_stream_cnt = 0,
    zf_alloc_fail = 0
  }
}

(above dnode)->dn_phys

crash> p *((dnode_phys_t *) 0xffffc9000ac89400)
$163 = {
  dn_type = 19 '\023',
  dn_indblkshift = 14 '\016',
  dn_nlevels = 1 '\001',
  dn_nblkptr = 1 '\001',
  dn_bonustype = 44 ',',
  dn_checksum = 0 '\000',
  dn_compress = 0 '\000',
  dn_flags = 3 '\003',
  dn_datablkszsec = 256,
  dn_bonuslen = 220,
  dn_pad2 = "\000\000\000",
  dn_maxblkid = 0,
  dn_used = 0,
  dn_pad3 = {0, 0, 0, 0},
  dn_blkptr = {{
      blk_dva = {{
          dva_word = {0, 0}
        }, {
          dva_word = {0, 0}
        }, {
          dva_word = {0, 0}
        }},
      blk_prop = 0,
      blk_pad = {0, 0},
      blk_phys_birth = 0,
      blk_birth = 0,
      blk_fill = 0,
      blk_cksum = {
        zc_word = {0, 0, 0, 0}
      }
    }},
  dn_bonus = "\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000",
  dn_spill = {
    blk_dva = {{
        dva_word = {0, 0}
      }, {
        dva_word = {0, 0}
      }, {
        dva_word = {0, 0}
      }},
    blk_prop = 0,
    blk_pad = {0, 0},
    blk_phys_birth = 0,
    blk_birth = 0,
    blk_fill = 0,
    blk_cksum = {
      zc_word = {0, 0, 0, 0}
    }
  }
}

(above dnode)->dn_bonus

p *((struct dmu_buf_impl *) 0xffff88000becf2d0)
$70 = {
  db = {
    db_object = 226,
    db_offset = 18446744073709551615,
    db_size = 320,
    db_data = 0xffff88000c823e00
  },
  db_objset = 0xffff880018582000,
  db_dnode_handle = 0xffff880009e2c128,
  db_parent = 0xffff88000d11b2d0,
  db_hash_next = 0x0,
  db_blkid = 18446744073709551615,
  db_blkptr = 0x0,
  db_level = 0 '\000',
  db_mtx = {
    m = {
      count = {
        counter = 1
      },
      wait_lock = {
        raw_lock = {
          slock = 0
        }
      },
      wait_list = {
        next = 0xffff88000becf330,
        prev = 0xffff88000becf330
      },
      owner = 0x0
    }
  },
  db_state = DB_CACHED,
  db_holds = {
    rc_mtx = {
      m = {
        count = {
          counter = 1
        },
        wait_lock = {
          raw_lock = {
            slock = 0
          }
        },
        wait_list = {
          next = 0xffff88000becf358,
          prev = 0xffff88000becf358
        },
        owner = 0x0
      }
    },
    rc_tracked = B_FALSE,
    rc_list = {
      list_size = 40,
      list_offset = 0,
      list_head = {
        next = 0xffff88000becf388,
        prev = 0xffff88000becf388
      }
    },
    rc_removed = {
      list_size = 40,
      list_offset = 0,
      list_head = {
        next = 0xffff88000becf3a8,
        prev = 0xffff88000becf3a8
      }
    },
    rc_count = 2,
    rc_removed_count = 0
  },
  db_buf = 0x0,
  db_changed = {
    cv_magic = 879052276,
    cv_event = {
      lock = {
        raw_lock = {
          slock = 0
        }
      },
      task_list = {
        next = 0xffff88000becf3e0,
        prev = 0xffff88000becf3e0
      }
    },
    cv_destroy = {
      lock = {
        raw_lock = {
          slock = 0
        }
      },
      task_list = {
        next = 0xffff88000becf3f8,
        prev = 0xffff88000becf3f8
      }
    },
    cv_refs = {
      counter = 1
    },
    cv_waiters = {
      counter = 0
    },
    cv_mutex = 0x0
  },
  db_data_pending = 0x0,
  db_last_dirty = 0x0,
  db_link = {
    next = 0xdead000000100100,
    prev = 0xdead000000200200
  },
  db_user_ptr = 0x0,
  db_user_data_ptr_ptr = 0x0,
  db_evict_func = 0,
  db_immediate_evict = 0 '\000',
  db_freed_in_flight = 0 '\000',
  db_dirtycnt = 0 '\000'
}

likely dmu_tx_t *tx (only pointer in the frame that points to a valid tx)

crash> p (*((dmu_tx_t *) 0xffff880017337d40))
$159 = {
  tx_holds = {
    list_size = 80,
    list_offset = 8,
    list_head = {
      next = 0xffff880017337d50,
      prev = 0xffff880017337d50
    }
  },
  tx_objset = 0x0,
  tx_dir = 0x0,
  tx_pool = 0xffff88000d826000,
  tx_txg = 40,
  tx_lastsnap_txg = 0,
  tx_lasttried_txg = 0,
  tx_txgh = {
    th_cpu = 0x0,
    th_txg = 0
  },
  tx_tempreserve_cookie = 0x0,
  tx_needassign_txh = 0x0,
  tx_callbacks = {
    list_size = 32,
    list_offset = 0,
    list_head = {
      next = 0xffff880017337dc0,
      prev = 0xffff880017337dc0
    }
  },
  tx_anyobj = B_TRUE,
  tx_waited = B_FALSE,
  tx_start = 12944260191773,
  tx_wait_dirty = B_FALSE,
  tx_err = 0
}

the root_dir of the pool the tx points to

crash> p (*((struct dsl_pool *) 0xffff88000d826000).dp_root_dir)
$162 = {
  dd_object = 2,
  dd_phys = 0xffff88000fa09600,
  dd_dbuf = 0xffff88000da88040,
  dd_pool = 0xffff88000d826000,
  dd_dirty_link = {
    tn_next = {0xffff880009f52420, 0xffff880009f52420, 0x0, 0x0},
    tn_member = "\001\001\000"
  },
  dd_parent = 0x0,
  dd_lock = {
    m = {
      count = {
        counter = 1
      },
      wait_lock = {
        raw_lock = {
          slock = 0
        }
      },
      wait_list = {
        next = 0xffff88000c724c58,
        prev = 0xffff88000c724c58
      },
      owner = 0x0
    }
  },
  dd_prop_cbs = {
    list_size = 48,
    list_offset = 0,
    list_head = {
      next = 0xffff88000c724c80,
      prev = 0xffff88000c724c80
    }
  },
  dd_snap_cmtime = {
    tv_sec = 1422312492,
    tv_nsec = 833450356
  },
  dd_origin_txg = 1,
  dd_tempreserved = {0, 0, 0, 0},
  dd_space_towrite = {49938432, 74711040, 0, 0},
  dd_myname = "lustre-ost1\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"
}

[ofaaland]

dn_bonustype = 44 (aka DMU_OT_SA)

[ofaaland]

In the sanity test example above, dnode_syc()=>dnode_sync_free()=>dnode_evict_dbufs() cannot evict dn->dn_bonus because dn_bonus->db_holds.rc_count == 2. The entire refcount structure's values are above. Looking into whether I can tell why the refcount is not 0.

[behlendorf]

Closing as stale.