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

Integrate ARC more tightly with Linux #618

Closed
wants to merge 1 commit into from

Conversation

behlendorf
Copy link
Contributor

Under Solaris the ARC was designed to stay one step ahead of the
VM subsystem. It would attempt to recognize low memory situtions
before they occured and evict data from the cache. It would also
make assessments about if there was enough free memory to perform
a specific operation.

This was all possible because Solaris exposes a fairly decent
view of the memory state of the system to other kernel threads.
Linux on the other hand does not make this information easily
available. To avoid extensive modifications to the ARC the SPL
attempts to provide these same interfaces. While this works it
is not ideal and problems can arise when the ARC and Linux have
different ideas about when your out of memory. This has manifested
itself in the past as a spinning arc_reclaim_thread.

This patch abandons the emulated Solaris interfaces in favor of
the prefered Linux interface. That means moving the bulk of the
memory reclaim logic out of the arc_reclaim_thread and in to the
evict driven shrinker callback. The Linux VM will call this
function when it needs memory. The ARC is then responsible for
attempting to free the requested amount of memory if possible.

Several interfaces have been modified to accomidate this approach,
however the basic user space implementation remains the same.
The following changes almost exclusively just apply to the kernel
implementation.

  • Removed the hdr_recl() reclaim callback which is redundant
    with the broader arc_shrinker_func().
  • Reduced arc_grow_retry to 5 seconds from 60. This is now used
    internally in the ARC with arc_no_grow to indicate that direct
    reclaim was recently performed. This typically indicates a
    rapid change in memory demands which the kswapd threads were
    unable to keep ahead of. As long as direct reclaim is happening
    once every 5 seconds arc growth will be paused to avoid further
    contributing to the existing memory pressure. The more common
    indirect reclaim paths will not set arc_no_grow.
  • arc_shrink() has been extended to take the number of bytes by
    which arc_c should be reduced. This allows for a more granual
    reduction of the arc target. Since the kernel provides a
    reclaim value to the arc_shrinker_func() this value is used
    instead of 1<<arc_shrink_shift.
  • arc_reclaim_needed() has been removed. It was used to determine
    if the system was under memory pressure and relied extensively
    on Solaris specific VM interfaces. In most case the new code
    just checks arc_no_grow which indicates that within the last
    arc_grow_retry seconds direct memory reclaim occurred.
  • arc_memory_throttle() has been updated to always include the
    ammount of evictable memory (arc and page cache) in its free
    space calculations. This space is largely available in most
    call paths due to direct memory reclaim.
  • The Solaris pageout code was also removed to avoid confusion.
    It has always been disabled due to proc_pageout being defined
    as NULL in the Linux port.

Signed-off-by: Prakash Surya surya1@llnl.gov
Signed-off-by: Brian Behlendorf behlendorf1@llnl.gov

@dajhorn
Copy link
Contributor

dajhorn commented Mar 25, 2012

Per commentary on commit 201e2b2bfb1a017c378f6be8a590bd975f82516e, I started bisecting kernel and ZoL versions, but the panic is now happening on all recent combinations. Something in the affected pool is broken.

After recompiling SPL and ZFS with --enable-debug, I get a panic at import time and a better error message:

[ 5895.641360] ZFS: Loaded module v0.6.0.55-rc7 (DEBUG mode), ZFS pool version 28, ZFS filesystem version 5
[ 6023.207613] SPLError: 7962:0:(spl-err.c:67:vcmn_err()) WARNING: ZFS replay transaction error 5, dataset moxo/ROOT/ubuntu-4/var, seq 0x23d4, txtype 9 
[ 6023.207617] 
[ 6023.207623] SPLError: 7962:0:(zil.c:361:zil_parse()) ASSERTION(!claimed || !(zh->zh_flags & ZIL_CLAIM_LR_SEQ_VALID) || (max_blk_seq == claim_blk_seq && max_lr_seq == claim_lr_seq)) failed
[ 6023.207630] SPLError: 7962:0:(zil.c:361:zil_parse()) SPL PANIC
[ 6023.207633] SPL: Showing stack for process 7962
[ 6023.207637] Pid: 7962, comm: mount.zfs Tainted: P           O 3.2.0-20-generic #32-Ubuntu
[ 6023.207640] Call Trace:
[ 6023.207658]  [<ffffffffa0269477>] spl_debug_dumpstack+0x27/0x40 [spl]
[ 6023.207667]  [<ffffffffa026a952>] spl_debug_bug+0x82/0xe0 [spl]
[ 6023.207723]  [<ffffffffa03f6a2b>] zil_parse+0x9cb/0x9d0 [zfs]
[ 6023.207731]  [<ffffffff8104fe38>] ? hrtick_update+0x38/0x40
[ 6023.207766]  [<ffffffffa03f4c40>] ? zil_aitx_compare+0x20/0x20 [zfs]
[ 6023.207802]  [<ffffffffa03f5790>] ? zil_replay_error.isra.4+0xc0/0xc0 [zfs]
[ 6023.207839]  [<ffffffffa03f9e7b>] zil_replay+0xbb/0x160 [zfs]
[ 6023.207876]  [<ffffffffa03ee4f0>] ? zfs_rename+0x1090/0x1090 [zfs]
[ 6023.207913]  [<ffffffffa03e3960>] zfs_sb_setup+0x130/0x140 [zfs]
[ 6023.207949]  [<ffffffffa03e4bae>] zfs_domount+0x20e/0x260 [zfs]
[ 6023.207955]  [<ffffffff81127902>] ? register_shrinker+0x52/0x60
[ 6023.207990]  [<ffffffffa040aa60>] ? zpl_mount+0x30/0x30 [zfs]
[ 6023.208025]  [<ffffffffa040aa73>] zpl_fill_super+0x13/0x80 [zfs]
[ 6023.208094]  [<ffffffffa040aa60>] ? zpl_mount+0x30/0x30 [zfs]
[ 6023.208109]  [<ffffffff8117a84d>] mount_nodev+0x5d/0xc0
[ 6023.208152]  [<ffffffffa040aa55>] zpl_mount+0x25/0x30 [zfs]
[ 6023.208164]  [<ffffffff8117b603>] mount_fs+0x43/0x1b0
[ 6023.208178]  [<ffffffff81195e4a>] vfs_kern_mount+0x6a/0xc0
[ 6023.208190]  [<ffffffff81197354>] do_kern_mount+0x54/0x110
[ 6023.208202]  [<ffffffff81198ea4>] do_mount+0x1a4/0x260
[ 6023.208213]  [<ffffffff81199380>] sys_mount+0x90/0xe0
[ 6023.208226]  [<ffffffff81664502>] system_call_fastpath+0x16/0x1b
[ 6023.212040] SPL: Dumping log to /tmp/spl-log.1332710875.7962
[ 6028.084346] SPLError: 7800:0:(zil.c:1551:zil_sync()) ASSERTION(zh->zh_replay_seq < *replayed_seq) failed
[ 6028.084354] SPLError: 7800:0:(zil.c:1551:zil_sync()) SPL PANIC
[ 6028.084357] SPL: Showing stack for process 7800
[ 6028.084362] Pid: 7800, comm: txg_sync Tainted: P           O 3.2.0-20-generic #32-Ubuntu
[ 6028.084365] Call Trace:
[ 6028.084388]  [<ffffffffa0269477>] spl_debug_dumpstack+0x27/0x40 [spl]
[ 6028.084397]  [<ffffffffa026a952>] spl_debug_bug+0x82/0xe0 [spl]
[ 6028.084470]  [<ffffffffa03f91ab>] zil_sync+0x62b/0x640 [zfs]
[ 6028.084509]  [<ffffffffa04009ce>] ? zio_nowait+0x19e/0x350 [zfs]
[ 6028.084535]  [<ffffffffa03471d8>] dmu_objset_sync+0x228/0x570 [zfs]
[ 6028.084560]  [<ffffffffa0344b10>] ? findfunc+0x20/0x20 [zfs]
[ 6028.084585]  [<ffffffffa03457d0>] ? copies_changed_cb+0xe0/0xe0 [zfs]
[ 6028.084614]  [<ffffffffa0361580>] dsl_dataset_sync+0x80/0x170 [zfs]
[ 6028.084650]  [<ffffffffa03a6c20>] ? txg_list_remove+0x60/0x80 [zfs]
[ 6028.084681]  [<ffffffffa037676d>] dsl_pool_sync+0x12d/0x7e0 [zfs]
[ 6028.084689]  [<ffffffff8108aef0>] ? add_wait_queue+0x60/0x60
[ 6028.084723]  [<ffffffffa039109a>] spa_sync+0x39a/0xc20 [zfs]
[ 6028.084760]  [<ffffffffa03a60e6>] txg_sync_thread+0x2a6/0x4d0 [zfs]
[ 6028.084770]  [<ffffffffa026e097>] ? kmem_free_debug+0x57/0x1b0 [spl]
[ 6028.084807]  [<ffffffffa03a5e40>] ? txg_quiesce_thread+0x390/0x390 [zfs]
[ 6028.084817]  [<ffffffffa02728e1>] thread_generic_wrapper+0x81/0xe0 [spl]
[ 6028.084826]  [<ffffffffa0272860>] ? __thread_create+0x360/0x360 [spl]
[ 6028.084831]  [<ffffffff8108a45c>] kthread+0x8c/0xa0
[ 6028.084838]  [<ffffffff81666674>] kernel_thread_helper+0x4/0x10
[ 6028.084842]  [<ffffffff8108a3d0>] ? flush_kthread_worker+0xa0/0xa0
[ 6028.084846]  [<ffffffff81666670>] ? gs_change+0x13/0x13
[ 6028.084918] SPL: Dumping log to /tmp/spl-log.1332710880.7800

Plus the dump files are now written out and readable.

First /tmp/spl-log.1332710875.7962

b��ڍoO��   ��:�dsl_dir.cdsl_dir_open_spamoxo/ROOT/ubuntu-4/var
c��ڍoO��   ��`�dsl_dir.cdsl_dir_open_spalooking up ROOT in obj4
Q��ڍoO'�   ���dsl_dir.cdsl_dir_closedd=moxo 
k��ڍoO*�   ��`�dsl_dir.cdsl_dir_open_spalooking up ubuntu-4 in obj94222
V��ڍoO?�   ���dsl_dir.cdsl_dir_closedd=moxo/ROOT 
f��ڍoOA�   ��`�dsl_dir.cdsl_dir_open_spalooking up var in obj28675
_��ڍoOh�   ���dsl_dir.cdsl_dir_closedd=moxo/ROOT/ubuntu-4 
c��ڍoO�� ���dsl_dir.cdsl_dir_closedd=moxo/ROOT/ubuntu-4/var 
:���ڍoO��    ����dmu_objset.cdmu_objset_open_implreading  DVA[0]=<0:46000009c00:600> DVA[1]=<0:25000002400:600> [L0 DMU objset] fletcher4 lzjb LE contiguous unique double size=800L/200P birth=33765965L/33765965P fill=13980 cksum=18fe7b6036:7bc225bc6c3:1567d125db9f5:2acc9f96991078
c��ڍoOz�   ���dsl_dir.cdsl_dir_closedd=moxo/ROOT/ubuntu-4/var 
c��ڍoO~�   ���dsl_dir.cdsl_dir_closedd=moxo/ROOT/ubuntu-4/var 
_��ڍoO�� ���dsl_dir.cdsl_dir_closedd=moxo/ROOT/ubuntu-4 
_��ڍoO�� ���dsl_dir.cdsl_dir_closedd=moxo/ROOT/ubuntu-3 
_��ڍoO�� ���dsl_dir.cdsl_dir_closedd=moxo/ROOT/ubuntu-3 
V��ڍoO�� ���dsl_dir.cdsl_dir_closedd=moxo/ROOT 
b��ڍoO��   ��:�dsl_dir.cdsl_dir_open_spamoxo/ROOT/ubuntu-4/var
c��ڍoO"�   ��`�dsl_dir.cdsl_dir_open_spalooking up ROOT in obj4
Q��ڍoO6�   ���dsl_dir.cdsl_dir_closedd=moxo 
k��ڍoO9�   ��`�dsl_dir.cdsl_dir_open_spalooking up ubuntu-4 in obj94222
V��ڍoOM�   ���dsl_dir.cdsl_dir_closedd=moxo/ROOT 
f��ڍoOO�   ��`�dsl_dir.cdsl_dir_open_spalooking up var in obj28675
_��ڍoOs�   ���dsl_dir.cdsl_dir_closedd=moxo/ROOT/ubuntu-4 
c��ڍoO�� ���dsl_dir.cdsl_dir_closedd=moxo/ROOT/ubuntu-4/var 
:���ڍoO��    ����dmu_objset.cdmu_objset_open_implreading  DVA[0]=<0:46000009c00:600> DVA[1]=<0:25000002400:600> [L0 DMU objset] fletcher4 lzjb LE contiguous unique double size=800L/200P birth=33765965L/33765965P fill=13980 cksum=18fe7b6036:7bc225bc6c3:1567d125db9f5:2acc9f96991078
���ڍoOj� ����dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=6 blkid=0 db=ffff8800646128d8
���ڍoO{� ����dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=5 blkid=0 db=ffff880064612720
���ڍoO��   ����dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=4 blkid=0 db=ffff880064612568
���ڍoO��   ����de_diduse_spaceds=mos obj=21 dn=ffff880078abf000 dnp=ffffc90004876a00 used=0 delta=0
���ڍoO�q
        >���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ڍoO�r
        >���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ڍoO~r
        >���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
p��ڍoO�t
        >�`dsl_dataset.cdsl_dataset_block_bornds=          (null) <hole>
p��ڍoO   t
         >�`dsl_dataset.cdsl_dataset_block_bornds=          (null) <hole>
���ڍoOT~
        >���dnode.cdnode_diduse_spaceds=mos obj=1071 dn=ffff8800785b7950 dnp=ffffc900023afe00 used=3124242 delta=0
���ڍoO�~
        >���dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff880078dfd410 dnp=ffffc9000540e800 used=920700 delta=0
���ڍoO��
        >���dnode.cdnode_diduse_spaceds=mos obj=1185 dn=ffff880078be8990 dnp=ffffc900023b3200 used=2019402 delta=0
���ڍoO:�
        >���dnode.cdnode_diduse_spaceds=mos obj=1185 dn=ffff880078be8990 dnp=ffffc900023b3200 used=2019402 delta=0
���ڍoO��
        >���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
g���ڍoO��
         K�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:460016ba800:c00> DVA[1]=<0:25000374a00:c00> DVA[2]=<0:4006270000:c00> [L1 SPA space map] fletcher4 lzjb LE contiguous unique triple size=4000L/800P birth=33765988L/33765988P fill=22 cksum=bb14626285:beeede8d0aa7:798d52b86f759e:3ab7b6e2f4391ea6
i���ڍoO��
         I�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000da6400:1200> DVA[1]=<0:25000377400:1200> DVA[2]=<0:4001703a00:1200> [L0 SPA space map] fletcher4 lzjb LE contiguous unique triple size=1000L/a00P birth=33765988L/33765988P fill=1 cksum=91aad96e0a:c492b983a1e8:a536c2f3abb182:681a88cbf5bbec16
k���ڍoO��
         O�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000e0ac00:1200> DVA[1]=<0:25000387000:1200> DVA[2]=<0:4001708200:1200> [L1 SPA space map] fletcher4 lzjb LE contiguous unique triple size=4000L/a00P birth=33765988L/33765988P fill=36 cksum=fd222fb313:12bdbaa710438:f1f33039995f87:94961af82a920743
m���ڍoO՚
        O�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000e08e00:1e00> DVA[1]=<0:25000378600:1e00> DVA[2]=<0:4001706400:1e00> [L1 SPA space map] fletcher4 lzjb LE contiguous unique triple size=4000L/1200P birth=33765988L/33765988P fill=74 cksum=1a79dcbefeb:40feb97107e90:630ef547de4930b:7d68042b2b1c97f
c���ڍoO��
         S�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:460016bb400:c00> DVA[1]=<0:25000386400:c00> DVA[2]=<0:4006270c00:c00> [L0 DMU dnode] fletcher4 lzjb LE contiguous unique triple size=4000L/800P birth=33765988L/33765988P fill=32 cksum=a30d9d39c1:b1e8dff43050:7911dd87c0e35c:3e30d7522d533158
���ڍoO��
        >���dnode.cdnode_diduse_spaceds=mos obj=1071 dn=ffff8800785b7950 dnp=ffffc900023afe00 used=3124242 delta=0
���ڍoO?�
        >���dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff880078dfd410 dnp=ffffc9000540e800 used=920700 delta=0
���ڍoOϠ
       >���dnode.cdnode_diduse_spaceds=mos obj=1185 dn=ffff880078be8990 dnp=ffffc900023b3200 used=2019402 delta=0
���ڍoOR�
        >���dnode.cdnode_diduse_spaceds=mos obj=1185 dn=ffff880078be8990 dnp=ffffc900023b3200 used=2019402 delta=0
���ڍoO��
        >���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ڍoO��
        ��$�txg.ctxg_wait_syncedbroadcasting sync more tx_synced=33765988 waiting=33765989 dp=ffff8800c8717000
���ڍoO��
        >���dnode.cdnode_diduse_spaceds=mos obj=21 dn=ffff880078abf000 dnp=ffffc90004876a00 used=0 delta=0
���ڍoO��
        >���dnode.cdnode_diduse_spaceds=mos obj=21 dn=ffff880078abf000 dnp=ffffc90004876a00 used=0 delta=0
���ڍoO'�
        >���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ڍoO��
        >���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ڍoO��
        >���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
p��ڍoO��
        >�`dsl_dataset.cdsl_dataset_block_bornds=          (null) <hole>
p��ڍoO��
        >�`dsl_dataset.cdsl_dataset_block_bornds=          (null) <hole>
h���ڍoO��
         S�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000da8200:1800> DVA[1]=<0:25000389a00:1800> DVA[2]=<0:4001711e00:1800> [L0 DMU dnode] fletcher4 lzjb LE contiguous unique triple size=4000L/e00P birth=33765989L/33765989P fill=30 cksum=f1b41365d0:1c0505ddc005f:20c4a4a86d164a6:c92c2817de9efbe6
m���ڍoO��
         S�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000e85600:3000> DVA[1]=<0:2500038b200:3000> DVA[2]=<0:400173ca00:3000> [L1 DMU dnode] fletcher4 lzjb LE contiguous unique triple size=4000L/1e00P birth=33765989L/33765989P fill=3696 cksum=26353b2f43e:8fa7d87f83377:164d587dc91c74dd:aac4e57f2b2b8a7c
m���ڍoO��
         S�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:460016c8000:2400> DVA[1]=<0:2500039a200:2400> DVA[2]=<0:4006295800:2400> [L2 DMU dnode] fletcher4 lzjb LE contiguous unique triple size=4000L/1400P birth=33765989L/33765989P fill=91012 cksum=18d95a17e02:3ffdc47a63c70:69fee86c3faaa64:3ff09a7f98704d27
b���ڍoO��
         S�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000e0be00:600> DVA[1]=<0:2500039c600:600> DVA[2]=<0:4001710600:600> [L0 DMU objset] fletcher4 lzjb LE contiguous unique triple size=800L/200P birth=33765989L/33765989P fill=91012 cksum=10426664e4:65bfaa04b80:145c7eb38a769:2c7ba62a37825f
���ڍoO��
        >���dnode.cdnode_diduse_spaceds=mos obj=1071 dn=ffff8800785b7950 dnp=ffffc900023afe00 used=3124242 delta=0
���ڍoO��
        >���dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff880078dfd410 dnp=ffffc9000540e800 used=920700 delta=3069
���ڍoOX�
        >���dnode.cdnode_diduse_spaceds=mos obj=1185 dn=ffff880078be8990 dnp=ffffc900023b3200 used=2019402 delta=0
���ڍoO��
        >���dnode.cdnode_diduse_spaceds=mos obj=1185 dn=ffff880078be8990 dnp=ffffc900023b3200 used=2019402 delta=0
���ڍoO��
        >���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
g���ڍoOk
Q�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:460016ca400:c00> DVA[1]=<0:2500039d200:c00> DVA[2]=<0:4006297c00:c00> [L1 SPA space map] fletcher4 lzjb LE contiguous unique triple size=4000L/800P birth=33765989L/33765989P fill=22 cksum=bac188a1b4:be8acdaad395:79645611635c9a:3aad8659fb244cd2
j���ڍoO�
        S�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000daf400:1800> DVA[1]=<0:2500039de00:1800> DVA[2]=<0:4001736a00:1800> [L0 SPA space map] fletcher4 lzjb LE contiguous unique triple size=1000L/c00P birth=33765989L/33765989P fill=1 cksum=a8b515453f:13d01411973dd:154fc404b97abce
���ڍoO2|
        >���dnode.cdnode_diduse_spaceds=moxo/ROOT/ubuntu-4/var obj=16455 dn=ffff880064a058b8 dnp=ffffc90004888e00 used=38796252 delta=0
���ڍoO�|
        >���dnode.cdnode_diduse_spaceds=moxo/ROOT/ubuntu-4/var obj=16455 dn=ffff880064a058b8 dnp=ffffc90004888e00 used=38796252 delta=0
���ڍoO�|
        >���dnode.cdnode_diduse_spaceds=moxo/ROOT/ubuntu-4/var obj=16455 dn=ffff880064a058b8 dnp=ffffc90004888e00 used=38796252 delta=0
���ڍoO�|
        >���dnode.cdnode_diduse_spaceds=moxo/ROOT/ubuntu-4/var obj=mdn dn=ffff880064660040 dnp=ffffc900072b5600 used=3983562 delta=0
���ڍoO"}
        >���dnode.cdnode_diduse_spaceds=moxo/ROOT/ubuntu-4/var obj=mdn dn=ffff880064660040 dnp=ffffc900072b5600 used=3983562 delta=0
���ڍoOO}
        >���dnode.cdnode_diduse_spaceds=moxo/ROOT/ubuntu-4/var obj=mdn dn=ffff880064660040 dnp=ffffc900072b5600 used=3983562 delta=0
���ڍoOx}
        >���dnode.cdnode_diduse_spaceds=moxo/ROOT/ubuntu-4/var obj=mdn dn=ffff880064660040 dnp=ffffc900072b5600 used=3983562 delta=0
���ڍoO�}
        >���dnode.cdnode_diduse_spaceds=moxo/ROOT/ubuntu-4/var obj=mdn dn=ffff880064660040 dnp=ffffc900072b5600 used=3983562 delta=0
���ڍoO�}
        >���dnode.cdnode_diduse_spaceds=moxo/ROOT/ubuntu-4/var obj=mdn dn=ffff880064660040 dnp=ffffc900072b5600 used=3983562 delta=0
���ڍoO�}
        >���dnode.cdnode_diduse_spaceds=moxo/ROOT/ubuntu-4/var obj=mdn dn=ffff880064660040 dnp=ffffc900072b5600 used=3983562 delta=0
���ڍoO3�
        >���dnode.cdnode_diduse_spaceds=moxo/ROOT/ubuntu-4/var obj=-2 dn=ffff880064a074a8 dnp=ffffc900072b5c00 used=2046 delta=0
J���ڍoO��
         E��dsl_dataset.cdsl_dataset_block_killfreeing ds=28683 DVA[0]=<0:280783f4800:600> DVA[1]=<0:46001ce2400:600> [L0 ZFS user/group used] fletcher4 lzjb LE contiguous unique double size=600L/200P birth=33765964L/33765964P fill=1 cksum=10969980ee:69ba3d79462:15bc9d1295602:311c1688fb8a11
M���ڍoO��
         E�`dsl_dataset.cdsl_dataset_block_bornds=ffff8800647c0400 DVA[0]=<0:46000e97000:600> DVA[1]=<0:25000406e00:600> [L0 ZFS user/group used] fletcher4 lzjb LE contiguous unique double size=600L/200P birth=33765990L/33765990P fill=1 cksum=10969980ee:69ba3d79462:15bc9d1295602:311c1688fb8a11
E���ڍoO*�
         O��dsl_dataset.cdsl_dataset_block_killfreeing ds=28683 DVA[0]=<0:46000e91c00:600> DVA[1]=<0:250003b4c00:600> [L0 DMU objset] fletcher4 lzjb LE contiguous unique double size=800L/200P birth=33765990L/33765990P fill=13980 cksum=1765270296:6f5a2ad2748:12bd732f961f5:24f1c9eb378a63
H���ڍoO3�
         O�`dsl_dataset.cdsl_dataset_block_bornds=ffff8800647c0400 DVA[0]=<0:46000e9d600:600> DVA[1]=<0:25000407400:600> [L0 DMU objset] fletcher4 lzjb LE contiguous unique double size=800L/200P birth=33765990L/33765990P fill=13980 cksum=1925558566:740690fdc37:1329727efc5b4:25624859b27739
���ڍoO��
        >���dnode.cdnode_diduse_spaceds=mos obj=21 dn=ffff880078abf000 dnp=ffffc90004876a00 used=0 delta=0
p��ڍoO��
        >�`dsl_dataset.cdsl_dataset_block_bornds=          (null) <hole>
���ڍoO_�
        >���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ڍoO��
        >���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ڍoO��
        >���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ڍoO��
        >���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ڍoO,�
        >���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
S�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000db5a00:1800> DVA[1]=<0:25000452400:1800> DVA[2]=<0:400173fa00:1800> [L0 DMU dnode] fletcher4 lzjb LE contiguous unique triple size=4000L/e00P birth=33765990L/33765990P fill=30 cksum=f1ca1181e2:1c08e9e722721:20ca25797751b1c:c97f1abab024f204
S�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000ebf200:3000> DVA[1]=<0:2500050a600:3000> DVA[2]=<0:4001833000:3000> [L1 DMU dnode] fletcher4 lzjb LE contiguous unique triple size=4000L/1e00P birth=33765990L/33765990P fill=3696 cksum=28fc23940ad:9d5b524ed4fa8:1897737d3e041490:ff4757f5bfd33a42
���ڍoO�>>���dnode.cdnode_diduse_spaceds=mos obj=1585 dn=ffff880078dfe6b0 dnp=ffffc9000483b200 used=359073 delta=0
���ڍoO�?>���dnode.cdnode_diduse_spaceds=mos obj=1585 dn=ffff880078dfe6b0 dnp=ffffc9000483b200 used=359073 delta=0
���ڍoO$@>���dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff880078dfd410 dnp=ffffc9000540e800 used=923769 delta=0
���ڍoO�@>���dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff880078dfd410 dnp=ffffc9000540e800 used=923769 delta=0
���ڍoO�A>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ڍoONB>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
e���ڍoOzFE�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:460016f9800:c00> DVA[1]=<0:2500050d600:c00> DVA[2]=<0:40062dde00:c00> [L0 SPA space map] fletcher4 lzjb LE contiguous unique triple size=1000L/600P birth=33765990L/33765990P fill=1 cksum=59d3257b6c:49d40fac5063:23c1a87360906c:ce0f0be9a595f42
g���ڍoO��S�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:460016fb600:c00> DVA[1]=<0:2500050e200:c00> DVA[2]=<0:40062dea00:c00> [L1 SPA space map] fletcher4 lzjb LE contiguous unique triple size=4000L/800P birth=33765990L/33765990P fill=29 cksum=cf002a6bd2:ce9c25be132f:86f89301c654f7:4302d5fecc17e465
j���ڍoO��Q�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000db7200:1800> DVA[1]=<0:2500051c600:1800> DVA[2]=<0:40018ca200:1800> [L0 SPA space map] fletcher4 lzjb LE contiguous unique triple size=1000L/c00P birth=33765990L/33765990P fill=1 cksum=afa64d82d0:14058c795833c:155ce084ab9af59:a57be12ad6bbdf5
b���ڍoO��O�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000ea1800:600> DVA[1]=<0:2500050fa00:600> DVA[2]=<0:4001755600:600> [L0 SPA space map] fletcher4 lzjb LE contiguous unique triple size=1000L/200P birth=33765990L/33765990P fill=1 cksum=2861edd55f:8903a67ecee:14adf24d4f0fd:2837f402b632dc
l���ڍoOϾK�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000eaae00:1200> DVA[1]=<0:25000520800:1200> DVA[2]=<0:4002222a00:1200> [L1 SPA space map] fletcher4 lzjb LE contiguous unique triple size=4000L/a00P birth=33765990L/33765990P fill=37 cksum=10031068f43:12a229a44bbf8:f16cbca6365bfa:9480250764d950d9
g���ڍoO�S�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:460016fce00:c00> DVA[1]=<0:2500051de00:c00> DVA[2]=<0:40062e0200:c00> [L1 SPA space map] fletcher4 lzjb LE contiguous unique triple size=4000L/800P birth=33765990L/33765990P fill=22 cksum=bd9e24e5b1:c03cf8689e15:79f406ac5bb9d7:3acef1407aa5634f
c���ڍoO�S�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46001:a34d718f48520bb
i���ڍoO 
        M�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000e0ca00:1200> DVA[1]=<0:2500039f600:1200> DVA[2]=<0:4001717200:1200> [L0 SPA space map] fletcher4 lzjb LE contiguous unique triple size=1000L/a00P birth=33765989L/33765989P fill=1 cksum=9a1ef2609e:c5e409792f47:a55315f671bbaf:681c3afda0397416
m���ڍoO�
        K�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000e2da00:1e00> DVA[1]=<0:250003a0800:1e00> DVA[2]=<0:400174d200:1e00> [L1 SPA space map] fletcher4 lzjb LE contiguous unique triple size=4000L/1200P birth=33765989L/33765989P fill=74 cksum=1a87c72d840:410d95ec1a62d:63155eea6846f38:7f1aa4ce6da7dca
k���ڍoO��
         G�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000e8aa00:1200> DVA[1]=<0:250003a3200:1200> DVA[2]=<0:400174f000:1200> [L1 SPA space map] fletcher4 lzjb LE contiguous unique triple size=4000L/a00P birth=33765989L/33765989P fill=36 cksum=fb52220ed3:12ba252f57e9f:f1edd09feb7445:94956fc8931cfe79
���ڍoO��
        >���dnode.cdnode_diduse_spaceds=mos obj=1071 dn=ffff8800785b7950 dnp=ffffc900023afe00 used=3124242 delta=0
���ڍoO-�
        >���dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff880078dfd410 dnp=ffffc9000540e800 used=923769 delta=0
���ڍoO��
        >���dnode.cdnode_diduse_spaceds=mos obj=1185 dn=ffff880078be8990 dnp=ffffc900023b3200 used=2019402 delta=0
���ڍoO �
        >���dnode.cdnode_diduse_spaceds=mos obj=1185 dn=ffff880078be8990 dnp=ffffc900023b3200 used=2019402 delta=3069
���ڍoO��
        >���dnode.cdnode_diduse_spaceds=mos obj=1185 dn=ffff880078be8990 dnp=ffffc900023b3200 used=2022471 delta=0
���ڍoO��
        >���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
b���ڍoOn8
         K�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000e8ec00:600> DVA[1]=<0:250003a5c00:600> DVA[2]=<0:4001752000:600> [L0 SPA space map] fletcher4 lzjb LE contiguous unique triple size=1000L/200P birth=33765989L/33765989P fill=1 cksum=15d1f180f4:96a36bd5e0a:210ab988bae27:4e90b4aaaa3012
���ڍoO#<
        >���dnode.cdnode_diduse_spaceds=mos obj=1071 dn=ffff8800785b7950 dnp=ffffc900023afe00 used=3124242 delta=0
���ڍoO�<
        >���dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff880078dfd410 dnp=ffffc9000540e800 used=923769 delta=0
���ڍoOC=
        >���dnode.cdnode_diduse_spaceds=mos obj=1185 dn=ffff880078be8990 dnp=ffffc900023b3200 used=2022471 delta=0
���ڍoO�=
        >���dnode.cdnode_diduse_spaceds=mos obj=1185 dn=ffff880078be8990 dnp=ffffc900023b3200 used=2022471 delta=0
���ڍoO�=
        >���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ڍoO�>
        >���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ڍoO
      ?
       >���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ڍoOc?
        >���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ڍoO�n
        ����dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=1 blkid=4 db=ffff880064611170
���ڍoO�n
        ����dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=0 blkid=514 db=ffff880064610fb8
���ڍoO<o
        ����dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=16455 lvl=2 blkid=0 db=ffff880064610c48
���ڍoOFo
        ����dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=16455 lvl=1 blkid=2 db=ffff880064610a90
���ڍoOQo
        ����dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=16455 lvl=0 blkid=272 db=ffff8800646108d8
���ڍoOlo
        ����dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=16455 lvl=0 blkid=272 db=ffff8800646108d8
z��ڍoOyo
        ��N�dmu_tx.cdmu_tx_dirty_buffound txh type 2 beginblk=0 endblk=7fffffffffff
s��ڍoO|o
        ��N�dmu_tx.cdmu_tx_dirty_buffound txh type 1 beginblk=110 endblk=110
���ڍoO�o
        ����dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=16455 lvl=0 blkid=272 size=20000
���ڍoO�o
        ���dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=16455 blkid=272 nblks=1 txg=33765990
x��ڍoO
      ��N�dmu_tx.cdmu_tx_dirty_buffound txh type 2 beginblk=0 endblk=ffffffffff
o��ڍoO�o
        ��N�dmu_tx.cdmu_tx_dirty_buffound txh type 1 beginblk=2 endblk=2
~��ڍoO�o
        ����dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=16455 lvl=1 blkid=2 size=4000
w��ڍoO�o
        ��N�dmu_tx.cdmu_tx_dirty_buffound txh type 2 beginblk=0 endblk=1ffffffff
o��ڍoO�o
        ��N�dmu_tx.cdmu_tx_dirty_buffound txh type 1 beginblk=0 endblk=0
~��ڍoO�o
        ����dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=16455 lvl=2 blkid=0 size=4000
x��ڍoO�o
        ����dnode.cdnode_setdirtyds=moxo/ROOT/ubuntu-4/var obj=16455 txg=33765990
~��ڍoO�o
        ����dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=0 blkid=514 size=4000
���ڍoO�o
        ���dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=mdn blkid=514 nblks=1 txg=33765990
|��ڍoO�o
        ����dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=1 blkid=4 size=4000
|��ڍoO�o
        ����dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=2 blkid=0 size=4000
|��ڍoO�o
        ����dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=3 blkid=0 size=4000
|��ڍoO�o
        ����dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=4 blkid=0 size=4000
|��ڍoO�o
        ����dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=5 blkid=0 size=4000
|��ڍoO�o
        ����dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=6 blkid=0 size=4000
z��ڍoO
      p
       ��N�dmu_tx.cdmu_tx_dirty_buffound txh type 2 beginblk=0 endblk=7fffffffffff
~��ڍoOp
       ����dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=16455 lvl=0 blkid=-1 size=140
~��ڍoO�p
        ����dmu_tx.cdmu_tx_committowrite=11403264 written=6684672 tofree=0 freed=167772
z��ڍoO'p
        �� �txg.ctxg_wait_syncedtxg=33765992 quiesce_txg=33765990 sync_txg=33765992
���ڍoO)p
        ��$�txg.ctxg_wait_syncedbroadcasting sync more tx_synced=33765989 waiting=33765992 dp=ffff8800c87170006fda00:c00> DVA[1]=<0:25000536a00:c00> DVA[2]=<0:40062e0e00:c00> [L0 DMU dnode] fletcher4 lzjb LE contiguous unique triple size=4000L/800P birth=33765990L/33765990P fill=32 cksum=a2bd3d9be4:b1a33bf5b9a5:78f3caa3773dff:3e28396b024e2cf0
f���ڍoO�S�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:460016fc200:c00> DVA[1]=<0:2500050ee00:c00> DVA[2]=<0:40062df600:c00> [L2 SPA space map] fletcher4 lzjb LE contiguous unique triple size=4000L/400P birth=33765990L/33765990P fill=29 cksum=5afd265a30:3de3df8971cb:16561c211a5484:5a7a1f4182d22b4
c���ڍoO
       S�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:460016fe600:c00> DVA[1]=<0:25000538e00:c00> DVA[2]=<0:40062e1a00:c00> [L0 DMU dnode] fletcher4 lzjb LE contiguous unique triple size=4000L/800P birth=33765990L/33765990P fill=31 cksum=9e9a0c4fa3:a6059bcdc642:700c9ed534f8dd:38c01e1cc45ec30a
���ڍoOA>���dnode.cdnode_diduse_spaceds=mos obj=1071 dn=ffff8800785b7950 dnp=ffffc900023afe00 used=3124242 delta=3069
���ڍoO�>���dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff880078dfd410 dnp=ffffc9000540e800 used=923769 delta=0
���ڍoO�>���dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff880078dfd410 dnp=ffffc9000540e800 used=926838 delta=0
���ڍoOC>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ڍoO�>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ڍoOW>���dnode.cdnode_diduse_spaceds=mos obj=21 dn=ffff880078abf000 dnp=ffffc90004876a00 used=0 delta=6138
���ڍoO+>���dnode.cdnode_diduse_spaceds=mos obj=21 dn=ffff880078abf000 dnp=ffffc90004876a00 used=12276 delta=6138
���ڍoO�>���dnode.cdnode_diduse_spaceds=mos obj=1071 dn=ffff8800785b7950 dnp=ffffc900023afe00 used=3127311 delta=0
���ڍoO�>���dnode.cdnode_diduse_spaceds=mos obj=1185 dn=ffff880078be8990 dnp=ffffc900023b3200 used=2022471 delta=0
���ڍoOd>���dnode.cdnode_diduse_spaceds=mos obj=1185 dn=ffff880078be8990 dnp=ffffc900023b3200 used=2022471 delta=0
���ڍoO�>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ڍoOn>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ڍoO�>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ڍoOY�>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ڍoO./>���dnode.cdnode_diduse_spaceds=mos obj=1071 dn=ffff8800785b7950 dnp=ffffc900023afe00 used=3127311 delta=6138
���ڍoO�0>���dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff880078dfd410 dnp=ffffc9000540e800 used=926838 delta=9207
���ڍoOJ0>���dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff880078dfd410 dnp=ffffc9000540e800 used=936045 delta=33759
���ڍoO
      1>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=42966
���ڍoO�2>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34400421 delta=36828
���ڍoOq2>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34437249 delta=24552
���ڍoO�2>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34461801 delta=30690
s���ڍoO�=I�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000db8a00:1800> DVA[1]=<0:2500059e800:1800> DVA[2]=<0:40021c2a00:1800> [L0 SPA space map] fletcher4 uncompressed LE contiguous unique triple size=1000L/1000P birth=33765990L/33765990P fill=1 cksum=2de113e525:a645504ac519:12eab5bfc7680c0:70fa4b98fe9a49e2
p���ۍoO��Q�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000dbf600:1800> DVA[1]=<0:250005ad200:1800> DVA[2]=<0:4002214000:1800> [L0 SPA space map] fletcher4 uncompressed LE contiguous unique triple size=1000L/1000P birth=33765990L/33765990P fill=1 cksum=3440e2ff4:cd88c7815f2:194aa28bc63c63:213b960b7a3efecc
s���ۍoO��I�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000ead800:1800> DVA[1]=<0:250005aea00:1800> DVA[2]=<0:4002c72a00:1800> [L0 SPA space map] fletcher4 uncompressed LE contiguous unique triple size=1000L/1000P birth=33765990L/33765990P fill=1 cksum=24adb41c9e:8924a5e4d3f3:1011a91f3509f9a:42373312cd9a6e55
v���ۍoO��G�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:460022e0600:6000> DVA[1]=<0:250010ecc00:6000> DVA[2]=<0:4008e7a000:6000> [L1 SPA space map] fletcher4 uncompressed LE contiguous unique triple size=4000L/4000P birth=33765990L/33765990P fill=37 cksum=8c9a7bb2a0:77c21457d7fba:33875c55ed9e2dc1:e1665c68b6cf2dd8
q���ۍoOF�I�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:4600239ca00:6000> DVA[1]=<0:2500112fe00:6000> DVA[2]=<0:4008ecb000:6000> [L0 DMU dnode] fletcher4 uncompressed LE contiguous unique triple size=4000L/4000P birth=33765990L/33765990P fill=32 cksum=2c6666f013:17bc25eec998f:697060abe965bea:33975ae544fb2fca
���ۍoO�p�>���dnode.cdnode_diduse_spaceds=mos obj=21 dn=ffff880078abf000 dnp=ffffc90004876a00 used=18414 delta=42966
���ۍoO�q�>���dnode.cdnode_diduse_spaceds=mos obj=21 dn=ffff880078abf000 dnp=ffffc90004876a00 used=104346 delta=42966
���ۍoOHr�>���dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff880078dfd410 dnp=ffffc9000540e800 used=969804 delta=0
���ۍoO�r�>���dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff880078dfd410 dnp=ffffc9000540e800 used=969804 delta=0
���ۍoOMs�>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34492491 delta=0
���ۍoO�s�>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34492491 delta=0
���ۍoO�t�>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34492491 delta=0
���ۍoO,t�>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34492491 delta=0
j���ۍoO=��O�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46002fc7000:6000> DVA[1]=<0:25001527c00:6000> DVA[2]=<0:400c1bcc00:6000> [L0 bpobj] fletcher4 uncompressed LE contiguous unique triple size=4000L/4000P birth=33765990L/33765990P fill=1 cksum=db30430b0:cf8c2fada64c:62658a237904f5c:2445dfd939849b66
j���ۍoO���I�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46002ffe800:6000> DVA[1]=<0:25001536600:6000> DVA[2]=<0:400cb9ca00:6000> [L1 bpobj] fletcher4 uncompressed LE contiguous unique triple size=4000L/4000P birth=33765990L/33765990P fill=1 cksum=278634149:2755719cbf51:1393b69e6c15ea3:7f5a4950fcb2c394
j���ۍoO5T�O�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46003075c00:6000> DVA[1]=<0:25001a96400:60dnode.cdnode_diduse_spaceds=mos obj=21 dn=ffff880078abf000 dnp=ffffc90004876a00 used=0 delta=0
���ۍoO��>���dnode.cdnode_diduse_spaceds=mos obj=21 dn=ffff880078abf000 dnp=ffffc90004876a00 used=0 delta=0
���ۍoO��>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ۍoOq�>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ۍoOد>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
p��ۍoOH�>�`dsl_dataset.cdsl_dataset_block_bornds=          (null) <hole>
p��ۍoON�>�`dsl_dataset.cdsl_dataset_block_bornds=          (null) <hole>
h���ۍoO��I�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000ec2200:1800> DVA[1]=<0:2500065f400:1800> DVA[2]=<0:4002c82600:1800> [L0 DMU dnode] fletcher4 lzjb LE contiguous unique triple size=4000L/e00P birth=33765992L/33765992P fill=30 cksum=f1eb0eabfd:1c0ebff536144:20d266b306aaccd:c9fb86aeea6de331
m���ۍoO
�G�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000f2ee00:3000> DVA[1]=<0:25000800a00:3000> DVA[2]=<0:400374ac00:3000> [L1 DMU dnode] fletcher4 lzjb LE contiguous unique triple size=4000L/1e00P birth=33765992L/33765992P fill=3696 cksum=27b69684706:9427365002454:16c62788811a3b8c:466d5a47244e0f4e
m���ۍoO

       �G�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46001737000:2400> DVA[1]=<0:2500072c600:2400> DVA[2]=<0:4006772200:2400> [L2 DMU dnode] fletcher4 lzjb LE contiguous unique triple size=4000L/1400P birth=33765992L/33765992P fill=91012 cksum=191be72ae51:4103e0a25b1df:6bdab6cf49b2fda:62c5317a8e07376d
a���ۍoO�
        �G�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000ecf400:600> DVA[1]=<0:2500072ae00:600> DVA[2]=<0:400318c000:600> [L0 DMU objset] fletcher4 lzjb LE contiguous unique triple size=800L/200P birth=33765992L/33765992P fill=91012 cksum=f9c9a2a86:6142bb6e4b9:13697a8462c0e:2a5f3e687d9436
�>���dnode.cdnode_diduse_spaceds=mos obj=1071 dn=ffff8800785b7950 dnp=ffffc900023afe00 used=3127311 delta=0
���ۍoOW�>���dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff880078dfd410 dnp=ffffc9000540e800 used=926838 delta=3069
���ۍoO�>���dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff880078dfd410 dnp=ffffc9000540e800 used=929907 delta=0
���ۍoO��>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ۍoO���>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ۍoO���>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ۍoOk��>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
d���ۍoO� �S�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46001739400:c00> DVA[1]=<0:2500074ac00:c00> DVA[2]=<0:4006774600:c00> [L0 SPA space map] fletcher4 lzjb LE contiguous unique triple size=1000L/400P birth=33765992L/33765992P fill=1 cksum=408ce89c27:20d7dc54e14e:a84840cbd9f9e:29369d82f42f6d2
c���ۍoO(�O�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:460017bd400:c00> DVA[1]=<0:25000791400:c00> DVA[2]=<0:4006778e00:c00> [L0 DMU dnode] fletcher4 lzjb LE contiguous unique triple size=4000L/600P birth=33765992L/33765992P fill=31 cksum=79f922a7e3:6ae2ff9c418c:366cb860eccf9b:144595432a07aeaf
c���ۍoO?�O�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:460017bc800:c00> DVA[1]=<0:25000790800:c00> DVA[2]=<0:4006778200:c00> [L0 DMU dnode] fletcher4 lzjb LE contiguous unique triple size=4000L/800P birth=33765992L/33765992P fill=32 cksum=9640f27b21:a920268b5ce6:75f12f0f15e08f:3d6a8f5365b491dc
���ۍoO��>���dnode.cdnode_diduse_spaceds=mos obj=1071 dn=ffff8800785b7950 dnp=ffffc900023afe00 used=3127311 delta=0
���ۍoO��>���dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff880078dfd410 dnp=ffffc9000540e800 used=929907 delta=0
���ۍoO��>���dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff880078dfd410 dnp=ffffc9000540e800 used=929907 delta=0
���ۍoO��>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ۍoOl >���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ۍoO� >���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ۍoOZ!>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
z��ۍoOٍ��N�dmu_tx.cdmu_tx_dirty_buffound txh type 2 beginblk=0 endblk=7fffffffffff
s��ۍoOݍ��N�dmu_tx.cdmu_tx_dirty_buffound txh type 1 beginblk=110 endblk=110
���ۍoO������dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=16455 lvl=0 blkid=272 size=20000
���ۍoO�����dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=16455 blkid=272 nblks=1 txg=33765993
x��ۍoO����N�dmu_tx.cdmu_tx_dirty_buffound txh type 2 beginblk=0 endblk=ffffffffff
o��ۍoO����N�dmu_tx.cdmu_tx_dirty_buffound txh type 1 beginblk=2 endblk=2
~��ۍoO������dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=16455 lvl=1 blkid=2 size=4000
w��ۍoO����N�dmu_tx.cdmu_tx_dirty_buffound txh type 2 beginblk=0 endblk=1ffffffff
o��ۍoO����N�dmu_tx.cdmu_tx_dirty_buffound txh type 1 beginblk=0 endblk=0
~��ۍoO�����dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=16455 lvl=2 blkid=0 size=4000
x��ۍoO   ����dnode.cdnode_setdirtyds=moxo/ROOT/ubuntu-4/var obj=16455 txg=33765993
����dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=0 blkid=514 size=4000
���ۍoO����dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=mdn blkid=514 nblks=1 txg=33765993
|��ۍoO�����dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=1 blkid=4 size=4000
|��ۍoO�����dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=2 blkid=0 size=4000
|��ۍoO'����dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=3 blkid=0 size=4000
|��ۍoO/����dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=4 blkid=0 size=4000
|��ۍoO7����dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=5 blkid=0 size=4000
|��ۍoO?����dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=6 blkid=0 size=4000
z��ۍoO���N�dmu_tx.cdmu_tx_dirty_buffound txh type 2 beginblk=0 endblk=7fffffffffff
~��ۍoO�����dbuf.cdbuf_dirtyds=moxo/ROOT/ub00> DVA[2]=<0:400cecdc00:6000> [L2 bpobj] fletcher4 uncompressed LE contiguous unique triple size=4000L/4000P birth=33765990L/33765990P fill=1 cksum=449379788:442cf57a620f:21e5b04063527ce:3d1bcd20499b3eb8
���ۍoO5V�>���dnode.cdnode_diduse_spaceds=mos obj=21 dn=ffff880078abf000 dnp=ffffc90004876a00 used=147312 delta=0
���ۍoO�W�>���dnode.cdnode_diduse_spaceds=mos obj=21 dn=ffff880078abf000 dnp=ffffc90004876a00 used=147312 delta=0
���ۍoOuW�>���dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff880078dfd410 dnp=ffffc9000540e800 used=969804 delta=0
���ۍoO�W�>���dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff880078dfd410 dnp=ffffc9000540e800 used=969804 delta=0
���ۍoO>X�>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34492491 delta=0
���ۍoO�X�>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34492491 delta=0
���ۍoO�&���$�txg.ctxg_wait_syncedbroadcasting sync more tx_synced=33765990 waiting=33765992 dp=ffff8800c8717000
���ۍoOz(�>���dnode.cdnode_diduse_spaceds=mos obj=21 dn=ffff880078abf000 dnp=ffffc90004876a00 used=0 delta=0
���ۍoO�(�>���dnode.cdnode_diduse_spaceds=mos obj=21 dn=ffff880078abf000 dnp=ffffc90004876a00 used=0 delta=0
���ۍoO�(�>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34492491 delta=-36828
���ۍoO�)�>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34455663 delta=-24552
���ۍoO�)�>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34431111 delta=-30690
p��ۍoOk+�>�`dsl_dataset.cdsl_dataset_block_bornds=          (null) <hole>
p��ۍoOq+�>�`dsl_dataset.cdsl_dataset_block_bornds=          (null) <hole>
���ۍoO�o�>���dnode.cdnode_diduse_spaceds=mos obj=1071 dn=ffff8800785b7950 dnp=ffffc900023afe00 used=3176415 delta=-6138
���ۍoO�p�>���dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff880078dfd410 dnp=ffffc9000540e800 used=969804 delta=-9207
���ۍoOq�>���dnode.cdnode_diduse_spaceds=mos obj=1185 dn=ffff880078be8990 dnp=ffffc900023b3200 used=2071575 delta=-6138
���ۍoO�q�>���dnode.cdnode_diduse_spaceds=mos obj=1185 dn=ffff880078be8990 dnp=ffffc900023b3200 used=2065437 delta=-39897
���ۍoO�r�>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34357455 delta=-42966
���ۍoO�r�>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ۍoO5s�>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ۍoO�s�>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
d���ۍoOD��M�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:4600172f800:c00> DVA[1]=<0:250006cb400:c00> DVA[2]=<0:400634c800:c00> [L0 SPA space map] fletcher4 lzjb LE contiguous unique triple size=1000L/400P birth=33765991L/33765991P fill=1 cksum=3a09c2b7fd:20799b37fd5d:a9fa52a1ea7d6:29939a875641db6
g���ۍoOM��M�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46001730400:c00> DVA[1]=<0:250006d8600:c00> DVA[2]=<0:400634d400:c00> [L1 SPA space map] fletcher4 lzjb LE contiguous unique triple size=4000L/800P birth=33765991L/33765991P fill=22 cksum=b94f42a7ce:bd3d5ee6d516:78e1b71924bf07:3a8cb88693d7cb90
b���ۍoO���G�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000eb3200:600> DVA[1]=<0:250005b2600:600> DVA[2]=<0:400222a200:600> [L0 SPA space map] fletcher4 lzjb LE contiguous unique triple size=1000L/200P birth=33765991L/33765991P fill=1 cksum=244e9d1872:90758ee5be9:15c5c9e21d126:28b002ddcde0f4
m���ۍoO���I�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000ecb200:1e00> DVA[1]=<0:250006b3a00:1e00> DVA[2]=<0:4003179400:1e00> [L1 SPA space map] fletcher4 lzjb LE contiguous unique triple size=4000L/1200P birth=33765991L/33765991P fill=75 cksum=1ac383e336e:411418b4e8eff:631080e77ce6f49:7d054394f62d10b
c���ۍoOw��S�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46001732800:c00> DVA[1]=<0:250006dbc00:c00> DVA[2]=<0:400634f800:c00> [L0 DMU dnode] fletcher4 lzjb LE contiguous unique triple size=4000L/600P birth=33765991L/33765991P fill=32 cksum=71806ecd67:6c1e40a39d9e:396152af384a9c:15d5a3c07b5aeb6e
c���ۍoO���S�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46001731c00:c00> DVA[1]=<0:250006db000:c00> DVA[2]=<0:400634ec00:c00> [L0 DMU dnode] fletcher4 lzjb LE contiguous unique triple size=4000L/800P birth=33765991L/33765991P fill=32 cksum=9b38692b27:ac62907d6570:770a9216f18f58:3dadd848c92494c7
d���ۍoO���S�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46001731000:c00> DVA[1]=<0:250006d9200:c00> DVA[2]=<0:400634e000:c00> [L0 SPA space map] fletcher4 lzjb LE contiguous unique triple size=1000L/400P birth=33765991L/33765991P fill=1 cksum=2f77f16643:1ce1562a7e1b:9a5bc61316756:255c9791a17598b
k���ۍoO���S�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46000ece200:1200> DVA[1]=<0:250006d9e00:1200> DVA[2]=<0:400318ae00:1200> [L1 SPA space map] fletcher4 lzjb LE contiguous unique triple size=4000L/a00P birth=33765991L/33765991P fill=37 cksum=ff5d098057:12920a3050e76:f12f89e1f38118:9476f378cfbcf993
c���ۍoO���S�`dsl_dataset.cdsl_dataset_block_bornds=          (null) DVA[0]=<0:46001733400:c00> DVA[1]=<0:250006dc800:c00> DVA[2]=<0:4006350400:c00> [L0 DMU dnode] fletcher4 lzjb LE contiguous unique triple size=4000L/600P birth=33765991L/33765991P fill=31 cksum=7b917899b1:6c94eeabbd3a:37a1e2afa052c6:14d5dc839fdc8642
���ۍoOq��>���dnode.cdnode_diduse_spaceds=mos obj=1071 dn=ffff8800785b7950 dnp=ffffc900023afe00 used=3127311 delta=0
���ۍoO���>���dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff880078dfd410 dnp=ffffc9000540e800 used=926838 delta=0
���ۍoOq��>���dnode.cdnode_diduse_spaceds=mos obj=1185 dn=ffff880078be8990 dnp=ffffc900023b3200 used=2025540 delta=0
���ۍoOѾ�>���dnode.cdnode_diduse_spaceds=mos obj=1185 dn=ffff880078be8990 dnp=ffffc900023b3200 used=2025540 delta=0
���ۍoO+��>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ۍoOſ�>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ۍoOK��>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ۍoO���>���dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff880078beb378 dnp=ffffc90002376a00 used=34271523 delta=0
���ۍoO����$�txg.ctxg_wait_syncedbroadcasting sync more tx_synced=33765991 waiting=33765992 dp=ffff8800c8717000
���ۍoOu�>���untu-4/var obj=16455 lvl=0 blkid=-1 size=140
~��ۍoO�����dmu_tx.cdmu_tx_committowrite=11403264 written=6684672 tofree=0 freed=167772
�ۍoO���Cspl-err.cvcmn_errWARNING: ZFS replay transaction error 5, dataset moxo/ROOT/ubuntu-4/var, seq 0x23d4, txtype 9 

���ۍoO���i�zil.czil_parseASSERTION(!claimed || !(zh->zh_flags & ZIL_CLAIM_LR_SEQ_VALID) || (max_blk_seq == claim_blk_seq && max_lr_seq == claim_lr_seq)) failed
J��ۍoO���i�zil.czil_parseSPL PANIC

Second /tmp/spl-log.1332710880.7800

}�����oO��w���txg.ctxg_quiesce_threadtxg=33765993 quiesce_txg=33765994 sync_txg=33765992
p�����oO��w���txg.ctxg_quiesce_threadquiesce done, handing off txg 33765993
z�����oO��x���txg.ctxg_sync_threadtxg=33765993 quiesce_txg=33765994 sync_txg=33765992
g�����oO
�x���dbuf.cdbuf_dirtyds=mos obj=21 lvl=0 blkid=-1 size=40
b�����oO��x���dnode.cdnode_setdirtyds=mos obj=21 txg=33765993
i�����oO��x���dbuf.cdbuf_dirtyds=mos obj=mdn lvl=0 blkid=0 size=4000
v�����oO��x��dnode.cdnode_clear_rangeds=mos obj=mdn blkid=0 nblks=1 txg=33765993
i�����oO��x���dbuf.cdbuf_dirtyds=mos obj=mdn lvl=1 blkid=0 size=4000
i�����oO"�x���dbuf.cdbuf_dirtyds=mos obj=mdn lvl=2 blkid=0 size=4000
h�����oO6�x���dbuf.cdbuf_dirtyds=mos obj=21 lvl=1 blkid=0 size=4000
h�����oO:�x���dbuf.cdbuf_dirtyds=mos obj=21 lvl=2 blkid=0 size=4000
������oO>�x��dnode.cdnode_clear_rangeds=mos obj=21 blkid=0 nblks=1125899906842624 txg=33765993
������oOB�x�dnode.cdnode_free_rangeds=mos obj=21 blkid=0 nblks=1125899906842624 txg=33765993
c�����oOD�x�V�dbuf.cdbuf_free_rangeds=mos obj=21 start=0 end=0
n�����oOF�x�l�dbuf.cdbuf_free_rangeds=mos obj=21 lvl=0 blkid=0 found buf 
k�����oOn�x���dbuf.cdbuf_dirtyds=mos obj=28683 lvl=0 blkid=-1 size=140
e�����oOq�x���dnode.cdnode_setdirtyds=mos obj=28683 txg=33765993
k�����oOt�x���dbuf.cdbuf_dirtyds=mos obj=mdn lvl=0 blkid=896 size=4000
x�����oOv�x��dnode.cdnode_clear_rangeds=mos obj=mdn blkid=896 nblks=1 txg=33765993
i�����oO{�x���dbuf.cdbuf_dirtyds=mos obj=mdn lvl=1 blkid=7 size=4000
t�����oO��x�M�dmu_objset.cdmu_objset_syncds=moxo/ROOT/ubuntu-4/var txg=33765993
t������oO��x��    dbuf.cdbuf_sync_indirectds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=6 blkid=0 blkptr=ffffc900072b5640 DVA[0]=<0:460016e6000:c00> DVA[1]=<0:25000406200:c00> [L6 DMU dnode] fletcher4 lzjb LE contiguous unique double size=4000L/400P birth=33765990L/33765990P fill=13980 cksum=587fa56f5d:3c2a7af086be:15a5aa013978e5:5741a4c56d74e19
t������oO��x��    dbuf.cdbuf_sync_indirectds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=5 blkid=0 blkptr=ffffc9000489c000 DVA[0]=<0:460016e2400:c00> DVA[1]=<0:25000402c00:c00> [L5 DMU dnode] fletcher4 lzjb LE contiguous unique double size=4000L/400P birth=33765990L/33765990P fill=13980 cksum=57f49f70d3:3ba6907c8c90:1566d1642b2030:5600f3ae5c21a0d
t������oO��x��    dbuf.cdbuf_sync_indirectds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=4 blkid=0 blkptr=ffffc90004897000 DVA[0]=<0:460016e0c00:c00> DVA[1]=<0:25000402000:c00> [L4 DMU dnode] fletcher4 lzjb LE contiguous unique double size=4000L/400P birth=33765990L/33765990P fill=13980 cksum=57f0d4c581:3b9e86a054ad:1560ee29cde9b6:55d8b0e9e3c8125
t������oO��x��    dbuf.cdbuf_sync_indirectds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=3 blkid=0 blkptr=ffffc90004892000 DVA[0]=<0:460016dbe00:c00> DVA[1]=<0:25000401400:c00> [L3 DMU dnode] fletcher4 lzjb LE contiguous unique double size=4000L/400P birth=33765990L/33765990P fill=13980 cksum=592ba31699:3cd1d4a31895:15f78819cab43f:58ef25ae178d4b9
t������oOǬx��    dbuf.cdbuf_sync_indirectds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=2 blkid=0 blkptr=ffffc900096cd000 DVA[0]=<0:460016db200:c00> DVA[1]=<0:250003b7600:c00> [L2 DMU dnode] fletcher4 lzjb LE contiguous unique double size=4000L/400P birth=33765990L/33765990P fill=13980 cksum=678db950ff:376e971d44c8:1134e54328658b:3fafbf8733d4538
q������oOլx��    dbuf.cdbuf_sync_indirectds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=1 blkid=4 blkptr=ffffc900096c3200 DVA[0]=<0:460016d8e00:c00> DVA[1]=<0:250003b6a00:c00> [L1 DMU dnode] fletcher4 lzjb LE contiguous unique double size=4000L/400P birth=33765990L/33765990P fill=50 cksum=6870a489e3:3ac5698d9747:12c05adacdc746:4643926bae48421
p������oO��x�M    dbuf.cdbuf_sync_leafds=moxo/ROOT/ubuntu-4/var obj=mdn lvl=0 blkid=514 blkptr=ffffc9000488d100 DVA[0]=<0:460016d8200:c00> DVA[1]=<0:250003b5e00:c00> [L0 DMU dnode] fletcher4 lzjb LE contiguous unique double size=4000L/800P birth=33765990L/33765990P fill=10 cksum=9f098db5f2:9a23a3688d1a:63c046a4276cda:313ecb699980d5b8
y������oO��x��    dbuf.cdbuf_sync_indirectds=moxo/ROOT/ubuntu-4/var obj=16455 lvl=2 blkid=0 blkptr=ffffc90004888e40 DVA[0]=<0:460016d7600:c00> DVA[1]=<0:250003b4000:c00> [L2 ZFS plain file] fletcher4 lzjb LE contiguous unique double size=4000L/400P birth=33765990L/33765990P fill=296 cksum=68683ebada:3b47c5dc4c56:12f6a0aee5f7e4:46eb0f8fd50d6be
y������oO �x��  dbuf.cdbuf_sync_indirectds=moxo/ROOT/ubuntu-4/var obj=16455 lvl=1 blkid=2 blkptr=ffffc90004883100 DVA[0]=<0:460016d3a00:c00> DVA[1]=<0:250003b3400:c00> [L1 ZFS plain file] fletcher4 lzjb LE contiguous unique double size=4000L/800P birth=33765990L/33765990P fill=31 cksum=b356484149:d3819dd56b36:914de57cf5d9a9:49609e56df982462
m������oO��x�M  dbuf.cdbuf_sync_leafds=moxo/ROOT/ubuntu-4/var obj=16455 lvl=0 blkid=272 blkptr=ffffc90002416800 DVA[0]=<0:46083b01a00:30000> [L0 ZFS plain file] fletcher4 uncompressed LE contiguous unique single size=20000L/20000P birth=33765990L/33765990P fill=1 cksum=1e4e6c4e872:c65d251c4f4127:98e876dfb4e267fd:78cfe1d3b9bb6e98
������oO �x�M dbuf.cdbuf_sync_leafds=moxo/ROOT/ubuntu-4/var obj=16455 lvl=0 blkid=-1 blkptr=          (null) <NULL>
s�����oO(�x��zil.czil_syncASSERTION(zh->zh_replay_seq < *replayed_seq) failed
I�����oO4�x��zil.czil_syncSPL PANIC
�����oO��>���dnode.cdnode_diduse_spaceds=moxo/ROOT/ubuntu-4/var obj=16455 dn=ffff880064a058b8 dnp=ffffc90004888e00 used=38796252 delta=0
�����oO��>���dnode.cdnode_diduse_spaceds=moxo/ROOT/ubuntu-4/var obj=16455 dn=ffff880064a058b8 dnp=ffffc90004888e00 used=38796252 delta=0

@dajhorn
Copy link
Contributor

dajhorn commented Mar 25, 2012

The pool becomes importable again using modprobe zfs zil_replay_disable=1, but the system still fails during basic loads. However, the debugging message now has an assertion.

[ 1352.489364] SPL: Loaded module v0.6.0.55-rc7 (DEBUG mode), using hostid 0x007f0101
[ 1352.491954] zunicode: module license 'CDDL' taints kernel.
[ 1352.491960] Disabling lock debugging due to kernel taint
[ 1352.569455] ZFS: Loaded module v0.6.0.55-rc7 (DEBUG mode), ZFS pool version 28, ZFS filesystem version 5
[ 3136.288077] SPLError: 7780:0:(dbuf.c:806:dbuf_unoverride()) ASSERTION(dr->dt.dl.dr_override_state != DR_IN_DMU_SYNC) failed
[ 3136.288085] SPLError: 7780:0:(dbuf.c:806:dbuf_unoverride()) SPL PANIC
[ 3136.288088] SPL: Showing stack for process 7780
[ 3136.288093] Pid: 7780, comm: flush-zfs-37 Tainted: P           O 3.2.0-20-generic #32-Ubuntu
[ 3136.288096] Call Trace:
[ 3136.288114]  [<ffffffffa0255477>] spl_debug_dumpstack+0x27/0x40 [spl]
[ 3136.288124]  [<ffffffffa0256952>] spl_debug_bug+0x82/0xe0 [spl]
[ 3136.288164]  [<ffffffffa031dcbe>] dbuf_unoverride+0x1be/0x210 [zfs]
[ 3136.288188]  [<ffffffffa03237d5>] dbuf_dirty+0x11b5/0x1560 [zfs]
[ 3136.288211]  [<ffffffffa031f77b>] ? dbuf_read+0x82b/0xcf0 [zfs]
[ 3136.288249]  [<ffffffffa037430e>] ? refcount_remove_many+0x19e/0x2c0 [zfs]
[ 3136.288273]  [<ffffffffa032cbf6>] ? dmu_buf_hold_array_by_dnode+0x256/0x6a0 [zfs]
[ 3136.288300]  [<ffffffffa03437a8>] ? dnode_rele+0x58/0xe0 [zfs]
[ 3136.288323]  [<ffffffffa0324787>] dmu_buf_will_dirty+0xa7/0x180 [zfs]
[ 3136.288348]  [<ffffffffa032d365>] dmu_write+0x85/0x250 [zfs]
[ 3136.288388]  [<ffffffffa03da315>] zfs_putpage+0x1b5/0x320 [zfs]
[ 3136.288395]  [<ffffffff811317d3>] ? vma_prio_tree_next+0x43/0x80
[ 3136.288431]  [<ffffffffa03f4ea0>] zpl_putpage+0x60/0x130 [zfs]
[ 3136.288437]  [<ffffffff8112197d>] write_cache_pages+0x20d/0x460
[ 3136.288472]  [<ffffffffa03f4e40>] ? zpl_readpage+0xc0/0xc0 [zfs]
[ 3136.288507]  [<ffffffffa03f4d78>] zpl_writepages+0x18/0x20 [zfs]
[ 3136.288512]  [<ffffffff81122ae1>] do_writepages+0x21/0x40
[ 3136.288518]  [<ffffffff811a0f00>] writeback_single_inode+0x180/0x430
[ 3136.288522]  [<ffffffff811a15c6>] writeback_sb_inodes+0x1b6/0x270
[ 3136.288527]  [<ffffffff810570eb>] ? check_preempt_wakeup+0x15b/0x230
[ 3136.288532]  [<ffffffff811a171e>] __writeback_inodes_wb+0x9e/0xd0
[ 3136.288536]  [<ffffffff811a19cb>] wb_writeback+0x27b/0x330
[ 3136.288542]  [<ffffffff810126e5>] ? __switch_to+0xf5/0x360
[ 3136.288547]  [<ffffffff811930b2>] ? get_nr_dirty_inodes+0x52/0x80
[ 3136.288551]  [<ffffffff811a1b1f>] wb_check_old_data_flush+0x9f/0xb0
[ 3136.288556]  [<ffffffff811a2a11>] wb_do_writeback+0x151/0x1d0
[ 3136.288561]  [<ffffffff8165c17e>] ? _raw_spin_lock_irqsave+0x2e/0x40
[ 3136.288567]  [<ffffffff81076c20>] ? usleep_range+0x50/0x50
[ 3136.288571]  [<ffffffff811a2b13>] bdi_writeback_thread+0x83/0x2a0
[ 3136.288576]  [<ffffffff811a2a90>] ? wb_do_writeback+0x1d0/0x1d0
[ 3136.288581]  [<ffffffff8108a45c>] kthread+0x8c/0xa0
[ 3136.288586]  [<ffffffff81666674>] kernel_thread_helper+0x4/0x10
[ 3136.288590]  [<ffffffff8108a3d0>] ? flush_kthread_worker+0xa0/0xa0
[ 3136.288594]  [<ffffffff81666670>] ? gs_change+0x13/0x13
[ 3136.288662] SPL: Dumping log to /tmp/spl-log.1332715670.7780
[ 3363.752072] INFO: task z_wr_int_h/0:19250 blocked for more than 120 seconds.
[ 3363.752076] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3363.752080] z_wr_int_h/0    D 0000000000000000     0 19250      2 0x00000000
[ 3363.752087]  ffff88008085fab0 0000000000000046 ffff880082eb4d80 00000003ffffffff
[ 3363.752094]  ffff88008085ffd8 ffff88008085ffd8 ffff88008085ffd8 0000000000013780
[ 3363.752100]  ffff8800805444d0 ffff880109db96f0 ffff88008085fac0 ffff88004953eca0
[ 3363.752107] Call Trace:
[ 3363.752118]  [<ffffffff81659fdf>] schedule+0x3f/0x60
[ 3363.752123]  [<ffffffff8165ade7>] __mutex_lock_slowpath+0xd7/0x150
[ 3363.752162]  [<ffffffffa030c692>] ? arc_change_state+0x32/0x8a0 [zfs]
[ 3363.752167]  [<ffffffff8165a9fa>] mutex_lock+0x2a/0x50
[ 3363.752192]  [<ffffffffa032b53a>] dmu_sync_done+0x3a/0x250 [zfs]
[ 3363.752214]  [<ffffffffa030c4fb>] ? buf_hash_insert+0x5b/0x1c0 [zfs]
[ 3363.752236]  [<ffffffffa0310dc7>] arc_write_done+0x147/0x610 [zfs]
[ 3363.752241]  [<ffffffff8165a9ed>] ? mutex_lock+0x1d/0x50
[ 3363.752283]  [<ffffffffa03ef7a2>] zio_done+0x2b2/0x1740 [zfs]
[ 3363.752318]  [<ffffffffa03a0114>] ? vdev_mirror_map_free+0x24/0x30 [zfs]
[ 3363.752354]  [<ffffffffa03e6137>] ? zio_vdev_io_assess+0x57/0x290 [zfs]
[ 3363.752389]  [<ffffffffa03efcf0>] zio_done+0x800/0x1740 [zfs]
[ 3363.752425]  [<ffffffffa03a1af0>] ? vdev_raidz_map_free_vsd+0x30/0xa0 [zfs]
[ 3363.752461]  [<ffffffffa03efcf0>] zio_done+0x800/0x1740 [zfs]
[ 3363.752495]  [<ffffffffa03e59fe>] ? zio_wait_for_children+0x6e/0xd0 [zfs]
[ 3363.752531]  [<ffffffffa03e720d>] zio_execute+0xed/0x2d0 [zfs]
[ 3363.752537]  [<ffffffff8104dec3>] ? __wake_up+0x53/0x70
[ 3363.752552]  [<ffffffffa0260716>] taskq_thread+0x276/0x850 [spl]
[ 3363.752558]  [<ffffffff810562ca>] ? finish_task_switch+0x4a/0xf0
[ 3363.752563]  [<ffffffff8105fad0>] ? try_to_wake_up+0x200/0x200
[ 3363.752573]  [<ffffffffa02604a0>] ? __taskq_create+0x6e0/0x6e0 [spl]
[ 3363.752579]  [<ffffffff8108a45c>] kthread+0x8c/0xa0
[ 3363.752585]  [<ffffffff81666674>] kernel_thread_helper+0x4/0x10
[ 3363.752589]  [<ffffffff8108a3d0>] ? flush_kthread_worker+0xa0/0xa0
[ 3363.752594]  [<ffffffff81666670>] ? gs_change+0x13/0x13
[ 3363.752600] INFO: task txg_quiesce:19283 blocked for more than 120 seconds.
[ 3363.752603] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3363.752606] txg_quiesce     D ffffffff81806240     0 19283      2 0x00000000
[ 3363.752612]  ffff880078421d40 0000000000000046 ffff880000000034 0000000000000049
[ 3363.752619]  ffff880078421fd8 ffff880078421fd8 ffff880078421fd8 0000000000013780
[ 3363.752625]  ffff880110b196f0 ffff88007eef5bc0 ffff880078421d50 ffffc9000063e358
[ 3363.752631] Call Trace:
[ 3363.752635]  [<ffffffff81659fdf>] schedule+0x3f/0x60
[ 3363.752647]  [<ffffffffa0268a95>] cv_wait_common+0xd5/0x330 [spl]
[ 3363.752651]  [<ffffffff8108aef0>] ? add_wait_queue+0x60/0x60
[ 3363.752661]  [<ffffffffa0268d23>] __cv_wait+0x13/0x20 [spl]
[ 3363.752697]  [<ffffffffa039149b>] txg_quiesce_thread+0x1fb/0x390 [zfs]
[ 3363.752733]  [<ffffffffa03912a0>] ? txg_do_callbacks+0x100/0x100 [zfs]
[ 3363.752742]  [<ffffffffa025e8e1>] thread_generic_wrapper+0x81/0xe0 [spl]
[ 3363.752751]  [<ffffffffa025e860>] ? __thread_create+0x360/0x360 [spl]
[ 3363.752755]  [<ffffffff8108a45c>] kthread+0x8c/0xa0
[ 3363.752760]  [<ffffffff81666674>] kernel_thread_helper+0x4/0x10
[ 3363.752764]  [<ffffffff8108a3d0>] ? flush_kthread_worker+0xa0/0xa0
[ 3363.752768]  [<ffffffff81666670>] ? gs_change+0x13/0x13
[ 3363.752778] INFO: task apt-get:32073 blocked for more than 120 seconds.
[ 3363.752780] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3363.752783] apt-get         D 0000000000000001     0 32073  19485 0x00000000
[ 3363.752788]  ffff880113527a88 0000000000000086 ffff880113527a88 ffffffffa03e5b24
[ 3363.752794]  ffff880113527fd8 ffff880113527fd8 ffff880113527fd8 0000000000013780
[ 3363.752800]  ffff8800890e0000 ffff88000ae8ade0 ffff880113527a98 ffff88003d9ba6d8
[ 3363.752805] Call Trace:
[ 3363.752841]  [<ffffffffa03e5b24>] ? zio_taskq_dispatch+0xc4/0x1c0 [zfs]
[ 3363.752845]  [<ffffffff81659fdf>] schedule+0x3f/0x60
[ 3363.752855]  [<ffffffffa0268a95>] cv_wait_common+0xd5/0x330 [spl]
[ 3363.752859]  [<ffffffff8108aef0>] ? add_wait_queue+0x60/0x60
[ 3363.752869]  [<ffffffffa0268d23>] __cv_wait+0x13/0x20 [spl]
[ 3363.752904]  [<ffffffffa03ebe1b>] zio_wait+0x1db/0x3e0 [zfs]
[ 3363.752940]  [<ffffffffa03e3e55>] zil_commit+0x5b5/0xad0 [zfs]
[ 3363.752949]  [<ffffffffa025a097>] ? kmem_free_debug+0x57/0x1b0 [spl]
[ 3363.752985]  [<ffffffffa039072f>] ? txg_rele_to_sync+0x6f/0xe0 [zfs]
[ 3363.753021]  [<ffffffffa03da3a2>] zfs_putpage+0x242/0x320 [zfs]
[ 3363.753027]  [<ffffffff811317d3>] ? vma_prio_tree_next+0x43/0x80
[ 3363.753062]  [<ffffffffa03f4ea0>] zpl_putpage+0x60/0x130 [zfs]
[ 3363.753067]  [<ffffffff8112197d>] write_cache_pages+0x20d/0x460
[ 3363.753072]  [<ffffffff8113a097>] ? do_anonymous_page.isra.38+0x247/0x2f0
[ 3363.753106]  [<ffffffffa03f4e40>] ? zpl_readpage+0xc0/0xc0 [zfs]
[ 3363.753141]  [<ffffffffa03f4d78>] zpl_writepages+0x18/0x20 [zfs]
[ 3363.753146]  [<ffffffff81122ae1>] do_writepages+0x21/0x40
[ 3363.753151]  [<ffffffff81118e1b>] __filemap_fdatawrite_range+0x5b/0x60
[ 3363.753156]  [<ffffffff81118e72>] filemap_write_and_wait_range+0x52/0x80
[ 3363.753190]  [<ffffffffa03f4964>] zpl_fsync+0x44/0xe0 [zfs]
[ 3363.753194]  [<ffffffff811419ee>] ? remove_vma+0x6e/0x90
[ 3363.753200]  [<ffffffff811a635b>] vfs_fsync+0x2b/0x40
[ 3363.753205]  [<ffffffff81146744>] sys_msync+0x144/0x1d0
[ 3363.753209]  [<ffffffff81664502>] system_call_fastpath+0x16/0x1b
[ 3363.753215] INFO: task flush-zfs-37:7780 blocked for more than 120 seconds.
[ 3363.753217] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3363.753220] flush-zfs-37    D ffffffff81806240     0  7780      2 0x00000000
[ 3363.753225]  ffff88003cbad6c0 0000000000000046 0000000000000000 0000000002033c47
[ 3363.753231]  ffff88003cbadfd8 ffff88003cbadfd8 ffff88003cbadfd8 0000000000013780
[ 3363.753237]  ffff880110b196f0 ffff8800146916f0 ffffffff00000001 0000000000000000
[ 3363.753242] Call Trace:
[ 3363.753246]  [<ffffffff81659fdf>] schedule+0x3f/0x60
[ 3363.753254]  [<ffffffffa025698d>] spl_debug_bug+0xbd/0xe0 [spl]
[ 3363.753277]  [<ffffffffa031dcbe>] dbuf_unoverride+0x1be/0x210 [zfs]
[ 3363.753301]  [<ffffffffa03237d5>] dbuf_dirty+0x11b5/0x1560 [zfs]
[ 3363.753323]  [<ffffffffa031f77b>] ? dbuf_read+0x82b/0xcf0 [zfs]
[ 3363.753357]  [<ffffffffa037430e>] ? refcount_remove_many+0x19e/0x2c0 [zfs]
[ 3363.753381]  [<ffffffffa032cbf6>] ? dmu_buf_hold_array_by_dnode+0x256/0x6a0 [zfs]
[ 3363.753409]  [<ffffffffa03437a8>] ? dnode_rele+0x58/0xe0 [zfs]
[ 3363.753432]  [<ffffffffa0324787>] dmu_buf_will_dirty+0xa7/0x180 [zfs]
[ 3363.753456]  [<ffffffffa032d365>] dmu_write+0x85/0x250 [zfs]
[ 3363.753491]  [<ffffffffa03da315>] zfs_putpage+0x1b5/0x320 [zfs]
[ 3363.753496]  [<ffffffff811317d3>] ? vma_prio_tree_next+0x43/0x80
[ 3363.753531]  [<ffffffffa03f4ea0>] zpl_putpage+0x60/0x130 [zfs]
[ 3363.753535]  [<ffffffff8112197d>] write_cache_pages+0x20d/0x460
[ 3363.753570]  [<ffffffffa03f4e40>] ? zpl_readpage+0xc0/0xc0 [zfs]
[ 3363.753605]  [<ffffffffa03f4d78>] zpl_writepages+0x18/0x20 [zfs]
[ 3363.753609]  [<ffffffff81122ae1>] do_writepages+0x21/0x40
[ 3363.753614]  [<ffffffff811a0f00>] writeback_single_inode+0x180/0x430
[ 3363.753618]  [<ffffffff811a15c6>] writeback_sb_inodes+0x1b6/0x270
[ 3363.753622]  [<ffffffff810570eb>] ? check_preempt_wakeup+0x15b/0x230
[ 3363.753627]  [<ffffffff811a171e>] __writeback_inodes_wb+0x9e/0xd0
[ 3363.753631]  [<ffffffff811a19cb>] wb_writeback+0x27b/0x330
[ 3363.753636]  [<ffffffff810126e5>] ? __switch_to+0xf5/0x360
[ 3363.753641]  [<ffffffff811930b2>] ? get_nr_dirty_inodes+0x52/0x80
[ 3363.753646]  [<ffffffff811a1b1f>] wb_check_old_data_flush+0x9f/0xb0
[ 3363.753650]  [<ffffffff811a2a11>] wb_do_writeback+0x151/0x1d0
[ 3363.753655]  [<ffffffff8165c17e>] ? _raw_spin_lock_irqsave+0x2e/0x40
[ 3363.753660]  [<ffffffff81076c20>] ? usleep_range+0x50/0x50
[ 3363.753664]  [<ffffffff811a2b13>] bdi_writeback_thread+0x83/0x2a0
[ 3363.753669]  [<ffffffff811a2a90>] ? wb_do_writeback+0x1d0/0x1d0
[ 3363.753673]  [<ffffffff8108a45c>] kthread+0x8c/0xa0
[ 3363.753677]  [<ffffffff81666674>] kernel_thread_helper+0x4/0x10
[ 3363.753681]  [<ffffffff8108a3d0>] ? flush_kthread_worker+0xa0/0xa0
[ 3363.753686]  [<ffffffff81666670>] ? gs_change+0x13/0x13
[ 3483.752072] INFO: task z_wr_int_h/0:19250 blocked for more than 120 seconds.
[ 3483.752076] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3483.752080] z_wr_int_h/0    D 0000000000000000     0 19250      2 0x00000000
[ 3483.752087]  ffff88008085fab0 0000000000000046 ffff880082eb4d80 00000003ffffffff
[ 3483.752094]  ffff88008085ffd8 ffff88008085ffd8 ffff88008085ffd8 0000000000013780
[ 3483.752101]  ffff8800805444d0 ffff880109db96f0 ffff88008085fac0 ffff88004953eca0
[ 3483.752107] Call Trace:
[ 3483.752118]  [<ffffffff81659fdf>] schedule+0x3f/0x60
[ 3483.752123]  [<ffffffff8165ade7>] __mutex_lock_slowpath+0xd7/0x150
[ 3483.752165]  [<ffffffffa030c692>] ? arc_change_state+0x32/0x8a0 [zfs]
[ 3483.752170]  [<ffffffff8165a9fa>] mutex_lock+0x2a/0x50
[ 3483.752195]  [<ffffffffa032b53a>] dmu_sync_done+0x3a/0x250 [zfs]
[ 3483.752217]  [<ffffffffa030c4fb>] ? buf_hash_insert+0x5b/0x1c0 [zfs]
[ 3483.752239]  [<ffffffffa0310dc7>] arc_write_done+0x147/0x610 [zfs]
[ 3483.752244]  [<ffffffff8165a9ed>] ? mutex_lock+0x1d/0x50
[ 3483.752287]  [<ffffffffa03ef7a2>] zio_done+0x2b2/0x1740 [zfs]
[ 3483.752323]  [<ffffffffa03a0114>] ? vdev_mirror_map_free+0x24/0x30 [zfs]
[ 3483.752359]  [<ffffffffa03e6137>] ? zio_vdev_io_assess+0x57/0x290 [zfs]
[ 3483.752394]  [<ffffffffa03efcf0>] zio_done+0x800/0x1740 [zfs]
[ 3483.752431]  [<ffffffffa03a1af0>] ? vdev_raidz_map_free_vsd+0x30/0xa0 [zfs]
[ 3483.752467]  [<ffffffffa03efcf0>] zio_done+0x800/0x1740 [zfs]
[ 3483.752502]  [<ffffffffa03e59fe>] ? zio_wait_for_children+0x6e/0xd0 [zfs]
[ 3483.752538]  [<ffffffffa03e720d>] zio_execute+0xed/0x2d0 [zfs]
[ 3483.752544]  [<ffffffff8104dec3>] ? __wake_up+0x53/0x70
[ 3483.752560]  [<ffffffffa0260716>] taskq_thread+0x276/0x850 [spl]
[ 3483.752566]  [<ffffffff810562ca>] ? finish_task_switch+0x4a/0xf0
[ 3483.752571]  [<ffffffff8105fad0>] ? try_to_wake_up+0x200/0x200
[ 3483.752581]  [<ffffffffa02604a0>] ? __taskq_create+0x6e0/0x6e0 [spl]
[ 3483.752587]  [<ffffffff8108a45c>] kthread+0x8c/0xa0
[ 3483.752593]  [<ffffffff81666674>] kernel_thread_helper+0x4/0x10
[ 3483.752598]  [<ffffffff8108a3d0>] ? flush_kthread_worker+0xa0/0xa0
[ 3483.752602]  [<ffffffff81666670>] ? gs_change+0x13/0x13
[ 3483.752608] INFO: task txg_quiesce:19283 blocked for more than 120 seconds.
[ 3483.752611] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3483.752614] txg_quiesce     D ffffffff81806240     0 19283      2 0x00000000
[ 3483.752620]  ffff880078421d40 0000000000000046 ffff880000000034 0000000000000049
[ 3483.752626]  ffff880078421fd8 ffff880078421fd8 ffff880078421fd8 0000000000013780
[ 3483.752632]  ffff880110b196f0 ffff88007eef5bc0 ffff880078421d50 ffffc9000063e358
[ 3483.752638] Call Trace:
[ 3483.752643]  [<ffffffff81659fdf>] schedule+0x3f/0x60
[ 3483.752654]  [<ffffffffa0268a95>] cv_wait_common+0xd5/0x330 [spl]
[ 3483.752660]  [<ffffffff8108aef0>] ? add_wait_queue+0x60/0x60
[ 3483.752670]  [<ffffffffa0268d23>] __cv_wait+0x13/0x20 [spl]
[ 3483.752707]  [<ffffffffa039149b>] txg_quiesce_thread+0x1fb/0x390 [zfs]
[ 3483.752743]  [<ffffffffa03912a0>] ? txg_do_callbacks+0x100/0x100 [zfs]
[ 3483.752753]  [<ffffffffa025e8e1>] thread_generic_wrapper+0x81/0xe0 [spl]
[ 3483.752763]  [<ffffffffa025e860>] ? __thread_create+0x360/0x360 [spl]
[ 3483.752768]  [<ffffffff8108a45c>] kthread+0x8c/0xa0
[ 3483.752773]  [<ffffffff81666674>] kernel_thread_helper+0x4/0x10
[ 3483.752778]  [<ffffffff8108a3d0>] ? flush_kthread_worker+0xa0/0xa0
[ 3483.752782]  [<ffffffff81666670>] ? gs_change+0x13/0x13
[ 3483.752792] INFO: task apt-get:32073 blocked for more than 120 seconds.
[ 3483.752795] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3483.752797] apt-get         D 0000000000000001     0 32073  19485 0x00000000
[ 3483.752803]  ffff880113527a88 0000000000000086 ffff880113527a88 ffffffffa03e5b24
[ 3483.752809]  ffff880113527fd8 ffff880113527fd8 ffff880113527fd8 0000000000013780
[ 3483.752815]  ffff8800890e0000 ffff88000ae8ade0 ffff880113527a98 ffff88003d9ba6d8
[ 3483.752821] Call Trace:
[ 3483.752857]  [<ffffffffa03e5b24>] ? zio_taskq_dispatch+0xc4/0x1c0 [zfs]
[ 3483.752862]  [<ffffffff81659fdf>] schedule+0x3f/0x60
[ 3483.752872]  [<ffffffffa0268a95>] cv_wait_common+0xd5/0x330 [spl]
[ 3483.752877]  [<ffffffff8108aef0>] ? add_wait_queue+0x60/0x60
[ 3483.752887]  [<ffffffffa0268d23>] __cv_wait+0x13/0x20 [spl]
[ 3483.752924]  [<ffffffffa03ebe1b>] zio_wait+0x1db/0x3e0 [zfs]
[ 3483.752960]  [<ffffffffa03e3e55>] zil_commit+0x5b5/0xad0 [zfs]
[ 3483.752970]  [<ffffffffa025a097>] ? kmem_free_debug+0x57/0x1b0 [spl]
[ 3483.753007]  [<ffffffffa039072f>] ? txg_rele_to_sync+0x6f/0xe0 [zfs]
[ 3483.753045]  [<ffffffffa03da3a2>] zfs_putpage+0x242/0x320 [zfs]
[ 3483.753051]  [<ffffffff811317d3>] ? vma_prio_tree_next+0x43/0x80
[ 3483.753087]  [<ffffffffa03f4ea0>] zpl_putpage+0x60/0x130 [zfs]
[ 3483.753093]  [<ffffffff8112197d>] write_cache_pages+0x20d/0x460
[ 3483.753098]  [<ffffffff8113a097>] ? do_anonymous_page.isra.38+0x247/0x2f0
[ 3483.753134]  [<ffffffffa03f4e40>] ? zpl_readpage+0xc0/0xc0 [zfs]
[ 3483.753169]  [<ffffffffa03f4d78>] zpl_writepages+0x18/0x20 [zfs]
[ 3483.753174]  [<ffffffff81122ae1>] do_writepages+0x21/0x40
[ 3483.753180]  [<ffffffff81118e1b>] __filemap_fdatawrite_range+0x5b/0x60
[ 3483.753185]  [<ffffffff81118e72>] filemap_write_and_wait_range+0x52/0x80
[ 3483.753220]  [<ffffffffa03f4964>] zpl_fsync+0x44/0xe0 [zfs]
[ 3483.753225]  [<ffffffff811419ee>] ? remove_vma+0x6e/0x90
[ 3483.753232]  [<ffffffff811a635b>] vfs_fsync+0x2b/0x40
[ 3483.753237]  [<ffffffff81146744>] sys_msync+0x144/0x1d0
[ 3483.753242]  [<ffffffff81664502>] system_call_fastpath+0x16/0x1b
[ 3483.753248] INFO: task flush-zfs-37:7780 blocked for more than 120 seconds.
[ 3483.753250] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3483.753253] flush-zfs-37    D ffffffff81806240     0  7780      2 0x00000000
[ 3483.753259]  ffff88003cbad6c0 0000000000000046 0000000000000000 0000000002033c47
[ 3483.753265]  ffff88003cbadfd8 ffff88003cbadfd8 ffff88003cbadfd8 0000000000013780
[ 3483.753271]  ffff880110b196f0 ffff8800146916f0 ffffffff00000001 0000000000000000
[ 3483.753277] Call Trace:
[ 3483.753281]  [<ffffffff81659fdf>] schedule+0x3f/0x60
[ 3483.753290]  [<ffffffffa025698d>] spl_debug_bug+0xbd/0xe0 [spl]
[ 3483.753315]  [<ffffffffa031dcbe>] dbuf_unoverride+0x1be/0x210 [zfs]
[ 3483.753338]  [<ffffffffa03237d5>] dbuf_dirty+0x11b5/0x1560 [zfs]
[ 3483.753362]  [<ffffffffa031f77b>] ? dbuf_read+0x82b/0xcf0 [zfs]
[ 3483.753396]  [<ffffffffa037430e>] ? refcount_remove_many+0x19e/0x2c0 [zfs]
[ 3483.753420]  [<ffffffffa032cbf6>] ? dmu_buf_hold_array_by_dnode+0x256/0x6a0 [zfs]
[ 3483.753449]  [<ffffffffa03437a8>] ? dnode_rele+0x58/0xe0 [zfs]
[ 3483.753472]  [<ffffffffa0324787>] dmu_buf_will_dirty+0xa7/0x180 [zfs]
[ 3483.753497]  [<ffffffffa032d365>] dmu_write+0x85/0x250 [zfs]
[ 3483.753533]  [<ffffffffa03da315>] zfs_putpage+0x1b5/0x320 [zfs]
[ 3483.753538]  [<ffffffff811317d3>] ? vma_prio_tree_next+0x43/0x80
[ 3483.753574]  [<ffffffffa03f4ea0>] zpl_putpage+0x60/0x130 [zfs]
[ 3483.753579]  [<ffffffff8112197d>] write_cache_pages+0x20d/0x460
[ 3483.753614]  [<ffffffffa03f4e40>] ? zpl_readpage+0xc0/0xc0 [zfs]
[ 3483.753650]  [<ffffffffa03f4d78>] zpl_writepages+0x18/0x20 [zfs]
[ 3483.753655]  [<ffffffff81122ae1>] do_writepages+0x21/0x40
[ 3483.753660]  [<ffffffff811a0f00>] writeback_single_inode+0x180/0x430
[ 3483.753665]  [<ffffffff811a15c6>] writeback_sb_inodes+0x1b6/0x270
[ 3483.753669]  [<ffffffff810570eb>] ? check_preempt_wakeup+0x15b/0x230
[ 3483.753675]  [<ffffffff811a171e>] __writeback_inodes_wb+0x9e/0xd0
[ 3483.753680]  [<ffffffff811a19cb>] wb_writeback+0x27b/0x330
[ 3483.753685]  [<ffffffff810126e5>] ? __switch_to+0xf5/0x360
[ 3483.753691]  [<ffffffff811930b2>] ? get_nr_dirty_inodes+0x52/0x80
[ 3483.753696]  [<ffffffff811a1b1f>] wb_check_old_data_flush+0x9f/0xb0
[ 3483.753701]  [<ffffffff811a2a11>] wb_do_writeback+0x151/0x1d0
[ 3483.753706]  [<ffffffff8165c17e>] ? _raw_spin_lock_irqsave+0x2e/0x40
[ 3483.753711]  [<ffffffff81076c20>] ? usleep_range+0x50/0x50
[ 3483.753717]  [<ffffffff811a2b13>] bdi_writeback_thread+0x83/0x2a0
[ 3483.753721]  [<ffffffff811a2a90>] ? wb_do_writeback+0x1d0/0x1d0
[ 3483.753726]  [<ffffffff8108a45c>] kthread+0x8c/0xa0
[ 3483.753731]  [<ffffffff81666674>] kernel_thread_helper+0x4/0x10
[ 3483.753736]  [<ffffffff8108a3d0>] ? flush_kthread_worker+0xa0/0xa0
[ 3483.753741]  [<ffffffff81666670>] ? gs_change+0x13/0x13
[ 3603.752073] INFO: task z_wr_int_h/0:19250 blocked for more than 120 seconds.
[ 3603.752077] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3603.752081] z_wr_int_h/0    D 0000000000000000     0 19250      2 0x00000000
[ 3603.752088]  ffff88008085fab0 0000000000000046 ffff880082eb4d80 00000003ffffffff
[ 3603.752095]  ffff88008085ffd8 ffff88008085ffd8 ffff88008085ffd8 0000000000013780
[ 3603.752101]  ffff8800805444d0 ffff880109db96f0 ffff88008085fac0 ffff88004953eca0
[ 3603.752108] Call Trace:
[ 3603.752118]  [<ffffffff81659fdf>] schedule+0x3f/0x60
[ 3603.752123]  [<ffffffff8165ade7>] __mutex_lock_slowpath+0xd7/0x150
[ 3603.752163]  [<ffffffffa030c692>] ? arc_change_state+0x32/0x8a0 [zfs]
[ 3603.752168]  [<ffffffff8165a9fa>] mutex_lock+0x2a/0x50
[ 3603.752193]  [<ffffffffa032b53a>] dmu_sync_done+0x3a/0x250 [zfs]
[ 3603.752215]  [<ffffffffa030c4fb>] ? buf_hash_insert+0x5b/0x1c0 [zfs]
[ 3603.752237]  [<ffffffffa0310dc7>] arc_write_done+0x147/0x610 [zfs]
[ 3603.752242]  [<ffffffff8165a9ed>] ? mutex_lock+0x1d/0x50
[ 3603.752284]  [<ffffffffa03ef7a2>] zio_done+0x2b2/0x1740 [zfs]
[ 3603.752320]  [<ffffffffa03a0114>] ? vdev_mirror_map_free+0x24/0x30 [zfs]
[ 3603.752356]  [<ffffffffa03e6137>] ? zio_vdev_io_assess+0x57/0x290 [zfs]
[ 3603.752391]  [<ffffffffa03efcf0>] zio_done+0x800/0x1740 [zfs]
[ 3603.752427]  [<ffffffffa03a1af0>] ? vdev_raidz_map_free_vsd+0x30/0xa0 [zfs]
[ 3603.752463]  [<ffffffffa03efcf0>] zio_done+0x800/0x1740 [zfs]
[ 3603.752498]  [<ffffffffa03e59fe>] ? zio_wait_for_children+0x6e/0xd0 [zfs]
[ 3603.752534]  [<ffffffffa03e720d>] zio_execute+0xed/0x2d0 [zfs]
[ 3603.752540]  [<ffffffff8104dec3>] ? __wake_up+0x53/0x70
[ 3603.752555]  [<ffffffffa0260716>] taskq_thread+0x276/0x850 [spl]
[ 3603.752560]  [<ffffffff810562ca>] ? finish_task_switch+0x4a/0xf0
[ 3603.752565]  [<ffffffff8105fad0>] ? try_to_wake_up+0x200/0x200
[ 3603.752575]  [<ffffffffa02604a0>] ? __taskq_create+0x6e0/0x6e0 [spl]
[ 3603.752581]  [<ffffffff8108a45c>] kthread+0x8c/0xa0
[ 3603.752586]  [<ffffffff81666674>] kernel_thread_helper+0x4/0x10
[ 3603.752591]  [<ffffffff8108a3d0>] ? flush_kthread_worker+0xa0/0xa0
[ 3603.752596]  [<ffffffff81666670>] ? gs_change+0x13/0x13
[ 3603.752602] INFO: task txg_quiesce:19283 blocked for more than 120 seconds.
[ 3603.752605] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 3603.752608] txg_quiesce     D ffffffff81806240     0 19283      2 0x00000000
[ 3603.752614]  ffff880078421d40 0000000000000046 ffff880000000034 0000000000000049
[ 3603.752620]  ffff880078421fd8 ffff880078421fd8 ffff880078421fd8 0000000000013780
[ 3603.752626]  ffff880110b196f0 ffff88007eef5bc0 ffff880078421d50 ffffc9000063e358
[ 3603.752632] Call Trace:
[ 3603.752637]  [<ffffffff81659fdf>] schedule+0x3f/0x60
[ 3603.752648]  [<ffffffffa0268a95>] cv_wait_common+0xd5/0x330 [spl]
[ 3603.752653]  [<ffffffff8108aef0>] ? add_wait_queue+0x60/0x60
[ 3603.752663]  [<ffffffffa0268d23>] __cv_wait+0x13/0x20 [spl]
[ 3603.752699]  [<ffffffffa039149b>] txg_quiesce_thread+0x1fb/0x390 [zfs]
[ 3603.752735]  [<ffffffffa03912a0>] ? txg_do_callbacks+0x100/0x100 [zfs]
[ 3603.752744]  [<ffffffffa025e8e1>] thread_generic_wrapper+0x81/0xe0 [spl]
[ 3603.752753]  [<ffffffffa025e860>] ? __thread_create+0x360/0x360 [spl]
[ 3603.752758]  [<ffffffff8108a45c>] kthread+0x8c/0xa0
[ 3603.752762]  [<ffffffff81666674>] kernel_thread_helper+0x4/0x10
[ 3603.752767]  [<ffffffff8108a3d0>] ? flush_kthread_worker+0xa0/0xa0
[ 3603.752771]  [<ffffffff81666670>] ? gs_change+0x13/0x13

The tail of the /tmp/spl-log.1332715670.7780 file is:

y����oO��TK�dnode.cdnode_clear_rangeds=mos obj=1185 blkid=238 nblks=1 txg=33766470
j����oO��TK��dbuf.cdbuf_dirtyds=mos obj=1185 lvl=1 blkid=1 size=4000
d����oO��TK��dnode.cdnode_setdirtyds=mos obj=1185 txg=33766470
j����oO��TK��dbuf.cdbuf_dirtyds=mos obj=mdn lvl=0 blkid=37 size=4000
w����oO��TK�dnode.cdnode_clear_rangeds=mos obj=mdn blkid=37 nblks=1 txg=33766470
i����oO��TK��dbuf.cdbuf_dirtyds=mos obj=1185 lvl=0 blkid=-1 size=40
g����oO��TK��dbuf.cdbuf_dirtyds=mos obj=2 lvl=0 blkid=-1 size=140
a����oO��TK��dnode.cdnode_setdirtyds=mos obj=2 txg=33766470
g����oO��TKV�dsl_dir.cdsl_dir_syncdd=moxo txg=33766470 towrite=0K
g����oO��TK��dbuf.cdbuf_dirtyds=mos obj=5 lvl=0 blkid=-1 size=140
a����oO��TK��dnode.cdnode_setdirtyds=mos obj=5 txg=33766470
l����oO��TKV�dsl_dir.cdsl_dir_syncdd=moxo/$MOS txg=33766470 towrite=0K
a����oO��TKM�dmu_objset.cdmu_objset_syncds=mos txg=33766470
������oO��TK�   dbuf.cdbuf_sync_indirectds=mos obj=mdn lvl=2 blkid=0 blkptr=ffffc900023bc440 DVA[0]=<0:4612fcae600:6000> DVA[1]=<0:250828f2400:6000> DVA[2]=<0:4084f2f400:6000> [L2 DMU dnode] fletcher4 uncompressed LE contiguous unique triple size=4000L/4000P birth=33766470L/33766470P fill=88288 cksum=e96d236fe9:abbd507992b89:41ca191d47760c1b:b5b28e761350dd6c
������oO��TK�   dbuf.cdbuf_sync_indirectds=mos obj=mdn lvl=1 blkid=0 blkptr=ffffc90004917000 DVA[0]=<0:4612fca8600:6000> DVA[1]=<0:250828ec400:6000> DVA[2]=<0:4084e94c00:6000> [L1 DMU dnode] fletcher4 uncompressed LE contiguous unique triple size=4000L/4000P birth=33766470L/33766470P fill=3545 cksum=18af4f009c7:c880fada7c5dd:439a014c87cf10ad:9b626956e7921d30
������oO��TKM   dbuf.cdbuf_sync_leafds=mos obj=mdn lvl=0 blkid=0 blkptr=ffffc90004912000 DVA[0]=<0:4612fca2600:6000> DVA[1]=<0:250828e6400:6000> DVA[2]=<0:4084e0f400:6000> [L0 DMU dnode] fletcher4 uncompressed LE contiguous unique triple size=4000L/4000P birth=33766470L/33766470P fill=30 cksum=6a469e23be:31b3236cdcc97:1093f9bba0735bcd:a89e4f61b7374c7e
��00
v����oOd��TK�dnode.cdnode_clear_rangeds=mos obj=mdn blkid=0 nblks=1 txg=33766470
i����oOh��TK��dbuf.cdbuf_dirtyds=mos obj=mdn lvl=1 blkid=0 size=4000
i����oOk��TK��dbuf.cdbuf_dirtyds=mos obj=mdn lvl=2 blkid=0 size=4000
g����oOr��TK��dbuf.cdbuf_dirtyds=mos obj=21 lvl=0 blkid=-1 size=40
�����oO�TK��space_map.cspace_map_syncobject 1071, txg 33766470, pass 6, A, count 3, space 12000
l����oO���TK��dbuf.cdbuf_dirtyds=mos obj=1071 lvl=0 blkid=164 size=1000
y����oO���TK�dnode.cdnode_clear_rangeds=mos obj=1071 blkid=164 nblks=1 txg=33766470
j����oO���TK��dbuf.cdbuf_dirtyds=mos obj=1071 lvl=1 blkid=1 size=4000
d����oO���TK��dnode.cdnode_setdirtyds=mos obj=1071 txg=33766470
j����oO���TK��dbuf.cdbuf_dirtyds=mos obj=mdn lvl=0 blkid=33 size=4000
w����oO���TK�dnode.cdnode_clear_rangeds=mos obj=mdn blkid=33 nblks=1 txg=33766470
i����oO���TK��dbuf.cdbuf_dirtyds=mos obj=1071 lvl=0 blkid=-1 size=40
�����oO���TK��space_map.cspace_map_syncobject 1156, txg 33766470, pass 6, A, count 1, space 12000
k����oO���TK��dbuf.cdbuf_dirtyds=mos obj=1156 lvl=0 blkid=78 size=1000
x����oO���TK�dnode.cdnode_clear_rangeds=mos obj=1156 blkid=78 nblks=1 txg=33766470
j����oO���TK��dbuf.cdbuf_dirtyds=mos obj=1156 lvl=1 blkid=0 size=4000
d����oO���TK��dnode.cdnode_setdirtyds=mos obj=1156 txg=33766470
j����oO���TK��dbuf.cdbuf_dirtyds=mos obj=mdn lvl=0 blkid=36 size=4000
w����oO���TK�dnode.cdnode_clear_rangeds=mos obj=mdn blkid=36 nblks=1 txg=33766470
i����oO���TK��dbuf.cdbuf_dirtyds=mos obj=1156 lvl=0 blkid=-1 size=40
�����oO��TK��space_map.cspace_map_syncobject 1185, txg 33766470, pass 6, A, count 1, space 12000
l����oO���TK��dbuf.cdbuf_dirtyds=mos obj=1185 lvl=0 blkid=238 size=1000
y����oO ��TK�dnode.cdnode_clear_rangeds=mos obj=1185 blkid=238 nblks=1 txg=33766470
j����oO%��TK��dbuf.cdbuf_dirtyds=mos obj=1185 lvl=1 blkid=1 size=4000
d����oO(��TK��dnode.cdnode_setdirtyds=mos obj=1185 txg=33766470
j����oO*��TK��dbuf.cdbuf_dirtyds=mos obj=mdn lvl=0 blkid=37 size=4000
w����oO,��TK�dnode.cdnode_clear_rangeds=mos obj=mdn blkid=37 nblks=1 txg=33766470
i����oO8��TK��dbuf.cdbuf_dirtyds=mos obj=1185 lvl=0 blkid=-1 size=40
g����oOO��TK��dbuf.cdbuf_dirtyds=mos obj=2 lvl=0 blkid=-1 size=140
a����oOR��TK��dnode.cdnode_setdirtyds=mos obj=2 txg=33766470
g����oOU��TKV�dsl_dir.cdsl_dir_syncdd=moxo txg=33766470 towrite=0K
g����oOY��TK��dbuf.cdbuf_dirtyds=mos obj=5 lvl=0 blkid=-1 size=140
a����oO[��TK��dnode.cdnode_setdirtyds=mos obj=5 txg=33766470
l����oO]��TKV�dsl_dir.cdsl_dir_syncdd=moxo/$MOS txg=33766470 towrite=0K
a����oO`��TKM�dmu_objset.cdmu_objset_syncds=mos txg=33766470
������oOm��TK�  dbuf.cdbuf_sync_indirectds=mos obj=mdn lvl=2 blkid=0 blkptr=ffffc900023bc440 DVA[0]=<0:4612fcae600:6000> DVA[1]=<0:250828f2400:6000> DVA[2]=<0:4084f2f400:6000> [L2 DMU dnode] fletcher4 uncompressed LE contiguous unique triple size=4000L/4000P birth=33766470L/33766470P fill=88288 cksum=e852be7b7f:aaa4d497b5f4d:413ec54535268717:d347e29c043de863
������oOz��TK�  dbuf.cdbuf_sync_indirectds=mos obj=mdn lvl=1 blkid=0 blkptr=ffffc90004917000 DVA[0]=<0:4612fca8600:6000> DVA[1]=<0:250828ec400:6000> DVA[2]=<0:4084e94c00:6000> [L1 DMU dnode] fletcher4 uncompressed LE contiguous unique triple size=4000L/4000P birth=33766470L/33766470P fill=3545 cksum=18b65502a52:c8ee4fb6eeca2:43cf1bd6615a0ceb:aeb6bfde21f16d50
������oO���TKM    dbuf.cdbuf_sync_leafds=mos obj=mdn lvl=0 blkid=0 blkptr=ffffc90004912000 DVA[0]=<0:4612fca2600:6000> DVA[1]=<0:250828e6400:6000> DVA[2]=<0:4084e0f400:6000> [L0 DMU dnode] fletcher4 uncompressed LE contiguous unique triple size=4000L/4000P birth=33766470L/33766470P fill=30 cksum=6a59e78154:31b9c981daf85:10952328690e97d8:aadb7d68d4d893ca
������oO���TKM    dbuf.cdbuf_sync_leafds=mos obj=mdn lvl=0 blkid=33 blkptr=ffffc90004913080 DVA[0]=<0:4612fc90600:6000> DVA[1]=<0:250828d4400:6000> DVA[2]=<0:4084def600:6000> [L0 DMU dnode] fletcher4 uncompressed LE contiguous unique triple size=4000L/4000P birth=33766470L/33766470P fill=32 cksum=28a448c544:15d154e9ff92e:619be93bad722ca:de446d95d4c0d41b
������oO��TKM   dbuf.cdbuf_sync_leafds=mos obj=mdn lvl=0 blkid=36 blkptr=ffffc90004913200 DVA[0]=<0:4612fc96600:6000> DVA[1]=<0:250828da400:6000> DVA[2]=<0:4084df5600:6000> [L0 DMU dnode] fletcher4 uncompressed LE contiguous unique triple size=4000L/4000P birth=33766470L/33766470P fill=32 cksum=15d1149ce5:6d3d4ec008a8:20de17d00087eb4:b724706b0deebecc
������oO��TKM   dbuf.cdbuf_sync_leafds=mos obj=mdn lvl=0 blkid=37 blkptr=ffffc90004913280 DVA[0]=<0:4612fc9c600:6000> DVA[1]=<0:250828e0400:6000> DVA[2]=<0:4084e04c00:6000> [L0 DMU dnode] fletcher4 uncompressed LE contiguous unique triple size=4000L/4000P birth=33766470L/33766470P fill=31 cksum=178414cdf4:afc5bcedc821:38442cf87a9c7ab:8775e903e8100bdf
}�����oO��TK� dbuf.cdbuf_sync_indirectds=mos obj=21 lvl=2 blkid=0 blkptr=ffffc9000490fa40 DVA[0]=<0:4612fcc0600:6000> DVA[1]=<0:25082904400:6000> DVA[2]=<0:4084feb800:6000> [L2 bpobj] fletcher4 uncompressed LE contiguous unique triple size=4000L/4000P birth=33766470L/33766470P fill=1 cksum=3d071f16b:3cac8b158c74:1e2b2da5ba750ce:bfb5e98ff59834
������oO
��TK�   dbuf.cdbuf_sync_indirectds=mos obj=21 lvl=1 blkid=0 blkptr=ffffc9000b5f0000 DVA[0]=<0:4612fcba600:6000> DVA[1]=<0:250828fe400:6000> DVA[2]=<0:4084fe1000:6000> [L1 bpobj] fletcher4 uncompressed LE contiguous unique triple size=4000L/4000P birth=33766470L/33766470P fill=1 cksum=34135ccf3:33cc36ec5b12:19c45f5deae659f:8c267107ef9b8834
{�����oO���TKM    dbuf.cdbuf_sync_leafds=mos obj=21 lvl=0 blkid=0 blkptr=ffffc9000b5eb000 DVA[0]=<0:4612fcb4600:6000> DVA[1]=<0:250828f8400:6000> DVA[2]=<0:4084fc4e00:6000> [L0 bpobj] fletcher4 uncompressed LE contiguous unique triple size=4000L/4000P birth=33766470L/33766470P fill=1 cksum=dc2059eb6:d0700ebdddb6:62d1d57e29982a7:46a229d745c5c6ae
�����oO/��TKM   dbuf.cdbuf_sync_leafds=mos obj=21 lvl=0 blkid=-1 blkptr=          (null) <NULL>
������oO:��TK�  dbuf.cdbuf_sync_indirectds=mos obj=1071 lvl=1 blkid=1 blkptr=ffffc900047ddec0 DVA[0]=<0:4612fc7e600:6000> DVA[1]=<0:250828c2400:6000> DVA[2]=<0:4084dd5800:6000> [L1 SPA space map] fletcher4 uncompressed LE contiguous unique triple size=4000L/4000P birth=33766470L/33766470P fill=37 cksum=83789f9ea9:70a5e65005827:30bb24c04f2b367e:fe53a527f8d5a1be
������oOE��TKM  dbuf.cdbuf_sync_leafds=mos obj=1071 lvl=0 blkid=164 blkptr=ffffc9000c2ca200 DVA[0]=<0:46155329800:1800> DVA[1]=<0:250853f4a00:1800> DVA[2]=<0:402b177200:1800> [L0 SPA space map] fletcher4 uncompressed LE contiguous unique triple siobj=15690 lvl=0 blkid=55 size=20000
�����oO���I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=55 nblks=1 txg=33766471
�����oO��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=56 db=ffff88005f7f5850
�����oO?�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=56 db=ffff88005f7f5850
�����oO[�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=56 db=ffff88005f7f5850
�����oOu�I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=56 size=20000
�����oO{�I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=56 nblks=1 txg=33766471
�����oOs�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=57 db=ffff8801053a9850
�����oO��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=57 db=ffff8801053a9850
�����oO��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=57 db=ffff8801053a9850
�����oOחI}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=57 size=20000
�����oOݗI}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=57 nblks=1 txg=33766471
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=58 db=ffff880083e7c3b0
�����oO
 �I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=58 db=ffff880083e7c3b0
�����oO% �I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=58 db=ffff880083e7c3b0
�����oO? �I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=58 size=20000
�����oOF �I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=58 nblks=1 txg=33766471
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=59 db=ffff88000ba71170
�����oOɝ�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=59 db=ffff88000ba71170
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=59 db=ffff88000ba71170
�����o��I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=59 size=20000
�����oO��I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=59 nblks=1 txg=33766471
�����oOI}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=60 db=ffff880104a05170
�����oO��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=60 db=ffff880104a05170
�����oO��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=60 db=ffff880104a05170
�����oO��I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=60 size=20000
�����oO��I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=60 nblks=1 txg=33766471
�����oO7�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=61 db=ffff880066e0f698
�����oOe�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=61 db=ffff880066e0f698
�����oO��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=61 db=ffff880066e0f698
�����oO��I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=61 size=20000
�����oO��I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=61 nblks=1 txg=33766471
�����oOD#I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=110 db=ffff8801028be568
�����oOs#I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=110 db=ffff8801028be568
�����oOI}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=110 db=ffff8801028be568
�����oO�#I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=110 size=20000
�����oO�#I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=110 nblks=1 txg=33766471
�����oO��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=111 db=ffff88008c478e00
�����oO��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=111 db=ffff88008c478e00
�����oOעI}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=111 db=ffff88008c478e00
�����oO��I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=111 size=20000
�����oO��I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=111 nblks=1 txg=33766471
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=112 db=ffff88000b879170
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=112 db=ffff88000b879170
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=112 db=ffff88000b879170
�����oO� �I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=112 size=20000
�����oO� �I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=112 nblks=1 txg=33766471
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=113 db=ffff88007798e720
�����oO%��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=113 db=ffff88007798e720
�����oO?��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=113 db=ffff88007798e720
�����oOZ��I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=113 size=20000
�����oO`��I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=113 nblks=1 txg=33766471
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=114 db=ffff8801047234e0
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=114 db=ffff8801047234e0
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=114 db=ffff8801047234e0
�����oO���I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=114 size=20000
�����oO���I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=114 nblks=1 txg=33766471
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=115 db=ffff880084ddfbc0
�����oO̒�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=115 db=ffff880084ddfbc0
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=115 db=ffff880084ddfze=1000L/1000P birth=33766470L/33766470P fill=1 cksum=117f43054c1:225981e4e4aaa:2cc8460722f8088:c823e2bc38e76580
�����oOW��TKM   dbuf.cdbuf_sync_leafds=mos obj=1071 lvl=0 blkid=-1 blkptr=          (null) <NULL>
����oOa��TK�  dbuf.cdbuf_sync_indirectds=mos obj=1156 lvl=1 blkid=0 blkptr=ffffc900047b9840 DVA[0]=<0:4612fc84600:6000> DVA[1]=<0:250828c8400:6000> DVA[2]=<0:4084ddb800:6000> [L1 SPA space map] fletcher4 uncompressed LE contiguous unique triple size=4000L/4000P birth=33766470L/33766470P fill=79 cksum=11fd117d5bc:c4defcd83a909:47db03bb173ce0cf:5c42c7e3ac6b1f84
������oOn��TKM  dbuf.cdbuf_sync_leafds=mos obj=1156 lvl=0 blkid=78 blkptr=ffffc900024c6700 DVA[0]=<0:4615532b000:1800> DVA[1]=<0:250853f6200:1800> DVA[2]=<0:402b178a00:1800> [L0 SPA space map] fletcher4 uncompressed LE contiguous unique triple size=1000L/1000P birth=33766470L/33766470P fill=1 cksum=537735236c:1069371f2f920:1a801370b7cce00:d3b74b75b0b9e243
�����oOt��TKM   dbuf.cdbuf_sync_leafds=mos obj=1156 lvl=0 blkid=-1 blkptr=          (null) <NULL>
����oO}��TK�  dbuf.cdbuf_sync_indirectds=mos obj=1185 lvl=1 blkid=1 blkptr=ffffc900047e12c0 DVA[0]=<0:4612fc8a600:6000> DVA[1]=<0:250828ce400:6000> DVA[2]=<0:4084de6000:6000> [L1 SPA space map] fletcher4 uncompressed LE contiguous unique triple size=4000L/4000P birth=33766470L/33766470P fill=111 cksum=19e217c15d4:ecac1a072ef10:505d839308f201f5:1f045b51b80449c
������oO���TKM    dbuf.cdbuf_sync_leafds=mos obj=1185 lvl=0 blkid=238 blkptr=ffffc90006cfd700 DVA[0]=<0:4615532c800:1800> DVA[1]=<0:250853f7a00:1800> DVA[2]=<0:402b17a200:1800> [L0 SPA space map] fletcher4 uncompressed LE contiguous unique triple size=1000L/1000P birth=33766470L/33766470P fill=1 cksum=4a8d7a8e07:1066606ab5982:1d16ff713add600:2aa23e8abc655fa2
�����oO�TKM dbuf.cdbuf_sync_leafds=mos obj=1185 lvl=0 blkid=-1 blkptr=          (null) <NULL>
�����oO���TKM dbuf.cdbuf_sync_leafds=mos obj=2 lvl=0 blkid=-1 blkptr=          (null) <NULL>
�����oO���TKM dbuf.cdbuf_sync_leafds=mos obj=5 lvl=0 blkid=-1 blkptr=          (null) <NULL>
�����oO����K��dnode.cdnode_diduse_spaceds=mos obj=21 dn=ffff88008040d8b8 dnp=ffffc9000490fa00 used=147312 delta=0
�����oO\���K��dnode.cdnode_diduse_spaceds=mos obj=1071 dn=ffff880080c2b378 dnp=ffffc900047dde00 used=2053161 delta=0
�����oO����K��dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff8800808ec618 dnp=ffffc900047b9800 used=1015839 delta=0
�����oO����K��dnode.cdnode_diduse_spaceds=mos obj=1156 dn=ffff8800808ec618 dnp=ffffc900047b9800 used=1015839 delta=0
�����oOZ���K��dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff88008040f000 dnp=ffffc900023bc400 used=34283799 delta=0
�����oO����K��dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff88008040f000 dnp=ffffc900023bc400 used=34283799 delta=0
�����oO^���K��dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff88008040f000 dnp=ffffc900023bc400 used=34283799 delta=0
�����oO����K��dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff88008040f000 dnp=ffffc900023bc400 used=34283799 delta=0
�����oO����K��dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff88008040f000 dnp=ffffc900023bc400 used=34283799 delta=0
a�����oO�P�TK��dsl_pool.cdsl_pool_syncmeta objset rootbp is  DVA[0]=<0:4615532e000:c00> DVA[1]=<0:250853f9200:c00> DVA[2]=<0:4041a66600:c00> [L0 DMU objset] fletcher4 uncompressed LE contiguous unique triple size=800L/800P birth=33766470L/33766470P fill=88288 cksum=39c2f3c5b:6af1e5ca9af:633f75b017e25:3d8e03c589da2a6
�����oO�Y�TK��txg.ctxg_sync_threadwaiting; tx_synced=33766470 waiting=33766261 dp=ffff8800cefcd000
�����oO`I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=35 db=ffff88008d786fb8
�����oI}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=35 db=ffff88008d786fb8
�����oO�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=35 db=ffff88008d786fb8
�����oO�I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=35 size=20000
�����oO�I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=35 nblks=1 txg=33766471
�����oO��   I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=36 db=ffff88008d786c48
�����oO�� I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=36 db=ffff88008d786c48
�����oO9� I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=36 db=ffff88008d786c48
�����oOS� I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=36 size=20000
�����oOZ� I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=36 nblks=1 txg=33766471
�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=52 db=ffff88008d7868d8
�����oO��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=52 db=ffff88008d7868d8
�����oO-�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=52 db=ffff88008d7868d8
�����oOH�I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=52 size=20000
�����oOP�I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=52 nblks=1 txg=33766471
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=53 db=ffff88008d786568
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=53 db=ffff88008d786568
�����oO��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=53 db=ffff88008d786568
�����oO���I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=53 size=20000
�����oO!��I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=53 nblks=1 txg=33766471
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=54 db=ffff88008d783bc0
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=54 db=ffff88008d783bc0
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=54 db=ffff88008d783bc0
�����oO���I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=54 size=20000
�����oO���I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=54 nblks=1 txg=33766471
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=55 db=ffff88010595c720
�����oOӗ�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=55 db=ffff88010595c720
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=55 db=ffff88010595c720
�����oO
��I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var ����oOHI}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=127 db=ffff8801048e6a90
�����oObI}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=127 size=20000
�����oOiI}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=127 nblks=1 txg=33766471
�����oO�T I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=129 db=ffff880100985bc0
�����oO�T I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=129 db=ffff880100985bc0
�����oO�U   I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=129 db=ffff880100985bc0
�����oO4U   I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=129 size=20000
�����oO;U   I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=129 nblks=1 txg=33766471
root@xubuntu:/tmp# \62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;c62;9;bc0
�����oO���I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=115 size=20000
�����o��I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=115 nblks=1 txg=33766471
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=116 db=ffff88000d484568
�����oO4��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=116 db=ffff88000d484568
�����oOP��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=116 db=ffff88000d484568
�����oOk��I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=116 size=20000
�����oOq��I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=116 nblks=1 txg=33766471
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=117 db=ffff8801029e5850
�����oOI��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=117 db=ffff8801029e5850
�����oOd��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=117 db=ffff8801029e5850
�����oO~��I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=117 size=20000
�����oO���I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=117 nblks=1 txg=33766471
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=118 db=ffff8801047241f8
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=118 db=ffff8801047241f8
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=118 db=ffff8801047241f8
�����oO���I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=118 size=20000
�����oO��I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=118 nblks=1 txg=33766471
�����oO�v�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=119 db=ffff88000e9cfa08
�����oO�v�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=119 db=ffff88000e9cfa08
�����oO�v�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=119 db=ffff88000e9cfa08
�����oO�v�I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=119 size=20000
�����oO�v�I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=119 nblks=1 txg=33766471
�����oO���I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=120 db=ffff880015fd83b0
�����oO@��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=120 db=ffff880015fd83b0
�����oO]��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=120 db=ffff880015fd83b0
�����oOw��I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=120 size=20000
�����oO|��I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=120 nblks=1 txg=33766471
�����oO�lI}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=121 db=ffff880108ee8c48
�����oO�lI}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=121 db=ffff880108ee8c48
�����oOmI}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=121 db=ffff880108ee8c48
�����oO"mI}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=121 size=20000
�����oO)mI}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=121 nblks=1 txg=33766471
�����oO��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=122 db=ffff880104713a08
�����oO)�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=122 db=ffff880104713a08
�����oOD�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=122 db=ffff880104713a08
�����oO^�I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=122 size=20000
�����oOc�I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=122 nblks=1 txg=33766471
�����oO{^�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=123 db=ffff880066e11d78
�����oO�^�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=123 db=ffff880066e11d78
�����oO�^�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=123 db=ffff880066e11d78
�����oO�^�I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=123 size=20000
�����oO�^�I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=123 nblks=1 txg=33766471
�����oO3��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=124 db=ffff88000d7b01f8
�����oO_��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=124 db=ffff88000d7b01f8
�����oOz��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=124 db=ffff88000d7b01f8
�����oO���I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=124 size=20000
�����oO���I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=124 nblks=1 txg=33766471
�����oO7NI}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=125 db=ffff8801044eaa90
�����oOdNI}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=125 db=ffff8801044eaa90
�����oO�NI}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=125 db=ffff8801044eaa90
�����oO�NI}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=125 size=20000
�����oO�NI}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=125 nblks=1 txg=33766471
�����oO��I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=126 db=ffff8801059303b0
�����oO"�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=126 db=ffff8801059303b0
�����oO=�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=126 db=ffff8801059303b0
�����oOX�I}��dbuf.cdbuf_dirtyds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=126 size=20000
�����oO^�I}�dnode.cdnode_clear_rangeds=moxo/ROOT/ubuntu-4/var obj=15690 blkid=126 nblks=1 txg=33766471
�����oO�I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=127 db=ffff8801048e6a90
�����oO,I}��dbuf.cdbuf_createds=moxo/ROOT/ubuntu-4/var obj=15690 lvl=0 blkid=127 db=ffff8801048e6a90

@behlendorf
Copy link
Contributor Author

Thanks for following up on this, but the more that I look at it the more it seems unrelated to the VM change above. Probably just bad timing and we're now seeing some previous damage to the pool.

The first set of assertions indicate some damage to the zil log which was written out. Unfortunately, the assertions don't provide enough data to see exactly what's wrong. Changing the to ASSERTs to the ASSERT3x variants would be helpful to see exactly what condition is failing but I'd also probably need a hex dump of those blocks to see exactly whats wrong.
My guess would be it was caused by 2c6d0b1 which is the only regression I'm aware of which slipped in. Plus the first reports of this type of error (from a few people) started appears slightly after that change was merge, and it would have been capable of causing this sort of damage.

The second assertion after you disabled zil replay is a little more troubling, although it might be related. That's going to take some digging as well. I think we should probably move both of these issues to new bugs so as not to cloud any issues with this VM patch.

The spl utility (which doesn't have man page, I know) is used to decode these log files. The first argument is the binary log, the second the output file name.

spl /tmp/spl-log.1332715670.7780 /tmp/spl-log.1332715670.7780.txt

Under Solaris the ARC was designed to stay one step ahead of the
VM subsystem.  It would attempt to recognize low memory situtions
before they occured and evict data from the cache.  It would also
make assessments about if there was enough free memory to perform
a specific operation.

This was all possible because Solaris exposes a fairly decent
view of the memory state of the system to other kernel threads.
Linux on the other hand does not make this information easily
available.  To avoid extensive modifications to the ARC the SPL
attempts to provide these same interfaces.  While this works it
is not ideal and problems can arise when the ARC and Linux have
different ideas about when your out of memory.  This has manifested
itself in the past as a spinning arc_reclaim_thread.

This patch abandons the emulated Solaris interfaces in favor of
the prefered Linux interface.  That means moving the bulk of the
memory reclaim logic out of the arc_reclaim_thread and in to the
evict driven shrinker callback.  The Linux VM will call this
function when it needs memory.  The ARC is then responsible for
attempting to free the requested amount of memory if possible.

Several interfaces have been modified to accomidate this approach,
however the basic user space implementation remains the same.
The following changes almost exclusively just apply to the kernel
implementation.

* Removed the hdr_recl() reclaim callback which is redundant
  with the broader arc_shrinker_func().

* Reduced arc_grow_retry to 5 seconds from 60.  This is now used
  internally in the ARC with arc_no_grow to indicate that direct
  reclaim was recently performed.  This typically indicates a
  rapid change in memory demands which the kswapd threads were
  unable to keep ahead of.  As long as direct reclaim is happening
  once every 5 seconds arc growth will be paused to avoid further
  contributing to the existing memory pressure.  The more common
  indirect reclaim paths will not set arc_no_grow.

* arc_shrink() has been extended to take the number of bytes by
  which arc_c should be reduced.  This allows for a more granual
  reduction of the arc target.  Since the kernel provides a
  reclaim value to the arc_shrinker_func() this value is used
  instead of 1<<arc_shrink_shift.

* arc_reclaim_needed() has been removed.  It was used to determine
  if the system was under memory pressure and relied extensively
  on Solaris specific VM interfaces.  In most case the new code
  just checks arc_no_grow which indicates that within the last
  arc_grow_retry seconds direct memory reclaim occurred.

* arc_memory_throttle() has been updated to always include the
  amount of evictable memory (arc and page cache) in its free
  space calculations.  This space is largely available in most
  call paths due to direct memory reclaim.

* The Solaris pageout code was also removed to avoid confusion.
  It has always been disabled due to proc_pageout being defined
  as NULL in the Linux port.

Signed-off-by: Prakash Surya <surya1@llnl.gov>
Signed-off-by: Brian Behlendorf <behlendorf1@llnl.gov>
@pyavdr
Copy link
Contributor

pyavdr commented Apr 2, 2012

Hi Brian,

i really like this ARC patch. Usage of memory is now smooth and no more erratic then before. I run it for some days on Suse 12.1 kernel 3.1.9 without any problems. It also improves zvol performance by magnitudes.

Thanks!

@ryao
Copy link
Contributor

ryao commented Apr 3, 2012

Brian, I decided to try your patch on my server. The following happened:

[ 7109.054462] [] ? nf_hook_slow+0x6f/0x150
[ 7109.054464] [] ? inet_del_protocol+0x30/0x30
[ 7109.054466] [] ? ip_local_deliver_finish+0xd4/0x290
[ 7109.054468] [] ? __netif_receive_skb+0x162/0x490
[ 7109.054470] [] ? netif_receive_skb+0x2a/0x90
[ 7109.054476] [] ? br_nf_pre_routing_finish+0x18b/0x320 [bridge]
[ 7109.054479] [] ? br_nf_pre_routing+0x406/0x6f0 [bridge]
[ 7109.054481] [] ? __wake_up_common+0x50/0x80
[ 7109.054483] [] ? nf_iterate+0x75/0xa0
[ 7109.054485] [] ? br_handle_local_finish+0x40/0x40 [bridge]
[ 7109.054487] [] ? nf_hook_slow+0x6f/0x150
[ 7109.054489] [] ? br_handle_local_finish+0x40/0x40 [bridge]
[ 7109.054492] [] ? br_handle_frame+0x1c0/0x260 [bridge]
[ 7109.054495] [] ? br_handle_frame_finish+0x2d0/0x2d0 [bridge]
[ 7109.054496] [] ? __netif_receive_skb+0x114/0x490
[ 7109.054498] [] ? netif_receive_skb+0x2a/0x90
[ 7109.054500] [] ? napi_complete+0x32/0x60
[ 7109.054506] [] ? e1000_clean+0xd0/0x2a0 [e1000e]
[ 7109.054509] [] ? e1000_clean_tx_irq+0x158/0x310 [e1000e]
[ 7109.054510] [] ? net_rx_action+0x79/0x110
[ 7109.054512] [] ? __do_softirq+0x90/0x110
[ 7109.054515] [] ? call_softirq+0x1c/0x30
[ 7109.054517] [] ? do_softirq+0x4d/0x80
[ 7109.054518] [] ? irq_exit+0x86/0xa0
[ 7109.054520] [] ? do_IRQ+0x5c/0xd0
[ 7109.054522] [] ? common_interrupt+0x6b/0x6b
[ 7109.054523] [] ? spl_kmem_cache_create+0xde9/0x1040 [spl]
[ 7109.054531] [] ? spl_kmem_cache_reap_now+0x76/0x1d0 [spl]
[ 7109.054534] [] ? spl_kmem_cache_reap_now+0x17b/0x1d0 [spl]
[ 7109.054536] [] ? shrink_slab+0x134/0x1e0
[ 7109.054538] [] ? balance_pgdat+0x55c/0x700
[ 7109.054540] [] ? kswapd+0x186/0x2d0
[ 7109.054542] [] ? wake_up_bit+0x40/0x40
[ 7109.054543] [] ? balance_pgdat+0x700/0x700
[ 7109.054545] [] ? balance_pgdat+0x700/0x700
[ 7109.054546] [] ? kthread+0x9e/0xb0
[ 7109.054548] [] ? kernel_thread_helper+0x4/0x10
[ 7109.054550] [] ? flush_kthread_worker+0xc0/0xc0
[ 7109.054551] [] ? gs_change+0xb/0xb
[ 7109.054552] Mem-Info:
[ 7109.054553] DMA per-cpu:
[ 7109.054554] CPU 0: hi: 0, btch: 1 usd: 0
[ 7109.054556] CPU 1: hi: 0, btch: 1 usd: 0
[ 7109.054557] CPU 2: hi: 0, btch: 1 usd: 0
[ 7109.054558] CPU 3: hi: 0, btch: 1 usd: 0
[ 7109.054559] CPU 4: hi: 0, btch: 1 usd: 0
[ 7109.054560] CPU 5: hi: 0, btch: 1 usd: 0
[ 7109.054561] DMA32 per-cpu:
[ 7109.054562] CPU 0: hi: 186, btch: 31 usd: 4
[ 7109.054563] CPU 1: hi: 186, btch: 31 usd: 6
[ 7109.054564] CPU 2: hi: 186, btch: 31 usd: 19
[ 7109.054565] CPU 3: hi: 186, btch: 31 usd: 4
[ 7109.054566] CPU 4: hi: 186, btch: 31 usd: 9
[ 7109.054567] CPU 5: hi: 186, btch: 31 usd: 24
[ 7109.054568] Normal per-cpu:
[ 7109.054569] CPU 0: hi: 186, btch: 31 usd: 1
[ 7109.054570] CPU 1: hi: 186, btch: 31 usd: 0
[ 7109.054571] CPU 2: hi: 186, btch: 31 usd: 0
[ 7109.054572] CPU 3: hi: 186, btch: 31 usd: 17
[ 7109.054573] CPU 4: hi: 186, btch: 31 usd: 0
[ 7109.054574] CPU 5: hi: 186, btch: 31 usd: 32
[ 7109.054576] active_anon:879584 inactive_anon:44 isolated_anon:0
[ 7109.054577] active_file:2513 inactive_file:6126 isolated_file:0
[ 7109.054578] unevictable:542 dirty:0 writeback:0 unstable:0
[ 7109.054578] free:7092 slab_reclaimable:6082 slab_unreclaimable:71239
[ 7109.054579] mapped:2088 shmem:72 pagetables:2469 bounce:0
[ 7109.054582] DMA free:15896kB min:64kB low:80kB high:96kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15640kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
[ 7109.054585] lowmem_reserve[]: 0 3118 15214 15214
[ 7109.054589] DMA32 free:12376kB min:13836kB low:17292kB high:20752kB active_anon:135404kB inactive_anon:0kB active_file:0kB inactive_file:2544kB unevictable:4kB isolated(anon):0kB isolated(file):0kB present:3193664kB mlocked:4kB dirty:0kB writeback:0kB mapped:4kB shmem:0kB slab_reclaimable:6688kB slab_unreclaimable:79268kB kernel_stack:8kB pagetables:116kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:1 all_unreclaimable? no
[ 7109.054592] lowmem_reserve[]: 0 0 12096 12096
[ 7109.054596] Normal free:96kB min:53676kB low:67092kB high:80512kB active_anon:3382932kB inactive_anon:176kB active_file:10052kB inactive_file:21960kB unevictable:2164kB isolated(anon):0kB isolated(file):0kB present:12386304kB mlocked:2164kB dirty:0kB writeback:0kB mapped:8348kB shmem:288kB slab_reclaimable:17640kB slab_unreclaimable:205688kB kernel_stack:2416kB pagetables:9760kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:11 all_unreclaimable? no
[ 7109.054599] lowmem_reserve[]: 0 0 0 0
[ 7109.054601] DMA: 0_4kB 1_8kB 1_16kB 0_32kB 2_64kB 1_128kB 1_256kB 0_512kB 1_1024kB 1_2048kB 3_4096kB = 15896kB
[ 7109.054605] DMA32: 137_4kB 68_8kB 27_16kB 26_32kB 15_64kB 6_128kB 9_256kB 1_512kB 0_1024kB 0_2048kB 1_4096kB = 10996kB
[ 7109.054609] Normal: 0_4kB 0_8kB 0_16kB 0_32kB 0_64kB 0_128kB 0_256kB 0_512kB 0_1024kB 0_2048kB 0_4096kB = 0kB
[ 7109.054613] 9164 total pagecache pages
[ 7109.054614] 0 pages in swap cache
[ 7109.054615] Swap cache stats: add 0, delete 0, find 0/0
[ 7109.054616] Free swap = 0kB
[ 7109.054616] Total swap = 0kB
[ 7109.062628] 3964912 pages RAM
[ 7109.062628] 102944 pages reserved
[ 7109.062628] 16092 pages shared
[ 7109.062628] 3452027 pages non-shared
[ 7109.062628] SLUB: Unable to allocate memory on node -1 (gfp=0x20)
[ 7109.062628] cache: kmalloc-256, object size: 256, buffer size: 256, default order: 0, min order: 0
[ 7109.062628] node 0: slabs: 1411, objs: 22576, free: 32
[ 7109.111719] kswapd0: page allocation failure: order:0, mode:0x20
[ 7109.111726] Pid: 405, comm: kswapd0 Tainted: P O 3.3.0 #3
[ 7109.111732] Call Trace:
[ 7109.111736] [] ? warn_alloc_failed+0xfc/0x150
[ 7109.111753] [] ? __netif_receive_skb+0x162/0x490
[ 7109.111762] [] ? __alloc_pages_nodemask+0x5c5/0x860
[ 7109.111771] [] ? get_partial_node.clone.48+0x137/0x1b0
[ 7109.111779] [] ? __alloc_skb+0x40/0x170
[ 7109.111787] [] ? new_slab+0x209/0x220
[ 7109.111794] [] ? __slab_alloc.clone.66+0x1f9/0x280
[ 7109.111806] [] ? br_handle_frame+0x1c0/0x260 [bridge]
[ 7109.111814] [] ? __alloc_skb+0x40/0x170
[ 7109.111821] [] ? kmem_cache_alloc+0xc0/0xd0
[ 7109.111829] [] ? __alloc_skb+0x40/0x170
[ 7109.111836] [] ? __netdev_alloc_skb+0x17/0x40
[ 7109.111848] [] ? e1000_alloc_rx_buffers+0x1fa/0x2e0 [e1000e]
[ 7109.111857] [] ? swiotlb_map_sg+0x10/0x10
[ 7109.111866] [] ? e1000_clean_rx_irq+0x22d/0x420 [e1000e]
[ 7109.111874] [] ? try_to_wake_up+0xd3/0x290
[ 7109.111883] [] ? e1000_clean+0xb0/0x2a0 [e1000e]
[ 7109.111890] [] ? net_rx_action+0x79/0x110
[ 7109.111898] [] ? __do_softirq+0x90/0x110
[ 7109.111906] [] ? call_softirq+0x1c/0x30
[ 7109.111914] [] ? do_softirq+0x4d/0x80
[ 7109.111921] [] ? irq_exit+0x86/0xa0
[ 7109.111928] [] ? do_IRQ+0x5c/0xd0
[ 7109.111935] [] ? common_interrupt+0x6b/0x6b
[ 7109.111941] [] ? spl_kmem_cache_create+0xde9/0x1040 [spl]
[ 7109.111959] [] ? spl_kmem_cache_reap_now+0x76/0x1d0 [spl]
[ 7109.111967] [] ? spl_kmem_cache_reap_now+0x17b/0x1d0 [spl]
[ 7109.111975] [] ? shrink_slab+0x134/0x1e0
[ 7109.111982] [] ? balance_pgdat+0x55c/0x700
[ 7109.111989] [] ? kswapd+0x186/0x2d0
[ 7109.111997] [] ? wake_up_bit+0x40/0x40
[ 7109.112000] [] ? balance_pgdat+0x700/0x700
[ 7109.112002] [] ? balance_pgdat+0x700/0x700
[ 7109.112004] [] ? kthread+0x9e/0xb0
[ 7109.112006] [] ? kernel_thread_helper+0x4/0x10
[ 7109.112007] [] ? flush_kthread_worker+0xc0/0xc0
[ 7109.112009] [] ? gs_change+0xb/0xb
[ 7109.112010] Mem-Info:
[ 7109.112011] DMA per-cpu:
[ 7109.112012] CPU 0: hi: 0, btch: 1 usd: 0
[ 7109.112014] CPU 1: hi: 0, btch: 1 usd: 0
[ 7109.112015] CPU 2: hi: 0, btch: 1 usd: 0
[ 7109.112016] CPU 3: hi: 0, btch: 1 usd: 0
[ 7109.112017] CPU 4: hi: 0, btch: 1 usd: 0
[ 7109.112018] CPU 5: hi: 0, btch: 1 usd: 0
[ 7109.112019] DMA32 per-cpu:
[ 7109.112021] CPU 0: hi: 186, btch: 31 usd: 30
[ 7109.112022] CPU 1: hi: 186, btch: 31 usd: 6
[ 7109.112026] CPU 2: hi: 186, btch: 31 usd: 18
[ 7109.112031] CPU 3: hi: 186, btch: 31 usd: 3
[ 7109.112035] CPU 4: hi: 186, btch: 31 usd: 9
[ 7109.112040] CPU 5: hi: 186, btch: 31 usd: 24
[ 7109.112044] Normal per-cpu:
[ 7109.112049] CPU 0: hi: 186, btch: 31 usd: 3
[ 7109.112053] CPU 1: hi: 186, btch: 31 usd: 1
[ 7109.112058] CPU 2: hi: 186, btch: 31 usd: 0
[ 7109.112062] CPU 3: hi: 186, btch: 31 usd: 17
[ 7109.112067] CPU 4: hi: 186, btch: 31 usd: 0
[ 7109.112071] CPU 5: hi: 186, btch: 31 usd: 32
[ 7109.112076] active_anon:879584 inactive_anon:44 isolated_anon:0
[ 7109.112078] active_file:2513 inactive_file:6126 isolated_file:0
[ 7109.112080] unevictable:542 dirty:0 writeback:0 unstable:0
[ 7109.112081] free:6006 slab_reclaimable:6082 slab_unreclaimable:71239
[ 7109.112083] mapped:2088 shmem:72 pagetables:2469 bounce:0
[ 7109.112090] DMA free:15896kB min:64kB low:80kB high:96kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15640kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
[ 7109.112100] lowmem_reserve[]: 0 3118 15214 15214
[ 7109.112119] DMA32 free:8032kB min:13836kB low:17292kB high:20752kB active_anon:135404kB inactive_anon:0kB active_file:0kB inactive_file:2544kB unevictable:4kB isolated(anon):0kB isolated(file):0kB present:3193664kB mlocked:4kB dirty:0kB writeback:0kB mapped:4kB shmem:0kB slab_reclaimable:6688kB slab_unreclaimable:79268kB kernel_stack:8kB pagetables:116kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 7109.112131] lowmem_reserve[]: 0 0 12096 12096
[ 7109.112150] Normal free:96kB min:53676kB low:67092kB high:80512kB active_anon:3382932kB inactive_anon:176kB active_file:10052kB inactive_file:21960kB unevictable:2164kB isolated(anon):0kB isolated(file):0kB present:12386304kB mlocked:2164kB dirty:0kB writeback:0kB mapped:8348kB shmem:288kB slab_reclaimable:17640kB slab_unreclaimable:205688kB kernel_stack:2416kB pagetables:9760kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:3 all_unreclaimable? no
[ 7109.112162] lowmem_reserve[]: 0 0 0 0
[ 7109.112179] DMA: 0_4kB 1_8kB 1_16kB 0_32kB 2_64kB 1_128kB 1_256kB 0_512kB 1_1024kB 1_2048kB 3_4096kB = 15896kB
[ 7109.112219] DMA32: 93_4kB 39_8kB 10_16kB 8_32kB 3_64kB 1_128kB 5_256kB 0_512kB 0_1024kB 0_2048kB 1_4096kB = 6796kB
[ 7109.112257] Normal: 0_4kB 0_8kB 0_16kB 0_32kB 0_64kB 0_128kB 0_256kB 0_512kB 0_1024kB 0_2048kB 0_4096kB = 0kB
[ 7109.112297] 9164 total pagecache pages
[ 7109.112301] 0 pages in swap cache
[ 7109.112305] Swap cache stats: add 0, delete 0, find 0/0
[ 7109.112310] Free swap = 0kB
[ 7109.112313] Total swap = 0kB
[ 7109.112616] 3964912 pages RAM
[ 7109.112616] 102944 pages reserved
[ 7109.112616] 16092 pages shared
[ 7109.112616] 3451993 pages non-shared
[ 7109.112616] SLUB: Unable to allocate memory on node -1 (gfp=0x20)
[ 7109.112616] cache: kmalloc-256, object size: 256, buffer size: 256, default order: 0, min order: 0
[ 7109.112616] node 0: slabs: 1412, objs: 22592, free: 67
[ 7109.164516] kswapd0: page allocation failure: order:0, mode:0x4020
[ 7109.164519] Pid: 405, comm: kswapd0 Tainted: P O 3.3.0 #3
[ 7109.164520] Call Trace:
[ 7109.164521] [] ? warn_alloc_failed+0xfc/0x150
[ 7109.164527] [] ? __netif_receive_skb+0x162/0x490
[ 7109.164530] [] ? __alloc_pages_nodemask+0x5c5/0x860
[ 7109.164533] [] ? __alloc_skb+0x140/0x170
[ 7109.164536] [] ? get_partial_node.clone.48+0x137/0x1b0
[ 7109.164538] [] ? __netdev_alloc_skb+0x17/0x40
[ 7109.164539] [] ? new_slab+0x209/0x220
[ 7109.164541] [] ? __slab_alloc.clone.66+0x1f9/0x280
[ 7109.164544] [] ? do_IRQ+0x5c/0xd0
[ 7109.164546] [] ? __netdev_alloc_skb+0x17/0x40
[ 7109.164548] [] ? __kmalloc_track_caller+0x175/0x190
[ 7109.164550] [] ? __alloc_skb+0x6e/0x170
[ 7109.164551] [] ? __netdev_alloc_skb+0x17/0x40
[ 7109.164559] [] ? e1000_alloc_rx_buffers+0x1fa/0x2e0 [e1000e]
[ 7109.164562] [] ? swiotlb_map_sg+0x10/0x10
[ 7109.164565] [] ? e1000_clean_rx_irq+0x28a/0x420 [e1000e]
[ 7109.164568] [] ? try_to_wake_up+0xd1/0x290
[ 7109.164571] [] ? e1000_clean+0xb0/0x2a0 [e1000e]
[ 7109.164573] [] ? net_rx_action+0x79/0x110
[ 7109.164575] [] ? __do_softirq+0x90/0x110
[ 7109.164578] [] ? call_softirq+0x1c/0x30
[ 7109.164580] [] ? do_softirq+0x4d/0x80
[ 7109.164582] [] ? irq_exit+0x86/0xa0
[ 7109.164583] [] ? do_IRQ+0x5c/0xd0
[ 7109.164585] [] ? common_interrupt+0x6b/0x6b
[ 7109.164586] [] ? spl_kmem_cache_create+0xde9/0x1040 [spl]
[ 7109.164594] [] ? spl_kmem_cache_reap_now+0x76/0x1d0 [spl]
[ 7109.164596] [] ? spl_kmem_cache_reap_now+0x17b/0x1d0 [spl]
[ 7109.164599] [] ? shrink_slab+0x134/0x1e0
[ 7109.164602] [] ? balance_pgdat+0x55c/0x700
[ 7109.164604] [] ? kswapd+0x186/0x2d0
[ 7109.164606] [] ? wake_up_bit+0x40/0x40
[ 7109.164608] [] ? balance_pgdat+0x700/0x700
[ 7109.164609] [] ? balance_pgdat+0x700/0x700
[ 7109.164611] [] ? kthread+0x9e/0xb0
[ 7109.164613] [] ? kernel_thread_helper+0x4/0x10
[ 7109.164615] [] ? flush_kthread_worker+0xc0/0xc0
[ 7109.164617] [] ? gs_change+0xb/0xb
[ 7109.164618] Mem-Info:
[ 7109.164618] DMA per-cpu:
[ 7109.164620] CPU 0: hi: 0, btch: 1 usd: 0
[ 7109.164621] CPU 1: hi: 0, btch: 1 usd: 0
[ 7109.164622] CPU 2: hi: 0, btch: 1 usd: 0
[ 7109.164623] CPU 3: hi: 0, btch: 1 usd: 0
[ 7109.164624] CPU 4: hi: 0, btch: 1 usd: 0
[ 7109.164625] CPU 5: hi: 0, btch: 1 usd: 0
[ 7109.164626] DMA32 per-cpu:
[ 7109.164628] CPU 0: hi: 186, btch: 31 usd: 30
[ 7109.164629] CPU 1: hi: 186, btch: 31 usd: 9
[ 7109.164630] CPU 2: hi: 186, btch: 31 usd: 18
[ 7109.164631] CPU 3: hi: 186, btch: 31 usd: 3
[ 7109.164632] CPU 4: hi: 186, btch: 31 usd: 9
[ 7109.164633] CPU 5: hi: 186, btch: 31 usd: 24
[ 7109.164634] Normal per-cpu:
[ 7109.164635] CPU 0: hi: 186, btch: 31 usd: 3
[ 7109.164636] CPU 1: hi: 186, btch: 31 usd: 35
[ 7109.164638] CPU 2: hi: 186, btch: 31 usd: 0
[ 7109.164639] CPU 3: hi: 186, btch: 31 usd: 17
[ 7109.164640] CPU 4: hi: 186, btch: 31 usd: 0
[ 7109.164641] CPU 5: hi: 186, btch: 31 usd: 32
[ 7109.164644] active_anon:879584 inactive_anon:44 isolated_anon:0
[ 7109.164644] active_file:2513 inactive_file:6126 isolated_file:0
[ 7109.164645] unevictable:542 dirty:0 writeback:0 unstable:0
[ 7109.164646] free:6006 slab_reclaimable:6082 slab_unreclaimable:71239
[ 7109.164646] mapped:2088 shmem:72 pagetables:2469 bounce:0
[ 7109.164650] DMA free:15896kB min:64kB low:80kB high:96kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15640kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
[ 7109.164653] lowmem_reserve[]: 0 3118 15214 15214
[ 7109.164657] DMA32 free:8032kB min:13836kB low:17292kB high:20752kB active_anon:135404kB inactive_anon:0kB active_file:0kB inactive_file:2544kB unevictable:4kB isolated(anon):0kB isolated(file):0kB present:3193664kB mlocked:4kB dirty:0kB writeback:0kB mapped:4kB shmem:0kB slab_reclaimable:6688kB slab_unreclaimable:79268kB kernel_stack:8kB pagetables:116kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:3 all_unreclaimable? no
[ 7109.164661] lowmem_reserve[]: 0 0 12096 12096
[ 7109.164665] Normal free:96kB min:53676kB low:67092kB high:80512kB active_anon:3382932kB inactive_anon:176kB active_file:10052kB inactive_file:21960kB unevictable:2164kB isolated(anon):0kB isolated(file):0kB present:12386304kB mlocked:2164kB dirty:0kB writeback:0kB mapped:8348kB shmem:288kB slab_reclaimable:17640kB slab_unreclaimable:205688kB kernel_stack:2416kB pagetables:9760kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:42 all_unreclaimable? no
[ 7109.164669] lowmem_reserve[]: 0 0 0 0
[ 7109.164670] DMA: 0_4kB 1_8kB 1_16kB 0_32kB 2_64kB 1_128kB 1_256kB 0_512kB 1_1024kB 1_2048kB 3_4096kB = 15896kB
[ 7109.164675] DMA32: 93_4kB 39_8kB 10_16kB 8_32kB 3_64kB 1_128kB 5_256kB 0_512kB 0_1024kB 0_2048kB 1_4096kB = 6796kB
[ 7109.164680] Normal: 0_4kB 0_8kB 0_16kB 0_32kB 0_64kB 0_128kB 0_256kB 0_512kB 0_1024kB 0_2048kB 0_4096kB = 0kB
[ 7109.164684] 9164 total pagecache pages
[ 7109.164685] 0 pages in swap cache
[ 7109.164686] Swap cache stats: add 0, delete 0, find 0/0
[ 7109.164687] Free swap = 0kB
[ 7109.164688] Total swap = 0kB
[ 7109.165449] 3964912 pages RAM
[ 7109.165449] 102944 pages reserved
[ 7109.165449] 16091 pages shared
[ 7109.165449] 3451991 pages non-shared
[ 7109.165449] SLUB: Unable to allocate memory on node -1 (gfp=0x20)
[ 7109.165449] cache: kmalloc-2048, object size: 2048, buffer size: 2048, default order: 3, min order: 0
[ 7109.165449] node 0: slabs: 131, objs: 2096, free: 59
[ 7109.216967] kswapd0: page allocation failure: order:0, mode:0x4020
[ 7109.216969] Pid: 405, comm: kswapd0 Tainted: P O 3.3.0 #3
[ 7109.216970] Call Trace:
[ 7109.216972] [] ? warn_alloc_failed+0xfc/0x150
[ 7109.216979] [] ? __netif_receive_skb+0x162/0x490
[ 7109.216981] [] ? __alloc_pages_nodemask+0x5c5/0x860
[ 7109.216984] [] ? get_partial_node.clone.48+0x137/0x1b0
[ 7109.216987] [] ? __netdev_alloc_skb+0x17/0x40
[ 7109.216989] [] ? new_slab+0x209/0x220
[ 7109.216991] [] ? __slab_alloc.clone.66+0x1f9/0x280
[ 7109.216995] [] ? br_handle_frame+0x1c0/0x260 [bridge]
[ 7109.216997] [] ? __netdev_alloc_skb+0x17/0x40
[ 7109.217000] [] ? __kmalloc_track_caller+0x175/0x190
[ 7109.217002] [] ? __alloc_skb+0x6e/0x170
[ 7109.217003] [] ? __netdev_alloc_skb+0x17/0x40
[ 7109.217010] [] ? e1000_alloc_rx_buffers+0x1fa/0x2e0 [e1000e]
[ 7109.217013] [] ? swiotlb_map_sg+0x10/0x10
[ 7109.217016] [] ? e1000_clean_rx_irq+0x22d/0x420 [e1000e]
[ 7109.217019] [] ? try_to_wake_up+0xd1/0x290
[ 7109.217022] [] ? e1000_clean+0xb0/0x2a0 [e1000e]
[ 7109.217024] [] ? net_rx_action+0x79/0x110
[ 7109.217027] [] ? __do_softirq+0x90/0x110
[ 7109.217030] [] ? call_softirq+0x1c/0x30
[ 7109.217032] [] ? do_softirq+0x4d/0x80
[ 7109.217034] [] ? irq_exit+0x86/0xa0
[ 7109.217036] [] ? do_IRQ+0x5c/0xd0
[ 7109.217038] [] ? common_interrupt+0x6b/0x6b
[ 7109.217039] [] ? spl_kmem_cache_create+0xde9/0x1040 [spl]
[ 7109.217047] [] ? spl_kmem_cache_reap_now+0x76/0x1d0 [spl]
[ 7109.217050] [] ? spl_kmem_cache_reap_now+0x17b/0x1d0 [spl]
[ 7109.217053] [] ? shrink_slab+0x134/0x1e0
[ 7109.217055] [] ? balance_pgdat+0x55c/0x700
[ 7109.217057] [] ? kswapd+0x186/0x2d0
[ 7109.217059] [] ? wake_up_bit+0x40/0x40
[ 7109.217061] [] ? balance_pgdat+0x700/0x700
[ 7109.217063] [] ? balance_pgdat+0x700/0x700
[ 7109.217065] [] ? kthread+0x9e/0xb0
[ 7109.217067] [] ? kernel_thread_helper+0x4/0x10
[ 7109.217068] [] ? flush_kthread_worker+0xc0/0xc0
[ 7109.217070] [] ? gs_change+0xb/0xb
[ 7109.217071] Mem-Info:
[ 7109.217072] DMA per-cpu:
[ 7109.217073] CPU 0: hi: 0, btch: 1 usd: 0
[ 7109.217074] CPU 1: hi: 0, btch: 1 usd: 0
[ 7109.217076] CPU 2: hi: 0, btch: 1 usd: 0
[ 7109.217077] CPU 3: hi: 0, btch: 1 usd: 0
[ 7109.217078] CPU 4: hi: 0, btch: 1 usd: 0
[ 7109.217079] CPU 5: hi: 0, btch: 1 usd: 0
[ 7109.217080] DMA32 per-cpu:
[ 7109.217081] CPU 0: hi: 186, btch: 31 usd: 30
[ 7109.217082] CPU 1: hi: 186, btch: 31 usd: 9
[ 7109.217083] CPU 2: hi: 186, btch: 31 usd: 27
[ 7109.217085] CPU 3: hi: 186, btch: 31 usd: 3
[ 7109.217086] CPU 4: hi: 186, btch: 31 usd: 0
[ 7109.217087] CPU 5: hi: 186, btch: 31 usd: 0
[ 7109.217088] Normal per-cpu:
[ 7109.217089] CPU 0: hi: 186, btch: 31 usd: 3
[ 7109.217090] CPU 1: hi: 186, btch: 31 usd: 35
[ 7109.217091] CPU 2: hi: 186, btch: 31 usd: 0
[ 7109.217092] CPU 3: hi: 186, btch: 31 usd: 17
[ 7109.217093] CPU 4: hi: 186, btch: 31 usd: 0
[ 7109.217094] CPU 5: hi: 186, btch: 31 usd: 0
[ 7109.217097] active_anon:879584 inactive_anon:44 isolated_anon:0
[ 7109.217098] active_file:2513 inactive_file:6126 isolated_file:0
[ 7109.217098] unevictable:542 dirty:0 writeback:0 unstable:0
[ 7109.217099] free:5869 slab_reclaimable:6082 slab_unreclaimable:71239
[ 7109.217100] mapped:2088 shmem:72 pagetables:2469 bounce:0
[ 7109.217103] DMA free:15896kB min:64kB low:80kB high:96kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15640kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
[ 7109.217106] lowmem_reserve[]: 0 3118 15214 15214
[ 7109.217111] DMA32 free:7484kB min:13836kB low:17292kB high:20752kB active_anon:135404kB inactive_anon:0kB active_file:0kB inactive_file:2544kB unevictable:4kB isolated(anon):0kB isolated(file):0kB present:3193664kB mlocked:4kB dirty:0kB writeback:0kB mapped:4kB shmem:0kB slab_reclaimable:6688kB slab_unreclaimable:79268kB kernel_stack:8kB pagetables:116kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 7109.217114] lowmem_reserve[]: 0 0 12096 12096
[ 7109.217119] Normal free:96kB min:53676kB low:67092kB high:80512kB active_anon:3382932kB inactive_anon:176kB active_file:10052kB inactive_file:21960kB unevictable:2164kB isolated(anon):0kB isolated(file):0kB present:12386304kB mlocked:2164kB dirty:0kB writeback:0kB mapped:8348kB shmem:288kB slab_reclaimable:17640kB slab_unreclaimable:205688kB kernel_stack:2416kB pagetables:9760kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:1 all_unreclaimable? no
[ 7109.217122] lowmem_reserve[]: 0 0 0 0
[ 7109.217124] DMA: 0_4kB 1_8kB 1_16kB 0_32kB 2_64kB 1_128kB 1_256kB 0_512kB 1_1024kB 1_2048kB 3_4096kB = 15896kB
[ 7109.217129] DMA32: 75_4kB 32_8kB 12_16kB 10_32kB 3_64kB 0_128kB 4_256kB 0_512kB 0_1024kB 0_2048kB 1_4096kB = 6380kB
[ 7109.217133] Normal: 18_4kB 7_8kB 0_16kB 0_32kB 0_64kB 0_128kB 0_256kB 0_512kB 0_1024kB 0_2048kB 0_4096kB = 128kB
[ 7109.217138] 9164 total pagecache pages
[ 7109.217139] 0 pages in swap cache
[ 7109.217140] Swap cache stats: add 0, delete 0, find 0/0
[ 7109.217141] Free swap = 0kB
[ 7109.217141] Total swap = 0kB
[ 7109.217828] 3964912 pages RAM
[ 7109.217828] 102944 pages reserved
[ 7109.217828] 16091 pages shared
[ 7109.217828] 3452119 pages non-shared
[ 7109.217828] SLUB: Unable to allocate memory on node -1 (gfp=0x20)
[ 7109.217828] cache: kmalloc-2048, object size: 2048, buffer size: 2048, default order: 3, min order: 0
[ 7109.217828] node 0: slabs: 131, objs: 2096, free: 74
[ 7109.268631] kswapd0: page allocation failure: order:0, mode:0x4020
[ 7109.268633] Pid: 405, comm: kswapd0 Tainted: P O 3.3.0 #3
[ 7109.268634] Call Trace:
[ 7109.268635] [] ? warn_alloc_failed+0xfc/0x150
[ 7109.268641] [] ? __netif_receive_skb+0x162/0x490
[ 7109.268644] [] ? __alloc_pages_nodemask+0x5c5/0x860
[ 7109.268647] [] ? __netdev_alloc_skb+0x17/0x40
[ 7109.268649] [] ? new_slab+0x209/0x220
[ 7109.268651] [] ? __slab_alloc.clone.66+0x1f9/0x280
[ 7109.268653] [] ? skb_gro_receive+0x2de/0x450
[ 7109.268655] [] ? __netdev_alloc_skb+0x17/0x40
[ 7109.268657] [] ? __kmalloc_track_caller+0x175/0x190
[ 7109.268659] [] ? __alloc_skb+0x6e/0x170
[ 7109.268661] [] ? __netdev_alloc_skb+0x17/0x40
[ 7109.268667] [] ? e1000_alloc_rx_buffers+0x1fa/0x2e0 [e1000e]
[ 7109.268670] [] ? swiotlb_map_sg+0x10/0x10
[ 7109.268673] [] ? e1000_clean_rx_irq+0x22d/0x420 [e1000e]
[ 7109.268676] [] ? e1000_clean+0xb0/0x2a0 [e1000e]
[ 7109.268678] [] ? net_rx_action+0x79/0x110
[ 7109.268681] [] ? __do_softirq+0x90/0x110
[ 7109.268683] [] ? call_softirq+0x1c/0x30
[ 7109.268686] [] ? do_softirq+0x4d/0x80
[ 7109.268687] [] ? irq_exit+0x86/0xa0
[ 7109.268689] [] ? do_IRQ+0x5c/0xd0
[ 7109.268691] [] ? common_interrupt+0x6b/0x6b
[ 7109.268692] [] ? spl_kmem_cache_create+0xde9/0x1040 [spl]
[ 7109.268700] [] ? spl_kmem_cache_reap_now+0x76/0x1d0 [spl]
[ 7109.268703] [] ? spl_kmem_cache_reap_now+0x17b/0x1d0 [spl]
[ 7109.268705] [] ? shrink_slab+0x134/0x1e0
[ 7109.268708] [] ? balance_pgdat+0x55c/0x700
[ 7109.268710] [] ? kswapd+0x186/0x2d0
[ 7109.268712] [] ? wake_up_bit+0x40/0x40
[ 7109.268714] [] ? balance_pgdat+0x700/0x700
[ 7109.268716] [] ? balance_pgdat+0x700/0x700
[ 7109.268717] [] ? kthread+0x9e/0xb0
[ 7109.268719] [] ? kernel_thread_helper+0x4/0x10
[ 7109.268721] [] ? flush_kthread_worker+0xc0/0xc0
[ 7109.268723] [] ? gs_change+0xb/0xb
[ 7109.268724] Mem-Info:
[ 7109.268725] DMA per-cpu:
[ 7109.268726] CPU 0: hi: 0, btch: 1 usd: 0
[ 7109.268727] CPU 1: hi: 0, btch: 1 usd: 0
[ 7109.268728] CPU 2: hi: 0, btch: 1 usd: 0
[ 7109.268730] CPU 3: hi: 0, btch: 1 usd: 0
[ 7109.268731] CPU 4: hi: 0, btch: 1 usd: 0
[ 7109.268732] CPU 5: hi: 0, btch: 1 usd: 0
[ 7109.268733] DMA32 per-cpu:
[ 7109.268734] CPU 0: hi: 186, btch: 31 usd: 30
[ 7109.268735] CPU 1: hi: 186, btch: 31 usd: 9
[ 7109.268736] CPU 2: hi: 186, btch: 31 usd: 27
[ 7109.268737] CPU 3: hi: 186, btch: 31 usd: 3
[ 7109.268739] CPU 4: hi: 186, btch: 31 usd: 0
[ 7109.268740] CPU 5: hi: 186, btch: 31 usd: 0
[ 7109.268741] Normal per-cpu:
[ 7109.268742] CPU 0: hi: 186, btch: 31 usd: 3
[ 7109.268743] CPU 1: hi: 186, btch: 31 usd: 35
[ 7109.268744] CPU 2: hi: 186, btch: 31 usd: 0
[ 7109.268745] CPU 3: hi: 186, btch: 31 usd: 17
[ 7109.268746] CPU 4: hi: 186, btch: 31 usd: 0
[ 7109.268747] CPU 5: hi: 186, btch: 31 usd: 0
[ 7109.268750] active_anon:879584 inactive_anon:44 isolated_anon:0
[ 7109.268751] active_file:2513 inactive_file:6126 isolated_file:0
[ 7109.268751] unevictable:542 dirty:0 writeback:0 unstable:0
[ 7109.268752] free:5869 slab_reclaimable:6082 slab_unreclaimable:71239
[ 7109.268753] mapped:2088 shmem:72 pagetables:2469 bounce:0
[ 7109.268756] DMA free:15896kB min:64kB low:80kB high:96kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15640kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
[ 7109.268759] lowmem_reserve[]: 0 3118 15214 15214
[ 7109.268764] DMA32 free:7484kB min:13836kB low:17292kB high:20752kB active_anon:135404kB inactive_anon:0kB active_file:0kB inactive_file:2544kB unevictable:4kB isolated(anon):0kB isolated(file):0kB present:3193664kB mlocked:4kB dirty:0kB writeback:0kB mapped:4kB shmem:0kB slab_reclaimable:6688kB slab_unreclaimable:79268kB kernel_stack:8kB pagetables:116kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 7109.268767] lowmem_reserve[]: 0 0 12096 12096
[ 7109.268771] Normal free:96kB min:53676kB low:67092kB high:80512kB active_anon:3382932kB inactive_anon:176kB active_file:10052kB inactive_file:21960kB unevictable:2164kB isolated(anon):0kB isolated(file):0kB present:12386304kB mlocked:2164kB dirty:0kB writeback:0kB mapped:8348kB shmem:288kB slab_reclaimable:17640kB slab_unreclaimable:205688kB kernel_stack:2416kB pagetables:9760kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:1 all_unreclaimable? no
[ 7109.268775] lowmem_reserve[]: 0 0 0 0
[ 7109.268777] DMA: 0_4kB 1_8kB 1_16kB 0_32kB 2_64kB 1_128kB 1_256kB 0_512kB 1_1024kB 1_2048kB 3_4096kB = 15896kB
[ 7109.268781] DMA32: 75_4kB 32_8kB 12_16kB 10_32kB 3_64kB 0_128kB 4_256kB 0_512kB 0_1024kB 0_2048kB 1_4096kB = 6380kB
[ 7109.268786] Normal: 18_4kB 7_8kB 0_16kB 0_32kB 0_64kB 0_128kB 0_256kB 0_512kB 0_1024kB 0_2048kB 0_4096kB = 128kB
[ 7109.268790] 9164 total pagecache pages
[ 7109.268791] 0 pages in swap cache
[ 7109.268792] Swap cache stats: add 0, delete 0, find 0/0
[ 7109.268793] Free swap = 0kB
[ 7109.268794] Total swap = 0kB
[ 7109.269497] 3964912 pages RAM
[ 7109.269497] 102944 pages reserved
[ 7109.269497] 16091 pages shared
[ 7109.269497] 3452119 pages non-shared
[ 7109.269497] SLUB: Unable to allocate memory on node -1 (gfp=0x20)
[ 7109.269497] cache: kmalloc-2048, object size: 2048, buffer size: 2048, default order: 3, min order: 0
[ 7109.269497] node 0: slabs: 131, objs: 2096, free: 41
[ 7109.319654] kswapd0: page allocation failure: order:0, mode:0x4020
[ 7109.319656] Pid: 405, comm: kswapd0 Tainted: P O 3.3.0 #3
[ 7109.319657] Call Trace:
[ 7109.319658] [] ? warn_alloc_failed+0xfc/0x150
[ 7109.319665] [] ? __netif_receive_skb+0x162/0x490
[ 7109.319667] [] ? __alloc_pages_nodemask+0x5c5/0x860
[ 7109.319670] [] ? __alloc_skb+0x140/0x170
[ 7109.319673] [] ? get_partial_node.clone.48+0x137/0x1b0
[ 7109.319675] [] ? __netdev_alloc_skb+0x17/0x40
[ 7109.319677] [] ? new_slab+0x209/0x220
[ 7109.319678] [] ? __slab_alloc.clone.66+0x1f9/0x280
[ 7109.319680] [] ? skb_gro_receive+0x2de/0x450
[ 7109.319682] [] ? __netdev_alloc_skb+0x17/0x40
[ 7109.319684] [] ? __kmalloc_track_caller+0x175/0x190
[ 7109.319686] [] ? __alloc_skb+0x6e/0x170
[ 7109.319688] [] ? __netdev_alloc_skb+0x17/0x40
[ 7109.319695] [] ? e1000_alloc_rx_buffers+0x1fa/0x2e0 [e1000e]
[ 7109.319698] [] ? swiotlb_map_sg+0x10/0x10
[ 7109.319701] [] ? e1000_clean_rx_irq+0x22d/0x420 [e1000e]
[ 7109.319704] [] ? e1000_clean+0xb0/0x2a0 [e1000e]
[ 7109.319707] [] ? net_rx_action+0x79/0x110
[ 7109.319709] [] ? __do_softirq+0x90/0x110
[ 7109.319712] [] ? call_softirq+0x1c/0x30
[ 7109.319715] [] ? do_softirq+0x4d/0x80
[ 7109.319716] [] ? irq_exit+0x86/0xa0
[ 7109.319718] [] ? do_IRQ+0x5c/0xd0
[ 7109.319720] [] ? common_interrupt+0x6b/0x6b
[ 7109.319721] [] ? spl_kmem_cache_create+0xde9/0x1040 [spl]
[ 7109.319728] [] ? spl_kmem_cache_reap_now+0x76/0x1d0 [spl]
[ 7109.319731] [] ? spl_kmem_cache_reap_now+0x17b/0x1d0 [spl]
[ 7109.319734] [] ? shrink_slab+0x134/0x1e0
[ 7109.319736] [] ? balance_pgdat+0x55c/0x700
[ 7109.319738] [] ? kswapd+0x186/0x2d0
[ 7109.319741] [] ? wake_up_bit+0x40/0x40
[ 7109.319742] [] ? balance_pgdat+0x700/0x700
[ 7109.319744] [] ? balance_pgdat+0x700/0x700
[ 7109.319746] [] ? kthread+0x9e/0xb0
[ 7109.319748] [] ? kernel_thread_helper+0x4/0x10
[ 7109.319750] [] ? flush_kthread_worker+0xc0/0xc0
[ 7109.319751] [] ? gs_change+0xb/0xb
[ 7109.319752] Mem-Info:
[ 7109.319753] DMA per-cpu:
[ 7109.319754] CPU 0: hi: 0, btch: 1 usd: 0
[ 7109.319756] CPU 1: hi: 0, btch: 1 usd: 0
[ 7109.319757] CPU 2: hi: 0, btch: 1 usd: 0
[ 7109.319758] CPU 3: hi: 0, btch: 1 usd: 0
[ 7109.319759] CPU 4: hi: 0, btch: 1 usd: 0
[ 7109.319760] CPU 5: hi: 0, btch: 1 usd: 0
[ 7109.319761] DMA32 per-cpu:
[ 7109.319762] CPU 0: hi: 186, btch: 31 usd: 30
[ 7109.319763] CPU 1: hi: 186, btch: 31 usd: 9
[ 7109.319764] CPU 2: hi: 186, btch: 31 usd: 27
[ 7109.319766] CPU 3: hi: 186, btch: 31 usd: 3
[ 7109.319767] CPU 4: hi: 186, btch: 31 usd: 0
[ 7109.319768] CPU 5: hi: 186, btch: 31 usd: 0
[ 7109.319769] Normal per-cpu:
[ 7109.319770] CPU 0: hi: 186, btch: 31 usd: 3
[ 7109.319771] CPU 1: hi: 186, btch: 31 usd: 35
[ 7109.319773] CPU 2: hi: 186, btch: 31 usd: 0
[ 7109.319774] CPU 3: hi: 186, btch: 31 usd: 17
[ 7109.319775] CPU 4: hi: 186, btch: 31 usd: 0
[ 7109.319776] CPU 5: hi: 186, btch: 31 usd: 0
[ 7109.319779] active_anon:879584 inactive_anon:44 isolated_anon:0
[ 7109.319779] active_file:2513 inactive_file:6126 isolated_file:0
[ 7109.319780] unevictable:542 dirty:0 writeback:0 unstable:0
[ 7109.319781] free:5869 slab_reclaimable:6082 slab_unreclaimable:71239
[ 7109.319781] mapped:2088 shmem:72 pagetables:2469 bounce:0
[ 7109.319785] DMA free:15896kB min:64kB low:80kB high:96kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15640kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
[ 7109.319788] lowmem_reserve[]: 0 3118 15214 15214
[ 7109.319792] DMA32 free:7484kB min:13836kB low:17292kB high:20752kB active_anon:135404kB inactive_anon:0kB active_file:0kB inactive_file:2544kB unevictable:4kB isolated(anon):0kB isolated(file):0kB present:3193664kB mlocked:4kB dirty:0kB writeback:0kB mapped:4kB shmem:0kB slab_reclaimable:6688kB slab_unreclaimable:79268kB kernel_stack:8kB pagetables:116kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 7109.319796] lowmem_reserve[]: 0 0 12096 12096
[ 7109.319800] Normal free:96kB min:53676kB low:67092kB high:80512kB active_anon:3382932kB inactive_anon:176kB active_file:10052kB inactive_file:21960kB unevictable:2164kB isolated(anon):0kB isolated(file):0kB present:12386304kB mlocked:2164kB dirty:0kB writeback:0kB mapped:8348kB shmem:288kB slab_reclaimable:17640kB slab_unreclaimable:205688kB kernel_stack:2416kB pagetables:9760kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:1 all_unreclaimable? no
[ 7109.319803] lowmem_reserve[]: 0 0 0 0
[ 7109.319805] DMA: 0_4kB 1_8kB 1_16kB 0_32kB 2_64kB 1_128kB 1_256kB 0_512kB 1_1024kB 1_2048kB 3_4096kB = 15896kB
[ 7109.319810] DMA32: 75_4kB 32_8kB 12_16kB 10_32kB 3_64kB 0_128kB 4_256kB 0_512kB 0_1024kB 0_2048kB 1_4096kB = 6380kB
[ 7109.319814] Normal: 18_4kB 7_8kB 0_16kB 0_32kB 0_64kB 0_128kB 0_256kB 0_512kB 0_1024kB 0_2048kB 0_4096kB = 128kB
[ 7109.319819] 9164 total pagecache pages
[ 7109.319820] 0 pages in swap cache
[ 7109.319821] Swap cache stats: add 0, delete 0, find 0/0
[ 7109.319822] Free swap = 0kB
[ 7109.319822] Total swap = 0kB
[ 7109.320561] 3964912 pages RAM
[ 7109.320561] 102944 pages reserved
[ 7109.320561] 16091 pages shared
[ 7109.320561] 3452119 pages non-shared
[ 7109.320561] SLUB: Unable to allocate memory on node -1 (gfp=0x20)
[ 7109.320561] cache: kmalloc-2048, object size: 2048, buffer size: 2048, default order: 3, min order: 0
[ 7109.320561] node 0: slabs: 131, objs: 2096, free: 0
[ 7109.370758] kswapd0: page allocation failure: order:0, mode:0x4020
[ 7109.370760] Pid: 405, comm: kswapd0 Tainted: P O 3.3.0 #3
[ 7109.370761] Call Trace:
[ 7109.370762] [] ? warn_alloc_failed+0xfc/0x150
[ 7109.370768] [] ? trigger_load_balance+0x59/0x2d0
[ 7109.370770] [] ? __alloc_pages_nodemask+0x5c5/0x860
[ 7109.370773] [] ? handle_irq_event_percpu+0x79/0x140
[ 7109.370776] [] ? __alloc_skb+0x140/0x170
[ 7109.370779] [] ? common_interrupt+0x6b/0x6b
[ 7109.370781] [] ? __netdev_alloc_skb+0x17/0x40
[ 7109.370783] [] ? new_slab+0x209/0x220
[ 7109.370785] [] ? __slab_alloc.clone.66+0x1f9/0x280
[ 7109.370787] [] ? skb_gro_receive+0x2de/0x450
[ 7109.370789] [] ? __netdev_alloc_skb+0x17/0x40
[ 7109.370791] [] ? __kmalloc_track_caller+0x175/0x190
[ 7109.370792] [] ? __alloc_skb+0x6e/0x170
[ 7109.370794] [] ? __netdev_alloc_skb+0x17/0x40
[ 7109.370800] [] ? e1000_alloc_rx_buffers+0x1fa/0x2e0 [e1000e]
[ 7109.370803] [] ? swiotlb_map_sg+0x10/0x10
[ 7109.370806] [] ? e1000_clean_rx_irq+0x28a/0x420 [e1000e]
[ 7109.370809] [] ? e1000_clean+0xb0/0x2a0 [e1000e]
[ 7109.370812] [] ? net_rx_action+0x79/0x110
[ 7109.370814] [

@pyavdr
Copy link
Contributor

pyavdr commented Apr 3, 2012

Just a question,

did you check if there is a swap device with some space available? In my case, there was some 200 MB swap space needed, while using 20 GB RAM and konfigured 2 GB swap space on opensuse. It maybe the case that your server cant use swap " Free swap = 0kB, Total swap = 0kB".

@ryao
Copy link
Contributor

ryao commented Apr 3, 2012

I have no swap device. My plan is to use a zvol for swap when the issues involving that have been solved.

@pyavdr
Copy link
Contributor

pyavdr commented Apr 3, 2012

Ok, i need to try that too.

@pyavdr
Copy link
Contributor

pyavdr commented Apr 3, 2012

Ok, within Opensuse (kernel 3.1.9)

i created a swap zvol : zfs create -o volblocksize=64k -V 10G /stor2/zfsswap
did a :mkswap /dev/zd16
swapon /dev/zd16

created 100.000 random data files using 100 GB on another zpool, it uses up to 12 GB RAM. It is using
the zfsswap without any problems, 40 MB used on that zfsswapdevice, no messages in dmesg for the first 10 minutes. But as always: using swap makes the box really slow, starting eclipse takes some minutes:-) .

@behlendorf
Copy link
Contributor Author

First off thanks for trying the patch. This is the kind of feedback I need.

The memory allocation failed because it was GFP_ATOMIC. These types of allocations are typically only done in interrupt context thus are not allowed to sleep and invoke any of the memory reclaim logic. The free memory must be available right now on the system. There's really not much we can do about that other than use less memory or increase min_free_kbytes to leave a larger reserve. A swap device might help too, in my experience Linux still can't really run without swap safely for a wide variety of workloads.

As for your success with the swap device that's good to hear although I haven't fixed anything there yet. So I'm not sure how stable that will be.

@ryao
Copy link
Contributor

ryao commented Apr 3, 2012

@pyavdr You might be interested in issue #342. As far as testing swap goes, you probably should fill the swap file to half full by filling a tmpfs or some other means. If your system doesn't lockup, then that would be very good news.

@behlendorf I am not sure if increasing min_free_kbytes is the right way to address this. This issue looks like a mix of internal and external fragmentation in the SLUB allocator. It is internal because SLUB has wasted up to 50% of our allocated space and some of that wasted free space is likely adjacent to unallocated free space that might have been big enough to satisfy these allocation requests had the wasted space been available. It is also external because if the free space chunks were more continuous, these allocations would have succeed.

I imagine that we could patch the ZFS code to do allocations from a heap in a virtual address space, which should permit us to fight this kind of fragmentation. Another possibility is to patch the kernel to provide better guarantees on the buckets available when entering an ATOMIC section, but that does not seem to be as good of a solution to me.

What do you think?

@ryao
Copy link
Contributor

ryao commented Apr 3, 2012

Actually, this issue is more complicated than I first thought. I suspect that it would not happen if CONFIG_PREEMPT_VOLUNTARY=y was not set, although this is not a proper fix. I will test that and post my results.

@ryao
Copy link
Contributor

ryao commented Apr 3, 2012

@behlendorf, I seem to have overreacted earlier. Disabling CONFIG_PREEMPT_VOLUNTARY made the system stable. ZFS is freeing memory in low memory situations. My only complaint is that it appears to free about 6 gigabytes on a 16GB system, which seems to be a little extreme.

This would appear to be safe as long as you patch the ./configure script to fail when CONFIG_PREEMPT_VOLUNTARY is enabled.

@behlendorf
Copy link
Contributor Author

@gentoofan Thanks for the update. Adding support for preempt is getting overdue at this point, we have a long standing issue open #83. However, I only fail configure on CONFIG_PREEMPT I should probably add CONFIG_PREEMPT_VOLUNTARY. Getting full preempt support going isn't a ton of work, it just requires some care and a whole lot of testing.

As for the 6GB free that does seem a bit much. This is likely due to have the shrinker reclaim functions are implemented they always err on the side of returning to much. They could/should be updated simply to scan the requested number of objects and free what they can. We'll certainly look in to that too, but one step at a time.

@pyavdr
Copy link
Contributor

pyavdr commented Apr 4, 2012

@gentofan Testing zfsswap on opensuse 12.1 (SMP kernel 3.1.9) with memtester and the ARC patch on 0.56-rc8. As soon the usage of zfsswap increases, the system locks. Need to reset the system, no chance to get some traces.

@behlendorf It looks like that every new feature rises new problems, which are sometimes caused by older not solved issues. Maybe you guys should concentrate on solving the essential old issues, thus making ZOL reliable. This should help to implement new features much faster and with less errors, because you dont need to search for problems caused by known older issues and you can incorporate known design rules for new features. Not solving the old issues may cause workarounds which costs double work and making ZOL unreliable. In terms of reliability error handling on vdevs, and making memory usage waterproof is essential. Features for usage (Samba support, Iscsi support, zvols, snapshots) makes ZOL usable. So implementing this ARC patch is the right way to solve well known design problems from old issues. Please go on for the essential old issues. In todays state ZOL makes more fun then ever. Im prepared to assist on testing as far as my knowledge allows. Just my 2 cents.

@ryao
Copy link
Contributor

ryao commented Apr 4, 2012

@pyadvr Does this patch break anything that was working previously?

@pyavdr
Copy link
Contributor

pyavdr commented Apr 4, 2012

@gentoofan As far as i tested everything works fine with opensuse 12.1 kernel 3.1.9 and this patch. ( But Opensuse uses systemd, which is not implemented yet .. so no automount or installing with ppa, zvols are not creating the /dev/zvol directory and more ...) I checked also vanila kernel 3.3.1 on opensuse, but not complete. To answer your question in total, the ZOL and SPL testsuites should become reliable for all supported plattforms, which is - as far as i see - not the case. In detail we are free to add some more testcases ( rsync? creating&deleting large files? access to xattrb? .zfs directory? zfs send&receive? snapshots?... ). Im sure that Brian uses lots of testcases. Maybe some of them should be available for testing.

@ryao
Copy link
Contributor

ryao commented Apr 4, 2012

@pyavdr This is a pull request for code that improves memory management. Your suggestions are unrelated to it, so they are unlikely to receive much attention here. You should file a new issue for them.

@behlendorf
Copy link
Contributor Author

@pyavdr Correctness and stability has always been my first priority. That's one of the major reasons I have yet to tag a stable release... we're not there yet. Yes, lots of people are running the release candidates successfully, but it's not to the point yet where I feel comfortable calling it stable. We are talking about a filesystem here and that means we need to set an exceptionally high bar. People are slow to forgive data loss and often first impressions last a long time.

As for pulling is new features I've tried to keep that to a minimum. However, there are certain features I want to be there in the production release so they have been merged after some decent testing, for example snapshots. Other features such as the pending smbfs support are relatively low risk and isolated so I may bring in that code.

I'm also all for additional testing. I do quite a bit of testing for every commit in an automated build farm but more is always better. What I would like to see happen, but haven't found anyone to do, is for the upstream ZFS test suite to get ported to Linux (Issue #6). It has a whole mess of existing tests to verify the basic ZFS functionality. If you have the ability and time getting this ported would certainly help improve stability and prevent regressions.

As for this VM patch I'm currently feeling pretty good about it. The reported issues this far have been unrelated to this change near as I can tell. There's still certainly room for improvement here but this should help.

@ryao
Copy link
Contributor

ryao commented Apr 5, 2012

Brian, I started some rsyncs while running 3 Virtual Machines and the system locked up, although it did it gradually. I first lost access to root, but I was able to ssh user@ip cat /path/to a few things.

I had a few levels of virtualization running on the system. First, I had 3 virtual machines running in KVM. In one was Open Indiana, in which I was installing Gentoo Prefix inside a Solaris Zone. Interestingly, my SSH connection to the host system and the KVM virtual machine died around the same time, while the Solaris Zone kept operating for about a minute. I was able to log into the system and get a shell, but attemping to sudo locked up. I then started piping information to my desktop until the machine had locked up entirely. I was only able to run a few commands. You can see the output of most of them below.

Here is an excerpt of dmesg:

[17914.034994] failure to allocate a tage (552)
[17914.036768] failure to allocate a tage (501)
[17914.039932] failure to allocate a tage (259)
[17914.040104] failure to allocate a tage (552)
[17914.042535] failure to allocate a tage (501)

It had several hundred of those. That was the only thing printed in the log in relation to this event. Free memory was at about 4GB, although I did not try to pipe that to a file until after SSH had stopped functioning, which prevented me from recording it.

Here is /proc/spl/kstat/zfs/arcstats:

4 1 0x01 77 3696 2006449653 18313977911159
name type data
hits 4 2082028
misses 4 159780
demand_data_hits 4 1355144
demand_data_misses 4 83422
demand_metadata_hits 4 463477
demand_metadata_misses 4 9489
prefetch_data_hits 4 85750
prefetch_data_misses 4 58648
prefetch_metadata_hits 4 177657
prefetch_metadata_misses 4 8221
mru_hits 4 597385
mru_ghost_hits 4 715
mfu_hits 4 1221236
mfu_ghost_hits 4 901
deleted 4 224893
recycle_miss 4 394
mutex_miss 4 36
evict_skip 4 145
evict_l2_cached 4 0
evict_l2_eligible 4 4530302976
evict_l2_ineligible 4 676677632
hash_elements 4 189222
hash_elements_max 4 411427
hash_collisions 4 486718
hash_chains 4 43143
hash_chain_max 4 9
p 4 9216659
c 4 1899279032
c_min 4 1610612736
c_max 4 12884901888
size 4 1866832200
hdr_size 4 122227136
data_size 4 1628502528
other_size 4 116102536
anon_size 4 815104
anon_evict_data 4 0
anon_evict_metadata 4 0
mru_size 4 393357824
mru_evict_data 4 232253952
mru_evict_metadata 4 59895808
mru_ghost_size 4 1500018688
mru_ghost_evict_data 4 1395628544
mru_ghost_evict_metadata 4 104390144
mfu_size 4 1234329600
mfu_evict_data 4 1202600960
mfu_evict_metadata 4 6947840
mfu_ghost_size 4 2752512
mfu_ghost_evict_data 4 2219008
mfu_ghost_evict_metadata 4 533504
l2_hits 4 0
l2_misses 4 0
l2_feeds 4 0
l2_rw_clash 4 0
l2_read_bytes 4 0
l2_write_bytes 4 0
l2_writes_sent 4 0
l2_writes_done 4 0
l2_writes_error 4 0
l2_writes_hdr_miss 4 0
l2_evict_lock_retry 4 0
l2_evict_reading 4 0
l2_free_on_write 4 0
l2_abort_lowmem 4 0
l2_cksum_bad 4 0
l2_io_error 4 0
l2_size 4 0
l2_hdr_size 4 0
memory_throttle_count 4 15454
memory_direct_count 4 3183
memory_indirect_count 4 6565
arc_no_grow 4 0
arc_tempreserve 4 0
arc_loaned_bytes 4 0
arc_prune 4 0
arc_meta_used 4 431457096
arc_meta_limit 4 3221225472
arc_meta_max 4 548193064

The system still responds to pings and port 22 is still open, although ssh blocks upon "debug1: Entering interactive session." when running it with -vv. Looking at network utilization from the router, the rsync processes do not appear to be downloading anything. Lastly, the system software watchdog did not trigger.

@pyavdr
Copy link
Contributor

pyavdr commented Apr 5, 2012

Hi Brian,
i started the usual splat tests withhin Opensuse 12.1. (Kernel 3.1.9) with this ARC patch.
/sbin/modprobe splat; /usr/sbin/splat -a
while executing kmem:slab_lock the system locks up, until i got this kernel soft lockup oops:

[22703.082949] BUG: soft lockup - CPU#7 stuck for 22s! [splat_kmem_cach:22555]
[22703.082951] Modules linked in: splat iscsi_trgt crc32c_intel zfs(P) zcommon(P) znvpair(P) zavl(P) zunicode(P) spl zlib_deflate fuse vmhgfs vsock acp
iphp mperf joydev snd_ens1371 gameport snd_rawmidi snd_seq_device snd_ac97_codec ac97_bus snd_pcm snd_timer snd soundcore floppy shpchp sr_mod i2c_piix
4 cdrom ppdev sg parport_pc parport pci_hotplug vmci snd_page_alloc mptctl vmw_balloon pcspkr container button ac autofs4 usbhid uhci_hcd ehci_hcd usbc
ore processor thermal_sys ata_generic mptspi mptscsih mptbase scsi_transport_spi vmxnet vmw_pvscsi vmxnet3 [last unloaded: crc32c_intel]
[22703.082979] CPU 7
[22703.082979] Modules linked in: splat iscsi_trgt crc32c_intel zfs(P) zcommon(P) znvpair(P) zavl(P) zunicode(P) spl zlib_deflate fuse vmhgfs vsock acp
iphp mperf joydev snd_ens1371 gameport snd_rawmidi snd_seq_device snd_ac97_codec ac97_bus snd_pcm snd_timer snd soundcore floppy shpchp sr_mod i2c_piix
4 cdrom ppdev sg parport_pc parport pci_hotplug vmci snd_page_alloc mptctl vmw_balloon pcspkr container button ac autofs4 usbhid uhci_hcd ehci_hcd usbc
ore processor thermal_sys ata_generic mptspi mptscsih mptbase scsi_transport_spi vmxnet vmw_pvscsi vmxnet3 [last unloaded: crc32c_intel]
[22703.083002]
[22703.083004] Pid: 22555, comm: splat_kmem_cach Tainted: P 3.1.9-1.4-default #1 VMware, Inc. VMware Virtual Platform/440BX Desktop Referenc
e Platform
[22703.083008] RIP: 0010:[] [] memset+0x39/0xc0
[22703.083013] RSP: 0018:ffff8802ccb49c88 EFLAGS: 00010207
[22703.083014] RAX: aaaaaaaaaaaaaaaa RBX: 8000000000000163 RCX: 0000000000000c0c
[22703.083016] RDX: 0000000000000000 RSI: 00000000000000aa RDI: ffffc90260308ff0
[22703.083017] RBP: ffffc9025fdf9000 R08: 0000000000000004 R09: 0000000000000004
[22703.083019] R10: ffffc902602f936c R11: 000000000003ffec R12: 00000000000012d2
[22703.083020] R13: 0000000000000000 R14: ffffc90018e7c000 R15: ffffc9001dd32000
[22703.083022] FS: 0000000000000000(0000) GS:ffff88032d2e0000(0000) knlGS:0000000000000000
[22703.083024] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[22703.083025] CR2: 00007ff31dd51000 CR3: 0000000317786000 CR4: 00000000000406e0
[22703.083029] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[22703.083033] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[22703.083035] Process splat_kmem_cach (pid: 22555, threadinfo ffff8802ccb48000, task ffff8802cef76340)
[22703.083036] Stack:
[22703.083038] ffffffffa046be5b ffff8802c9ace000 ffffffffa02a7af8 00000000ffffffff
[22703.083041] 000000000000000d 0000000000000000 ffffffffffffffff 00000000000002d2
[22703.083044] ffffffff81121f55 ffff8802cc3ab980 ffffffff811242c2 ffff880200000000
[22703.083047] Call Trace:
[22703.083054] [] splat_kmem_cache_test_constructor+0x3b/0x50 [splat]
[22703.083067] [] spl_slab_alloc+0x239/0x307 [spl]
[22703.083078] [] spl_cache_grow+0xc6/0x1e6 [spl]
[22703.083089] [] spl_cache_refill+0xba/0x305 [spl]
[22703.083099] [] spl_kmem_cache_alloc+0x13e/0x1b0 [spl]
[22703.083108] [] splat_kmem_cache_test_thread+0xde/0x290 [splat]
[22703.083115] [] thread_generic_wrapper+0x75/0x90 [spl]
[22703.083124] [] kthread+0x7e/0x90
[22703.083128] [] kernel_thread_helper+0x4/0x10
[22703.083131] Code: 01 01 01 01 01 01 48 f7 e1 41 89 f9 41 83 e1 07 75 7e 44 89 d9 c1 e9 06 74 38 0f 1f 84 00 00 00 00 00 ff c9 48 89 07 48 89 47 08
[22703.083145] 89 47 10 48 89 47 18 48 89 47 20 48 89 47 28 48 89 47 30 48
[22703.083152] Call Trace:
[22703.083156] [] splat_kmem_cache_test_constructor+0x3b/0x50 [splat]
[22703.083164] [] spl_slab_alloc+0x239/0x307 [spl]
[22703.083174] [] spl_cache_grow+0xc6/0x1e6 [spl]
[22703.083184] [] spl_cache_refill+0xba/0x305 [spl]
[22703.083194] [] spl_kmem_cache_alloc+0x13e/0x1b0 [spl]
[22703.083202] [] splat_kmem_cache_test_thread+0xde/0x290 [splat]
[22703.083209] [] thread_generic_wrapper+0x75/0x90 [spl]
[22703.083218] [] kthread+0x7e/0x90
[22703.083221] [] kernel_thread_helper+0x4/0x10

This lines are repeated for each CPU.

I give it a second run, ths system gives again a soft lock message at kmem:slab_overcommit:

[23341.132679] BUG: soft lockup - CPU#7 stuck for 23s! [splat_kmem_cach:25351]
[23341.132684] Modules linked in: splat iscsi_trgt crc32c_intel zfs(P) zcommon(P) znvpair(P) zavl(P) zunicode(P) spl zlib_deflate fuse vmhgfs vsock acpiphp mperf joydev snd_ens1371 gameport snd_rawmidi snd_seq_device snd_ac97_codec ac97_bus snd_pcm snd_timer snd soundcore floppy shpchp sr_mod i2c_piix4 cdrom ppdev sg parport_pc parport pci_hotplug vmci snd_page_alloc mptctl vmw_balloon pcspkr container button ac autofs4 usbhid uhci_hcd ehci_hcd usbcore processor thermal_sys ata_generic mptspi mptscsih mptbase scsi_transport_spi vmxnet vmw_pvscsi vmxnet3 [last unloaded: crc32c_intel]
[23341.132762] CPU 7
[23341.132764] Modules linked in: splat iscsi_trgt crc32c_intel zfs(P) zcommon(P) znvpair(P) zavl(P) zunicode(P) spl zlib_deflate fuse vmhgfs vsock acpiphp mperf joydev snd_ens1371 gameport
[23341.132784] BUG: soft lockup - CPU#6 stuck for 23s! [splat_kmem_cach:25349]
[23341.132789] Modules linked in: splat snd_rawmidi snd_seq_device snd_ac97_codec ac97_bus snd_pcm snd_timer snd soundcore floppy shpchp sr_mod i2c_piix4 cdrom ppdev sg parport_pc parport pci_hotplug vmci snd_page_alloc mptctl vmw_balloon pcspkr container button ac autofs4 usbhid uhci_hcd ehci_hcd usbcore processor thermal_sys ata_generic mptspi mptscsih mptbase scsi_transport_spi vmxnet vmw_pvscsi vmxnet3 [last unloaded: crc32c_intel]
[23341.132837]
[23341.132841] Pid: 25351, comm: splat_kmem_cach Tainted: P 3.1.9-1.4-default #1 iscsi_trgt VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform
[23341.132852] RIP: 0010:[] [] memset+0x32/0xc0
[23341.132862] RSP: 0018:ffff880220f29c88 EFLAGS: 00010203
[23341.132866] RAX: aaaaaaaaaaaaaaaa RBX: 8000000000000163 RCX: 0000000000000ccd
[23341.132869] RDX: 0000000000000000 RSI: 00000000000000aa RDI: ffffc901b0221000
[23341.132873] RBP: ffffc901afc94000 R08: 0000000000000004 R09: 0000000000000004
[23341.132876] R10: ffffc901b02143bc R11: 000000000003ffec R12: 00000000000012d2
[23341.132880] R13: 0000000000000000 R14: ffffffffffffff10 R15: ffffc9001aae1000
[23341.132884] FS: 0000000000000000(0000) GS:ffff88032d2e0000(0000) knlGS:0000000000000000
[23341.132889] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[23341.132892] CR2: 00007ff31dd51000 CR3: 00000003176e0000 CR4: 00000000000406e0
[23341.132896] crc32c_intel zfs(P) zcommon(P)
[23341.132901] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[23341.132904] znvpair(P) zavl(P) zunicode(P)
[23341.132909] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[23341.132913] Process splat_kmem_cach (pid: 25351, threadinfo ffff880220f28000, task ffff8802789d8740)
[23341.132917] Stack:
[23341.132919] ffffffffa046be5b spl ffff8802cbdec000 ffffffffa02a7af8 00000000ffffffff
[23341.132927] 000000000000000d 0000000000000000 ffffffffffffffff 00000000000002d2
[23341.132934] ffffffff81121f55 ffff8802c98ab2c0 ffffffff811242c2 ffff880200000000
[23341.132941] Call Trace:
[23341.132962] zlib_deflate fuse vmhgfs vsock acpiphp mperf joydev snd_ens1371 gameport snd_rawmidi
[23341.132980] [] splat_kmem_cache_test_constructor+0x3b/0x50 [splat]
[23341.132983] snd_seq_device snd_ac97_codec ac97_bus snd_pcm snd_timer snd soundcore floppy shpchp sr_mod i2c_piix4 cdrom ppdev sg
[23341.133008] [] spl_slab_alloc+0x239/0x307 [spl]
[23341.133011] parport_pc parport pci_hotplug vmci snd_page_alloc mptctl vmw_balloon pcspkr container button ac autofs4
[23341.133031] [] spl_cache_grow+0xc6/0x1e6 [spl]
[23341.133035] usbhid uhci_hcd ehci_hcd usbcore processor thermal_sys ata_generic mptspi mptscsih mptbase scsi_transport_spi
[23341.133053] [] spl_cache_refill+0xba/0x305 [spl]
[23341.133057] vmxnet vmw_pvscsi vmxnet3 [last unloaded: crc32c_intel]
[23341.133063] CPU 6
[23341.133064] Modules linked in: splat
[23341.133068] iscsi_trgt crc32c_intel zfs(P) zcommon(P) znvpair(P) zavl(P) zunicode(P) spl zlib_deflate fuse vmhgfs vsock acpiphp mperf joydev snd_ens1371 gameport snd_rawmidi snd_seq_device snd_ac97_codec ac97_bus snd_pcm snd_timer snd soundcore floppy shpchp sr_mod i2c_piix4 cdrom ppdev sg parport_pc parport pci_hotplug vmci snd_page_alloc mptctl vmw_balloon pcspkr container button ac autofs4 usbhid uhci_hcd ehci_hcd usbcore processor thermal_sys ata_generic mptspi mptscsih mptbase scsi_transport_spi vmxnet vmw_pvscsi vmxnet3 [last unloaded: crc32c_intel]
[23341.133132]
[23341.133136] Pid: 25349, comm: splat_kmem_cach Tainted: P 3.1.9-1.4-default #1 [] spl_kmem_cache_alloc+0x13e/0x1b0 [spl]
[23341.133150] VMware, Inc. VMware Virtual Platform/440BX Desktop Reference Platform
[23341.133155] RIP: 0010:[] [] memset+0x4d/0xc0
[23341.133167] [] splat_kmem_cache_test_thread+0xde/0x290 [splat]
[23341.133172] RSP: 0018:ffff8802ce6efc88 EFLAGS: 00010207
[23341.133175] RAX: aaaaaaaaaaaaaaaa RBX: 8000000000000163 RCX: 00000000000002cc
[23341.133186] [] thread_generic_wrapper+0x75/0x90 [spl]
[23341.133190] RDX: 0000000000000000 RSI: 00000000000000aa RDI: ffffc901b5192fc8
[23341.133193] RBP: ffffc901b4c9e000 R08: 0000000000000004 R09: 0000000000000004
[23341.133196] R10: ffffc901b515e344 R11: 000000000003ffec R12: 00000000000012d2
[23341.133199] R13: 0000000000000000 R14: 0000000000000010 R15: ffffc9001ab13000
[23341.133206] [] kthread+0x7e/0x90
[23341.133211] FS: 0000000000000000(0000) GS:ffff88032d2c0000(0000) knlGS:0000000000000000
[23341.133219] [] kernel_thread_helper+0x4/0x10
[23341.133223] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[23341.133225] Code: 0f b6 ce 48 b8 01 01 01 01 01 01 01 01 48 f7 e1 41 89 f9 41 83 e1 07 75 7e 44 89 d9 c1 e9 06 74 38 0f 1f 84 00 00 00 00 00 ff c9
[23341.133265] 89 07 48 89 47 08 48 89 47 10 48 89 47 18 48 89 47 20 48 89
[23341.133284] Call Trace:
[23341.133287] CR2: 00007ff31dd51000 CR3: 0000000001a05000 CR4: 00000000000406e0
[23341.133294] [] splat_kmem_cache_test_constructor+0x3b/0x50 [splat]
[23341.133304] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[23341.133315] [] spl_slab_alloc+0x239/0x307 [spl]
[23341.133323] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[23341.133327] Process splat_kmem_cach (pid: 25349, threadinfo ffff8802ce6ee000, task ffff8802cedaa6c0)
[23341.133338] [] spl_cache_grow+0xc6/0x1e6 [spl]
[23341.133341] Stack:
[23341.133343] ffffffffa046be5b ffff8802cbdec000 ffffffffa02a7af8 00000000ffffffff
[23341.133350] 000000000000000d [] spl_cache_refill+0xba/0x305 [spl]
[23341.133362] 0000000000000000 ffffffffffffffff 00000000000002d2
[23341.133367] ffffffff81121f55 ffff8802c98ab280 ffffffff811242c2 ffff880200000000
[23341.133375] Call Trace:
[23341.133386] [] spl_kmem_cache_alloc+0x13e/0x1b0 [spl]
[23341.133394] [] splat_kmem_cache_test_constructor+0x3b/0x50 [splat]
[23341.133413] [] splat_kmem_cache_test_thread+0xde/0x290 [splat]
[23341.133427] [] spl_slab_alloc+0x239/0x307 [spl]
[23341.133442] [] thread_generic_wrapper+0x75/0x90 [spl]
[23341.133454] [] spl_cache_grow+0xc6/0x1e6 [spl]
[23341.133475] [] spl_cache_refill+0xba/0x305 [spl]
[23341.133480] [] kthread+0x7e/0x90
[23341.133488] [] kernel_thread_helper+0x4/0x10
[23341.133502] [] spl_kmem_cache_alloc+0x13e/0x1b0 [spl]
[23341.133520] [] splat_kmem_cache_test_thread+0xde/0x290 [splat]
[23341.133535] [] thread_generic_wrapper+0x75/0x90 [spl]
[23341.133553] [] kthread+0x7e/0x90
[23341.133561] [] kernel_thread_helper+0x4/0x10
[23341.133566] Code: d9 c1 e9 06 74 38 0f 1f 84 00 00 00 00 00 ff c9 48 89 07 48 89 47 08 48 89 47 10 48 89 47 18 48 89 47 20 48 89 47 28 48 89 47 30
[23341.133595] 89 47 38 48 8d 7f 40 75 d9 66 0f 1f 84 00 00 00 00 00 44 89
[23341.133609] Call Trace:
[23341.133617] [] splat_kmem_cache_test_constructor+0x3b/0x50 [splat]
[23341.133633] [] spl_slab_alloc+0x239/0x307 [spl]
[23341.133653] [] spl_cache_grow+0xc6/0x1e6 [spl]
[23341.133672] [] spl_cache_refill+0xba/0x305 [spl]
[23341.133692] [] spl_kmem_cache_alloc+0x13e/0x1b0 [spl]
[23341.133709] [] splat_kmem_cache_test_thread+0xde/0x290 [splat]
[23341.133723] [] thread_generic_wrapper+0x75/0x90 [spl]
[23341.133741] [] kthread+0x7e/0x90
[23341.133748] [] kernel_thread_helper+0x4/0x10

After that the system runs the rest of the splat tests fine. There was no reset needed.

@behlendorf
Copy link
Contributor Author

@gentoofan: Were you using the latest version of this patch when you encountered the deadlock. There was a change made last week to more correctly account for the ghost list in the reclaim logic. We observed a similar issue.

@behlendorf
Copy link
Contributor Author

@pyavdr Thanks for the feedback. Those particular splat tests are designed to push the spl slab implementation as hard as possible. Likely much harder than zfs ever will. The slab_overcommit test is particularly nasty. Since the system just issued a few warning about being slow under the pressure that's actually pretty encouraging. Still, there's always room for improvement.

@ryao
Copy link
Contributor

ryao commented Apr 5, 2012

@behlendorf I was using commit 36a0e0d6ce2b18d9a5fca266fc3e8c7fd9baab4e. If I recall correctly, I cherry picked it two days ago. I take it that is the old version.

I will retest with 525c13f.

@behlendorf
Copy link
Contributor Author

@gentoofan Actually, commit 36a0e0d6ce2b18d9a5fca266fc3e8c7fd9baab4e does have the fix I was referring too, so I'll look a bit more carefully at the arc stats

@ryao
Copy link
Contributor

ryao commented Apr 5, 2012

This just happened to me again, although I was not able to get any output. I was recompiling Gentoo inside a virtual machine as part of a Gentoo install. The purpose had been to test booting Gentoo Linux off a raidz2 vdev using GRUB2.

There was a brief lag a few minutes before it happened, after which I had spotted a message in the host's dmesg stating that "hpet increased min_delta_ns". This is with Linux 3.3.1 in the host and Linux 3.3.0 from the Gentoo 12.1 LiveDVD in the guest.

After it happened, I could still interact with the host using screen over SSH, but running dmesg locked the screen window and new ones would not open. The system still reponded to pings and port 22 was still open, but I could not open new SSH connections.. Additionally, the system's CPU fan was running at an elevated RPM, which would suggest that there was some sort of CPU activity, although I do not know what that was for certain.

@chrisrd
Copy link
Contributor

chrisrd commented Apr 6, 2012

FYI, I've now had 2 lockups whilst running with openzfs/spl@8920c69, behlendorf/zfs@525c13f, the first on linux-3.3.0 and the second on linux-3.3.1. The machine would respond to pings, but I couldn't get any action from ssh windows open to the machine nor login anew, no response on the console, and kern.log ("locally" on an NFS-mounted root and to a remote syslog server) didn't show anything. The workload in both cases was a large tar to zfs from an md/lvm/ext4 partition on the same machine but different disks to zfs. Now continuing on with same workload to see if I get lockup number 3, and if so will then try without "Integrate ARC more tightly with Linux".

@ryao
Copy link
Contributor

ryao commented Apr 9, 2012

@behlendorf Is it possible that you have been testing this with behlendorf/zfs@c475167 included in your build?

@behlendorf
Copy link
Contributor Author

@gentoofan Yes, this commit, c475167 , has been in our master branch for quite some time now. You should be using it as well. Why?

@ryao
Copy link
Contributor

ryao commented Apr 10, 2012

I had managed to import this fix from Illumos in the process of importing fixes for issue #644 and mistakenly thought that we were missing that patch. If I recall, this one was odd in that it required manual editing to import and until now, I had not had a chance to follow-up on my mental note as to why. Looking at it more closely, the reason is that we had already merged it.

Please disregard my previous comment.

@ryao
Copy link
Contributor

ryao commented Apr 12, 2012

I have been testing this on my desktop. When compiling things with many X processes running, the system will lag. There is a correlation between increases in memory_direct_count (and to a lesser extent, memory_indirect_count) and these lags. I managed to get a split-second view of htop during a lag. All CPU cores were spending >90% of their time in the kernel.

Previously, I had tested this on my server and my SSH sessions would appear to freeze temporarily when the system was under load. I assume that the issue I observed on my server is the same as the one I observe on my desktop.

@ryao
Copy link
Contributor

ryao commented Apr 12, 2012

The issues I mentioned in my previous comment appear to have been the result of memory pressure caused by the limits set in 23bdb07.

I have written a patch to address that. It is a bit early to say that this has resolved the issue that I described in my previous comment, but my initial results are promising. I have opened pull request #660 with my patch.

@ryao
Copy link
Contributor

ryao commented Apr 13, 2012

While my patch helped, the original lag issue is not solved. It just happened again when compiling GCC 4.6.2.

@behlendorf
Copy link
Contributor Author

@gentoofan I suspect the lag your seeing is being caused by zfs attempting too free to much in the direct reclaim path. The Linux shrinker's request that a specific number of objects in a cache be scanned and any objects which can be freed in that group are. This is done so the kernel can load balance freeing from all the various caches on the system.

The rub is that the Solaris APIs which are used by the kmem slab don't take a scan count. They assume that once called the entire cache will be scanned and all eligible objects freed. That's obviously is going to take a little longer for a large cache. Prior to this patch the reclaim was done in the arc_reclaim thread so it was probably harder to observe this issue, now any process may encounter it as part of direct reclaim. Hence the lag. This isn't a big deal for a server but I can see it being more annoying on a desktop system.

The fix is going to have to be to update the shrinkers to only do partial scans rather than the Solaris style full scans. But that change should probably be done in a separate patch.

@behlendorf
Copy link
Contributor Author

Oh, and we really do need to keep the shrinker at least until we can completely map the ARC in to the Linux page cache. I've planned that work for 0.7.0 since it should solve most/all of our memory related problems. But it's a big change and will be destabilizing.

@pyavdr
Copy link
Contributor

pyavdr commented Apr 19, 2012

@behlendorf

While testing performance this patch (525c13f ) introduces a performance regression of about 10 % versus the plain rc8 code. My test case (opensuse 12.1 kernel 3.1.9 SMP 0.6.59.rc8 in vmware, 2 * RAIDZ1 with each 4 vdevs striped and 12 GB RAM ) is creating 100.000 randomly filled files with a total size of 95 GB and deleting them afterwards.

With rc8 it takes: 29 min , applying this patch to rc8 it takes: 33 min.

@ryao
Copy link
Contributor

ryao commented Apr 19, 2012

@pyavdr I imagine that the slow down is due to memory pressure. Try setting zfs_arc_max to 2GB and repeating your tests.

@pyavdr
Copy link
Contributor

pyavdr commented Apr 19, 2012

Playing around with zfs_arc_max (first: standard, then 2 GB, then 10 GB) and total system memory ( first 12 GB, then 16 GB) : the system ist not under memory pressure, there is about 1-2 GB always free. The difference between rc8 and rc8 with that patch remains. But Brian wrote, that he wants to go on with the total integration into standard linux memory handling. So at this time, those performance numbers are of no relevance, much more will come, but it remains strange. I expected the reverse situation.

Besides that: zfs rollback for a 100 GB case is really slow, and deleting 100.000 files too. In both cases the 8 cpu´s are idleing at 1-3% and zpool iostat reports about 100 iops/s, while on write there are 2200 iops/s.

@behlendorf
Copy link
Contributor Author

Thanks for the performance feedback. I'd also expect the slow down to be caused by more direct reclaim occurring in your test case rather than this being done asynchronously. Anyway, this is just a few step towards better Linux integration so for now it seems like the price we need to pay.

@behlendorf
Copy link
Contributor Author

Merged as commit 302f753

@behlendorf behlendorf closed this Apr 30, 2012
pcd1193182 pushed a commit to pcd1193182/zfs that referenced this pull request Sep 26, 2023
…aster

Merge remote-tracking branch '6.0/stage' into 'master'
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants