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

Assertion failure in Debug mode while trying to write to a zvol with mkswap #978

Closed
pyavdr opened this issue Sep 20, 2012 · 11 comments
Closed
Milestone

Comments

@pyavdr
Copy link
Contributor

pyavdr commented Sep 20, 2012

With Ubuntu 12.04 ( kernel 3.2) latest patches and SPL/ZFS latest github i can't format a zvol with
mkswap, in messages appear the following ASSERTION Failure. mkswap hangs, needed to reset.
The same Assertion failure can be seen while using zvol as swapspace on the same configuration.
I set #define PF_NOFS 0x00080000 in kmem.h as suggested.

[ 68.138204] SPL: Loaded module v0.6.0-rc11 (DEBUG mode)
[ 68.158312] zunicode: module license 'CDDL' taints kernel.
[ 68.158314] Disabling lock debugging due to kernel taint
[ 68.296506] ZFS: Loaded module v0.6.0-rc11 (DEBUG mode), ZFS pool version 28, ZFS filesystem version 5
[ 68.506516] SPL: using hostid 0xffffffff
[ 68.761104] zd0: unknown partition table
[ 96.599895] zd0: unknown partition table
[ 167.347091] SPLError: 2136:0:(zvol.c:548:zvol_write()) ASSERTION(!(current->flags & PF_NOFS)) failed
[ 167.347100] SPLError: 2136:0:(zvol.c:548:zvol_write()) SPL PANIC
[ 167.347104] SPL: Showing stack for process 2136
[ 167.347109] Pid: 2136, comm: zvol/15 Tainted: P O 3.2.0-30-generic #48-Ubuntu
[ 167.347112] Call Trace:
[ 167.347132] [] spl_debug_dumpstack+0x27/0x40 [spl]
[ 167.347141] [] spl_debug_bug+0x82/0xe0 [spl]
[ 167.347200] [] zvol_write+0x49c/0x4b0 [zfs]
[ 167.347210] [] ? default_spin_lock_flags+0x9/0x10
[ 167.347222] [] taskq_thread+0x266/0x840 [spl]
[ 167.347229] [] ? finish_task_switch+0x4a/0xf0
[ 167.347237] [] ? try_to_wake_up+0x200/0x200
[ 167.347248] [] ? __taskq_create+0x6e0/0x6e0 [spl]
[ 167.347254] [] kthread+0x8c/0xa0
[ 167.347263] [] kernel_thread_helper+0x4/0x10
[ 167.347268] [] ? flush_kthread_worker+0xa0/0xa0
[ 167.347273] [] ? gs_change+0x13/0x13
[ 167.347672] SPL: Dumping log to /tmp/spl-log.1348134249.2136
[ 368.026212] INFO: task zvol/15:2136 blocked for more than 120 seconds.
[ 368.026217] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 368.026221] zvol/15 D ffffffff81806200 0 2136 2 0x00000000
[ 368.026229] ffff880036781d30 0000000000000046 0000000000000000 0000000000001000
[ 368.026237] ffff880036781fd8 ffff880036781fd8 ffff880036781fd8 00000000000137c0
[ 368.026242] ffff880137c01700 ffff88003677ae00 ffffffff00000001 0000000000000000
[ 368.026249] Call Trace:
[ 368.026263] [] schedule+0x3f/0x60
[ 368.026279] [] spl_debug_bug+0xbd/0xe0 [spl]
[ 368.026339] [] zvol_write+0x49c/0x4b0 [zfs]
[ 368.026348] [] ? default_spin_lock_flags+0x9/0x10
[ 368.026360] [] taskq_thread+0x266/0x840 [spl]
[ 368.026367] [] ? finish_task_switch+0x4a/0xf0
[ 368.026374] [] ? try_to_wake_up+0x200/0x200
[ 368.026385] [] ? __taskq_create+0x6e0/0x6e0 [spl]
[ 368.026391] [] kthread+0x8c/0xa0
[ 368.026398] [] kernel_thread_helper+0x4/0x10
[ 368.026403] [] ? flush_kthread_worker+0xa0/0xa0
[ 368.026409] [] ? gs_change+0x13/0x13
[ 368.026426] INFO: task mkswap:2474 blocked for more than 120 seconds.
[ 368.026429] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 368.026432] mkswap D 0000000000000000 0 2474 2417 0x00000000
[ 368.026438] ffff880100ef7d18 0000000000000086 ffff8800b9ba0000 ffff8800b9ba0000
[ 368.026444] ffff880100ef7fd8 ffff880100ef7fd8 ffff880100ef7fd8 00000000000137c0
[ 368.026449] ffff8801383c0000 ffff88010a4f8000 ffff880100ef7cf8 ffff88013ae14080
[ 368.026455] Call Trace:
[ 368.026463] [] ? __lock_page+0x70/0x70
[ 368.026470] [] schedule+0x3f/0x60
[ 368.026475] [] io_schedule+0x8f/0xd0
[ 368.026480] [] sleep_on_page+0xe/0x20
[ 368.026486] [] __wait_on_bit+0x5f/0x90
[ 368.026492] [] wait_on_page_bit+0x78/0x80
[ 368.026497] [] ? autoremove_wake_function+0x40/0x40
[ 368.026503] [] filemap_fdatawait_range+0x10c/0x1a0
[ 368.026510] [] ? do_writepages+0x21/0x40
[ 368.026517] [] filemap_write_and_wait_range+0x68/0x80
[ 368.026524] [] blkdev_fsync+0x24/0x50
[ 368.026531] [] do_fsync+0x56/0x80
[ 368.026536] [] sys_fsync+0x10/0x20
[ 368.026541] [] system_call_fastpath+0x16/0x1b

@dajhorn
Copy link
Contributor

dajhorn commented Sep 20, 2012

This trace has the HW_INVALID_HOSTID sentinel in it, which indicates that the host lacks some important system components or has broken packaging. An undefined hostid can cause subtle problems.

@pyavdr
Copy link
Contributor Author

pyavdr commented Sep 20, 2012

The purpose of these installation (vmware guest) is only for searching those critical KM_SLEEP calls which leads to deadlocks in the memory management. This is a test case only, debug mode enabled and kmem.h edited. I found no way to insert a edited kmem.h and switch on the debug mode for zfs/spl in the regular installation routines. So i compiled it manually ( autogen, configure, make and make install ) tested and catched it short in advance of a total deadlock while writing to the zvol. Im happy to find this occurence, maybe it helps to find the reason for the remaining deadlocks, while using zvols as swapdevices.
Without debug mode, the assertion doesn´t trigger and everything runs smooth until the deadlock without any messages.

The reason why the hostid is set to 0xfffffff is maybe indeed a crude installation method of the system ( there where some missing and broken packages indeed, but i dont care) otherwise i cant imagine how this happens and i hope this doesn´t influence the Assertion failure.

@behlendorf
Copy link
Contributor

Can you rerun the test with debugging enabled but drop the kmem.h patch. This shouldn't be needed with Ubuntus 's default kernel. In fact it might not be safe I'd need to verify with the exact source.

@behlendorf
Copy link
Contributor

@pyavdr The assertion was almost certainly caused by the change to kmem.h which is right for SLES but not for Ubuntu. If you rerun without you shouldn't see this assert.

@pyavdr
Copy link
Contributor Author

pyavdr commented Sep 20, 2012

Ok, i reverted kmem.h to the original version. Compiled and rebooted. Running mkswap to the zvol gives the same assertion. Additional i added the last 100 lines of /tmp/spl xxxx.log.

SPL: Loaded module v0.6.0-rc11 (DEBUG mode)
[ 58.821624] zunicode: module license 'CDDL' taints kernel.
[ 58.821627] Disabling lock debugging due to kernel taint
[ 59.068372] SPL: using hostid 0xffffffff
[ 59.189394] zd0: unknown partition table
[ 59.193998] ZFS: Loaded module v0.6.0-rc11 (DEBUG mode), ZFS pool version 28, ZFS filesystem version 5
[ 92.094310] SPLError: 2331:0:(zvol.c:548:zvol_write()) ASSERTION(!(current->flags & PF_NOFS)) failed
[ 92.094319] SPLError: 2331:0:(zvol.c:548:zvol_write()) SPL PANIC
[ 92.094322] SPL: Showing stack for process 2331
[ 92.094327] Pid: 2331, comm: zvol/24 Tainted: P O 3.2.0-30-generic #48-Ubuntu
[ 92.094331] Call Trace:
[ 92.094349] [] spl_debug_dumpstack+0x27/0x40 [spl]
[ 92.094359] [] spl_debug_bug+0x82/0xe0 [spl]
[ 92.094417] [] zvol_write+0x49c/0x4b0 [zfs]
[ 92.094426] [] ? default_spin_lock_flags+0x9/0x10
[ 92.094437] [] taskq_thread+0x266/0x840 [spl]
[ 92.094443] [] ? finish_task_switch+0x4a/0xf0
[ 92.094450] [] ? try_to_wake_up+0x200/0x200
[ 92.094460] [] ? __taskq_create+0x6e0/0x6e0 [spl]
[ 92.094466] [] kthread+0x8c/0xa0
[ 92.094473] [] kernel_thread_helper+0x4/0x10
[ 92.094478] [] ? flush_kthread_worker+0xa0/0xa0
[ 92.094483] [] ? gs_change+0x13/0x13
[ 92.094525] SPL: Dumping log to /tmp/spl-log.1348159093.2331
[ 239.869828] INFO: task zvol/24:2331 blocked for more than 120 seconds.
[ 239.869831] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 239.869832] zvol/24 D ffffffff81806200 0 2331 2 0x00000000
[ 239.869836] ffff8801011d9d30 0000000000000046 0000000000000000 0000000000001000
[ 239.869839] ffff8801011d9fd8 ffff8801011d9fd8 ffff8801011d9fd8 00000000000137c0
[ 239.869841] ffffffff81c0d020 ffff88010110c500 ffffffff00000001 0000000000000000
[ 239.869844] Call Trace:
[ 239.869851] [] schedule+0x3f/0x60
[ 239.869859] [] spl_debug_bug+0xbd/0xe0 [spl]
[ 239.869900] [] zvol_write+0x49c/0x4b0 [zfs]
[ 239.869904] [] ? default_spin_lock_flags+0x9/0x10
[ 239.869909] [] taskq_thread+0x266/0x840 [spl]
[ 239.869912] [] ? finish_task_switch+0x4a/0xf0
[ 239.869915] [] ? try_to_wake_up+0x200/0x200
[ 239.869919] [] ? __taskq_create+0x6e0/0x6e0 [spl]
[ 239.869922] [] kthread+0x8c/0xa0
[ 239.869926] [] kernel_thread_helper+0x4/0x10
[ 239.869928] [] ? flush_kthread_worker+0xa0/0xa0
[ 239.869930] [] ? gs_change+0x13/0x13
[ 239.869938] INFO: task mkswap:2507 blocked for more than 120 seconds.
[ 239.869939] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 239.869940] mkswap D 0000000000000000 0 2507 2451 0x00000000
[ 239.869942] ffff8800bace9d18 0000000000000082 ffff880131510758 ffff880131510758
[ 239.869944] ffff8800bace9fd8 ffff8800bace9fd8 ffff8800bace9fd8 00000000000137c0
[ 239.869946] ffff880138364500 ffff8801011e5c00 ffff8800bace9cf8 ffff88013ae14080
[ 239.869948] Call Trace:
[ 239.869952] [] ? __lock_page+0x70/0x70
[ 239.869955] [] schedule+0x3f/0x60
[ 239.869957] [] io_schedule+0x8f/0xd0
[ 239.869959] [] sleep_on_page+0xe/0x20
[ 239.869961] [] __wait_on_bit+0x5f/0x90
[ 239.869963] [] wait_on_page_bit+0x78/0x80
[ 239.869966] [] ? autoremove_wake_function+0x40/0x40
[ 239.869968] [] filemap_fdatawait_range+0x10c/0x1a0
[ 239.869971] [] ? do_writepages+0x21/0x40
[ 239.869973] [] filemap_write_and_wait_range+0x68/0x80
[ 239.869977] [] blkdev_fsync+0x24/0x50
[ 239.869980] [] do_fsync+0x56/0x80
[ 239.869982] [] sys_fsync+0x10/0x20
[ 239.869984] [] system_call_fastpath+0x16/0x1b
[ 359.504020] INFO: task zvol/24:2331 blocked for more than 120 seconds.
[ 359.504025] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 359.504028] zvol/24 D ffffffff81806200 0 2331 2 0x00000000
[ 359.504035] ffff8801011d9d30 0000000000000046 0000000000000000 0000000000001000
[ 359.504041] ffff8801011d9fd8 ffff8801011d9fd8 ffff8801011d9fd8 00000000000137c0
[ 359.504046] ffffffff81c0d020 ffff88010110c500 ffffffff00000001 0000000000000000
[ 359.504050] Call Trace:
[ 359.504064] [] schedule+0x3f/0x60
[ 359.504078] [] spl_debug_bug+0xbd/0xe0 [spl]
[ 359.504129] [] zvol_write+0x49c/0x4b0 [zfs]
[ 359.504135] [] ? default_spin_lock_flags+0x9/0x10
[ 359.504146] [] taskq_thread+0x266/0x840 [spl]
[ 359.504151] [] ? finish_task_switch+0x4a/0xf0
[ 359.504156] [] ? try_to_wake_up+0x200/0x200
[ 359.504165] [] ? __taskq_create+0x6e0/0x6e0 [spl]
[ 359.504170] [] kthread+0x8c/0xa0
[ 359.504177] [] kernel_thread_helper+0x4/0x10
[ 359.504181] [] ? flush_kthread_worker+0xa0/0xa0
[ 359.504185] [] ? gs_change+0x13/0x13
[ 359.504198] INFO: task mkswap:2507 blocked for more than 120 seconds.
[ 359.504200] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 359.504202] mkswap D 0000000000000000 0 2507 2451 0x00000000
[ 359.504207] ffff8800bace9d18 0000000000000082 ffff880131510758 ffff880131510758
[ 359.504211] ffff8800bace9fd8 ffff8800bace9fd8 ffff8800bace9fd8 00000000000137c0
[ 359.504216] ffff880138364500 ffff8801011e5c00 ffff8800bace9cf8 ffff88013ae14080
[ 359.504220] Call Trace:
[ 359.504227] [] ? __lock_page+0x70/0x70
[ 359.504232] [] schedule+0x3f/0x60
[ 359.504236] [] io_schedule+0x8f/0xd0
[ 359.504241] [] sleep_on_page+0xe/0x20
[ 359.504245] [] __wait_on_bit+0x5f/0x90
[ 359.504250] [] wait_on_page_bit+0x78/0x80
[ 359.504255] [] ? autoremove_wake_function+0x40/0x40
[ 359.504259] [] filemap_fdatawait_range+0x10c/0x1a0
[ 359.504265] [] ? do_writepages+0x21/0x40
[ 359.504270] [] filemap_write_and_wait_range+0x68/0x80
[ 359.504276] [] blkdev_fsync+0x24/0x50
[ 359.504282] [] do_fsync+0x56/0x80
[ 359.504286] [] sys_fsync+0x10/0x20
[ 359.504290] [] system_call_fastpath+0x16/0x1b
[ 479.138041] INFO: task zvol/24:2331 blocked for more than 120 seconds.
[ 479.138044] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 479.138046] zvol/24 D ffffffff81806200 0 2331 2 0x00000000
[ 479.138051] ffff8801011d9d30 0000000000000046 0000000000000000 0000000000001000
[ 479.138055] ffff8801011d9fd8 ffff8801011d9fd8 ffff8801011d9fd8 00000000000137c0
[ 479.138058] ffffffff81c0d020 ffff88010110c500 ffffffff00000001 0000000000000000
[ 479.138061] Call Trace:
[ 479.138070] [] schedule+0x3f/0x60
[ 479.138080] [] spl_debug_bug+0xbd/0xe0 [spl]
[ 479.138116] [] zvol_write+0x49c/0x4b0 [zfs]
[ 479.138121] [] ? default_spin_lock_flags+0x9/0x10
[ 479.138127] [] taskq_thread+0x266/0x840 [spl]
[ 479.138130] [] ? finish_task_switch+0x4a/0xf0
[ 479.138134] [] ? try_to_wake_up+0x200/0x200
[ 479.138140] [] ? __taskq_create+0x6e0/0x6e0 [spl]
[ 479.138143] [] kthread+0x8c/0xa0
[ 479.138147] [] kernel_thread_helper+0x4/0x10
[ 479.138150] [] ? flush_kthread_worker+0xa0/0xa0
[ 479.138152] [] ? gs_change+0x13/0x13
[ 479.138162] INFO: task mkswap:2507 blocked for more than 120 seconds.
[ 479.138163] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 479.138165] mkswap D 0000000000000000 0 2507 2451 0x00000000
[ 479.138167] ffff8800bace9d18 0000000000000082 ffff880131510758 ffff880131510758
[ 479.138170] ffff8800bace9fd8 ffff8800bace9fd8 ffff8800bace9fd8 00000000000137c0
[ 479.138173] ffff880138364500 ffff8801011e5c00 ffff8800bace9cf8 ffff88013ae14080
[ 479.138176] Call Trace:
[ 479.138181] [] ? __lock_page+0x70/0x70
[ 479.138185] [] schedule+0x3f/0x60
[ 479.138187] [] io_schedule+0x8f/0xd0
[ 479.138190] [] sleep_on_page+0xe/0x20
[ 479.138193] [] __wait_on_bit+0x5f/0x90
[ 479.138196] [] wait_on_page_bit+0x78/0x80
[ 479.138199] [] ? autoremove_wake_function+0x40/0x40
[ 479.138202] [] filemap_fdatawait_range+0x10c/0x1a0
[ 479.138206] [] ? do_writepages+0x21/0x40
[ 479.138209] [] filemap_write_and_wait_range+0x68/0x80
[ 479.138213] [] blkdev_fsync+0x24/0x50
[ 479.138217] [] do_fsync+0x56/0x80
[ 479.138220] [] sys_fsync+0x10/0x20
[ 479.138223] [] system_call_fastpath+0x16/0x1b

root@u-test:/tmp# tail -100 spl*
p�YF[P��� �dnode.cdnode_clear_rangeds=mos obj=32 blkid=0 nblks=1 txg=204
]�YF[P��� �dnode.cdnode_setdirtyds=mos obj=32 txg=204
i�YF[P��� �dbuf.cdbuf_dirtyds=mos obj=mdn lvl=0 blkid=1 size=4000
q�YF[P��� �dnode.cdnode_clear_rangeds=mos obj=mdn blkid=1 nblks=1 txg=204
�YF[P��� �space_map.cspace_map_syncobject 32, txg 204, pass 2, F, count 3, space 600
g�YF[P��� �dbuf.cdbuf_dirtyds=mos obj=32 lvl=0 blkid=-1 size=40
�YF[P��� �space_map.cspace_map_syncobject 33, txg 204, pass 2, A, count 1, space 600
h�YF[P��� �dbuf.cdbuf_dirtyds=mos obj=33 lvl=0 blkid=0 size=1000
p�YF[P��� �dnode.cdnode_clear_rangeds=mos obj=33 blkid=0 nblks=1 txg=204
]�YF[P��� �dnode.cdnode_setdirtyds=mos obj=33 txg=204
�YF[P��� �space_map.cspace_map_syncobject 33, txg 204, pass 2, F, count 1, space 600
g�YF[P��� �dbuf.cdbuf_dirtyds=mos obj=33 lvl=0 blkid=-1 size=40
g�YF[P�� �dbuf.cdbuf_dirtyds=mos obj=2 lvl=0 blkid=-1 size=140
\�YF[P�� �dnode.cdnode_setdirtyds=mos obj=2 txg=204
c�YF[P�� Vdsl_dir.cdsl_dir_syncdd=stor1 txg=204 towrite=0K
g�YF[P�� �dbuf.cdbuf_dirtyds=mos obj=5 lvl=0 blkid=-1 size=140
\�YF[P�� �dnode.cdnode_setdirtyds=mos obj=5 txg=204
h�YF[P�� Vdsl_dir.cdsl_dir_syncdd=stor1/$MOS txg=204 towrite=0K
\�YF[P� Mdmu_objset.cdmu_objset_syncds=mos txg=204
c�YF[P&�� M dbuf.cdbuf_sync_leafds=mos obj=mdn lvl=0 blkid=0 blkptr=ffffc90013eb0440 DVA[0]=<0:11e00:c00> DVA[1]=<0:f000e000:c00> DVA[2]=<0:1e0006000:c00> [L0 DMU dnode] fletcher4 lzjb LE contiguous unique triple size=4000L/c00P birth=204L/204P fill=31 cksum=b2b17e3237:137279d6a8f2b:13b75997ec18ad8:ebd9e67034e7fc28
a�YF[P1�� M dbuf.cdbuf_sync_leafds=mos obj=mdn lvl=0 blkid=1 blkptr=ffffc90013eb04c0 DVA[0]=<0:12a00:a00> DVA[1]=<0:f000ec00:a00> DVA[2]=<0:1e0006c00:a00> [L0 DMU dnode] fletcher4 lzjb LE contiguous unique triple size=4000L/a00P birth=204L/204P fill=22 cksum=9c65e60c68:d71e80d35d97:ae90ae9f4b53ff:6a00422ed15ad024
�YF[P<�� M dbuf.cdbuf_sync_leafds=mos obj=31 lvl=0 blkid=0 blkptr=ffffc90013f5ce40 DVA[0]=<0:13600:200> DVA[1]=<0:f000f800:200> DVA[2]=<0:1e0007800:200> [L0 SPA space map] fletcher4 lzjb LE contiguous unique triple size=1000L/200P birth=204L/204P fill=1 cksum=14fc9e53e0:7bc5bc97d3c:1752c119b6bcc:2fe8a66efe965d
��YF[PC�� M dbuf.cdbuf_sync_leafds=mos obj=31 lvl=0 blkid=-1 blkptr= (null)
�YF[PK�� M dbuf.cdbuf_sync_leafds=mos obj=32 lvl=0 blkid=0 blkptr=ffffc90013f4a040 DVA[0]=<0:13800:200> DVA[1]=<0:f000fa00:200> DVA[2]=<0:1e0007a00:200> [L0 SPA space map] fletcher4 lzjb LE contiguous unique triple size=1000L/200P birth=204L/204P fill=1 cksum=167781464e:7b7bf2d2f6a:15dafe0cb873f:2a8295d16d1d26
��YF[PO�� M dbuf.cdbuf_sync_leafds=mos obj=32 lvl=0 blkid=-1 blkptr= (null)
�YF[PW�� M dbuf.cdbuf_sync_leafds=mos obj=33 lvl=0 blkid=0 blkptr=ffffc90013f4a240 DVA[0]=<0:13a00:200> DVA[1]=<0:f000fc00:200> DVA[2]=<0:1e0007c00:200> [L0 SPA space map] fletcher4 lzjb LE contiguous unique triple size=1000L/200P birth=204L/204P fill=1 cksum=16dcde2960:7c8635b4619:15e3157d93961:2a5e823f7d3b74
��YF[P[�� M dbuf.cdbuf_sync_leafds=mos obj=33 lvl=0 blkid=-1 blkptr= (null)
��YF[P^�� M dbuf.cdbuf_sync_leafds=mos obj=2 lvl=0 blkid=-1 blkptr= (null)
��YF[Pa�� M dbuf.cdbuf_sync_leafds=mos obj=5 lvl=0 blkid=-1 blkptr= (null)
��YF[P}�
�dnode.cdnode_diduse_spaceds=mos obj=31 dn=ffff8800bad5c9c0 dnp=ffffc90013f5ce00 used=1536 delta=0
��YF[P|�
�dnode.cdnode_diduse_spaceds=mos obj=32 dn=ffff8800bad5ce58 dnp=ffffc90013f4a000 used=1536 delta=0
��YF[PT�
�dnode.cdnode_diduse_spaceds=mos obj=33 dn=ffff8800bad5d2f0 dnp=ffffc90013f4a200 used=1536 delta=0
��YF[P��_ �dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff8800bad62068 dnp=ffffc90013eb0400 used=16896 delta=0
��YF[P�_ �dnode.cdnode_diduse_spaceds=mos obj=mdn dn=ffff8800bad62068 dnp=ffffc90013eb0400 used=16896 delta=0
B�YF[P�� �dsl_pool.cdsl_pool_syncmeta objset rootbp is DVA[0]=<0:13400:200> DVA[1]=<0:f000f600:200> DVA[2]=<0:1e0007600:200> [L0 DMU objset] fletcher4 lzjb LE contiguous unique triple size=800L/200P birth=204L/204P fill=53 cksum=12f84ce1c1:6e0473df68c:1497473dd9750:2a67434567c05e
X�YF[P+
� �dsl_dir.cdsl_dir_closedd=stor1/zswap
R�YF[P/
� �dsl_dir.cdsl_dir_closedd=stor1
}�YF[P�
� �txg.ctxg_sync_threadwaiting; tx_synced=204 waiting=203 dp=ffff8801350d2800
n�^F[P��� �txg.ctxg_quiesce_threadtxg=205 quiesce_txg=206 sync_txg=203
k�^F[P��� �txg.ctxg_quiesce_threadquiesce done, handing off txg 205
k�^F[P��� �txg.ctxg_sync_threadtxg=205 quiesce_txg=206 sync_txg=203
}�^F[P��� �txg.ctxg_sync_threadwaiting; tx_synced=205 waiting=203 dp=ffff8801350d2800
n�cF[P��� �txg.ctxg_quiesce_threadtxg=206 quiesce_txg=207 sync_txg=203
k�cF[P��� �txg.ctxg_quiesce_threadquiesce done, handing off txg 206
k�cF[P��� �txg.ctxg_sync_threadtxg=206 quiesce_txg=207 sync_txg=203
}�cF[Pd�� �txg.ctxg_sync_threadwaiting; tx_synced=206 waiting=203 dp=ffff8801350d2800
n�hF[PR�� �txg.ctxg_quiesce_threadtxg=207 quiesce_txg=208 sync_txg=203
k�hF[Pb�� �txg.ctxg_quiesce_threadquiesce done, handing off txg 207
k�hF[Pf�� �txg.ctxg_sync_threadtxg=207 quiesce_txg=208 sync_txg=203
}�hF[P��� �txg.ctxg_sync_threadwaiting; tx_synced=207 waiting=203 dp=ffff8801350d2800
n�mF[P��� �txg.ctxg_quiesce_threadtxg=208 quiesce_txg=209 sync_txg=203
k�mF[P��� �txg.ctxg_quiesce_threadquiesce done, handing off txg 208
k�mF[P��� �txg.ctxg_sync_threadtxg=208 quiesce_txg=209 sync_txg=203
}�mF[Pe�� �txg.ctxg_sync_threadwaiting; tx_synced=208 waiting=203 dp=ffff8801350d2800
n�rF[P��� �txg.ctxg_quiesce_threadtxg=209 quiesce_txg=210 sync_txg=203
k�rF[P��� �txg.ctxg_quiesce_threadquiesce done, handing off txg 209
k�rF[P��� �txg.ctxg_sync_threadtxg=209 quiesce_txg=210 sync_txg=203
}�rF[P.�� �txg.ctxg_sync_threadwaiting; tx_synced=209 waiting=203 dp=ffff8801350d2800
W�uF[P�� :dsl_dir.cdsl_dir_open_spastor1/zswap
d�uF[P@�� dsl_dir.cdsl_dir_open_spalooking up zswap in obj4 R�uF[Pe�� �dsl_dir.cdsl_dir_closedd=stor1 X�uF[P��� �dsl_dir.cdsl_dir_closedd=stor1/zswap #�uF[P��� dmu_objset.cdmu_objset_open_implreading DVA[0]=<0:11c00:200> DVA[1]=<0:f000de00:200> [L0 DMU objset] fletcher4 lzjb LE contiguous unique double size=800L/200P birth=204L/204P fill=2 cksum=119b76da64:6b427763e10:150664973a47d:2d393ce3ce5725 |�uF[Pt�� �dbuf.cdbuf_createds=stor1/zswap obj=mdn lvl=6 blkid=0 db=ffff8800bbb581e8 |�uF[Ph�� �dbuf.cdbuf_createds=stor1/zswap obj=mdn lvl=5 blkid=0 db=ffff8800bbb58040 |�uF[P��� �dbuf.cdbuf_createds=stor1/zswap obj=mdn lvl=4 blkid=0 db=ffff8800bac03e10 |�uF[Pc�� �dbuf.cdbuf_createds=stor1/zswap obj=mdn lvl=3 blkid=0 db=ffff8800bac03c68 |�uF[P��� �dbuf.cdbuf_createds=stor1/zswap obj=mdn lvl=2 blkid=0 db=ffff8800bac03ac0 |�uF[PS�� �dbuf.cdbuf_createds=stor1/zswap obj=mdn lvl=1 blkid=0 db=ffff8800bac03918 |�uF[P��� �dbuf.cdbuf_createds=stor1/zswap obj=mdn lvl=0 blkid=0 db=ffff8800bac03770 z�uF[P��� �dbuf.cdbuf_createds=stor1/zswap obj=2 lvl=0 blkid=0 db=ffff8800bac035c8 W�uF[P#�� :dsl_dir.cdsl_dir_open_spastor1/zswap d�uF[P.��dsl_dir.cdsl_dir_open_spalooking up zswap in obj4
R�uF[P=�� �dsl_dir.cdsl_dir_closedd=stor1
X�uF[PD�� �dsl_dir.cdsl_dir_closedd=stor1/zswap
X�uF[P��� �dsl_dir.cdsl_dir_closedd=stor1/zswap
R�uF[P��� �dsl_dir.cdsl_dir_closedd=stor1
W�uF[P
�� :dsl_dir.cdsl_dir_open_spastor1/zswap
d�uF[P�� dsl_dir.cdsl_dir_open_spalooking up zswap in obj4 R�uF[P*�� �dsl_dir.cdsl_dir_closedd=stor1 X�uF[Pd�� �dsl_dir.cdsl_dir_closedd=stor1/zswap #�uF[Po�� dmu_objset.cdmu_objset_open_implreading DVA[0]=<0:11c00:200> DVA[1]=<0:f000de00:200> [L0 DMU objset] fletcher4 lzjb LE contiguous unique double size=800L/200P birth=204L/204P fill=2 cksum=119b76da64:6b427763e10:150664973a47d:2d393ce3ce5725 |�uF[P��� �dbuf.cdbuf_createds=stor1/zswap obj=mdn lvl=6 blkid=0 db=ffff8800bbb581e8 |�uF[P��� �dbuf.cdbuf_createds=stor1/zswap obj=mdn lvl=5 blkid=0 db=ffff8800bbb58040 |�uF[P|�� �dbuf.cdbuf_createds=stor1/zswap obj=mdn lvl=4 blkid=0 db=ffff8800bac03e10 |�uF[Pr�� �dbuf.cdbuf_createds=stor1/zswap obj=mdn lvl=3 blkid=0 db=ffff8800bac03c68 |�uF[PA�� �dbuf.cdbuf_createds=stor1/zswap obj=mdn lvl=2 blkid=0 db=ffff8800bac03ac0 |�uF[P*�� �dbuf.cdbuf_createds=stor1/zswap obj=mdn lvl=1 blkid=0 db=ffff8800bac03918 |�uF[P��� �dbuf.cdbuf_createds=stor1/zswap obj=mdn lvl=0 blkid=0 db=ffff8800bac03770 z�uF[P��� �dbuf.cdbuf_createds=stor1/zswap obj=2 lvl=0 blkid=0 db=ffff8800bac03420 W�uF[P��� :dsl_dir.cdsl_dir_open_spastor1/zswap d�uF[P���dsl_dir.cdsl_dir_open_spalooking up zswap in obj4
R�uF[P��� �dsl_dir.cdsl_dir_closedd=stor1
X�uF[P��� �dsl_dir.cdsl_dir_closedd=stor1/zswap
z�uF[P�▒ �dbuf.cdbuf_createds=stor1/zswap obj=1 lvl=0 blkid=0 db=ffff8800bac03278
puF[P�▒ zvol.czvol_writeASSERTION(!(current->flags & PF_NOFS)) failed
LuF[P�▒ zvol.czvol_writeSPL PANIC

@pyavdr
Copy link
Contributor Author

pyavdr commented Sep 20, 2012

I got another one:

[ 60.392770] SPL: Loaded module v0.6.0-rc11 (DEBUG mode)
[ 60.416045] zunicode: module license 'CDDL' taints kernel.
[ 60.416047] Disabling lock debugging due to kernel taint
[ 60.564737] SPL: using hostid 0xffffffff
[ 60.618448] zd0: unknown partition table
[ 60.620448] ZFS: Loaded module v0.6.0-rc11 (DEBUG mode), ZFS pool version 28, ZFS filesystem version 5
[ 76.225458] SPLError: 2492:0:(kmem.h:92:sanitize_flags()) FATAL allocation for task txg_sync (2492) which used GFP flags 0xbacbbb1c with PF_NOFS set
[ 76.225466] SPLError: 2492:0:(kmem.h:92:sanitize_flags()) SPL PANIC
[ 76.225469] SPL: Showing stack for process 2492
[ 76.225473] Pid: 2492, comm: txg_sync Tainted: P O 3.2.0-30-generic #48-Ubuntu
[ 76.225476] Call Trace:
[ 76.225493] [] spl_debug_dumpstack+0x27/0x40 [spl]
[ 76.225500] [] spl_debug_bug+0x82/0xe0 [spl]
[ 76.225511] [] sanitize_flags.part.7+0x6b/0x264 [spl]
[ 76.225520] [] kmem_alloc_debug+0x405/0x430 [spl]
[ 76.225553] [] ? dmu_buf_rele+0x41/0xa0 [zfs]
[ 76.225560] [] ? default_spin_lock_flags+0x9/0x10
[ 76.225587] [] ddt_zap_lookup+0x4b/0x190 [zfs]
[ 76.225613] [] ddt_sync+0x403/0xe80 [zfs]
[ 76.225624] [] ? cv_wait_common+0x10b/0x3a0 [spl]
[ 76.225666] [] ? zio_wait+0x215/0x440 [zfs]
[ 76.225704] [] ? bpobj_enqueue_cb+0x20/0x20 [zfs]
[ 76.225741] [] spa_sync+0x3f1/0xc80 [zfs]
[ 76.225779] [] txg_sync_thread+0x2c0/0x560 [zfs]
[ 76.225816] [] ? txg_quiesce_thread+0x4d0/0x4d0 [zfs]
[ 76.225826] [] thread_generic_wrapper+0x81/0xe0 [spl]
[ 76.225862] [] ? __thread_create+0x360/0x360 [spl]
[ 76.225870] [] kthread+0x8c/0xa0
[ 76.225877] [] kernel_thread_helper+0x4/0x10
[ 76.225881] [] ? flush_kthread_worker+0xa0/0xa0
[ 76.225886] [] ? gs_change+0x13/0x13
[ 76.225924] SPL: Dumping log to /tmp/spl-log.1348164956.2492

@pyavdr
Copy link
Contributor Author

pyavdr commented Sep 20, 2012

in fact, after a reboot and doing any zfs related command ( zfs list, zpool status, ... ) this one showed up,
maybe because the pool have a zvol defined.

[ 67.235804] SPL: Loaded module v0.6.0-rc11 (DEBUG mode)
[ 67.249937] zunicode: module license 'CDDL' taints kernel.
[ 67.249940] Disabling lock debugging due to kernel taint
[ 67.444904] SPL: using hostid 0xffffffff
[ 67.500707] SPLError: 2480:0:(kmem.h:92:sanitize_flags()) FATAL allocation for task txg_sync (2480) which used GFP flags 0xbb2abb1c with PF_NOFS set
[ 67.500711] SPLError: 2480:0:(kmem.h:92:sanitize_flags()) SPL PANIC
[ 67.500712] SPL: Showing stack for process 2480
[ 67.500714] Pid: 2480, comm: txg_sync Tainted: P O 3.2.0-30-generic #48-Ubuntu
[ 67.500715] Call Trace:
[ 67.500723] [] spl_debug_dumpstack+0x27/0x40 [spl]
[ 67.500727] [] spl_debug_bug+0x82/0xe0 [spl]
[ 67.500731] [] sanitize_flags.part.7+0x6b/0x264 [spl]
[ 67.500735] [] kmem_alloc_debug+0x405/0x430 [spl]
[ 67.500760] [] ? dmu_buf_rele+0x41/0xa0 [zfs]
[ 67.500764] [] ? default_spin_lock_flags+0x9/0x10
[ 67.500783] [] ddt_zap_lookup+0x4b/0x190 [zfs]
[ 67.500801] [] ddt_sync+0x403/0xe80 [zfs]
[ 67.500806] [] ? cv_wait_common+0x10b/0x3a0 [spl]
[ 67.500830] [] ? zio_wait+0x215/0x440 [zfs]
[ 67.500852] [] ? bpobj_enqueue_cb+0x20/0x20 [zfs]
[ 67.500874] [] spa_sync+0x3f1/0xc80 [zfs]
[ 67.500896] [] txg_sync_thread+0x2c0/0x560 [zfs]
[ 67.500917] [] ? txg_quiesce_thread+0x4d0/0x4d0 [zfs]
[ 67.500921] [] thread_generic_wrapper+0x81/0xe0 [spl]
[ 67.500924] [] ? __thread_create+0x360/0x360 [spl]
[ 67.500927] [] kthread+0x8c/0xa0
[ 67.500930] [] kernel_thread_helper+0x4/0x10
[ 67.500931] [] ? flush_kthread_worker+0xa0/0xa0
[ 67.500933] [] ? gs_change+0x13/0x13
[ 67.500951] SPL: Dumping log to /tmp/spl-log.1348165976.2480

@behlendorf
Copy link
Contributor

The second set of stack traces were fixed in master and are related to dedup. You should grab the latest source and retry.

Also, do you have dedup enabled for your zvol swap dataset? I've never tested this and I could easily seeing it causing severe slowness but no outright failures. If you should disable it and see if your results improve.

@pyavdr
Copy link
Contributor Author

pyavdr commented Sep 21, 2012

Ok, although i was sure using the latest source; i loaded it again from github, verified the changes in ddt.c. I did enable dedup, but dumped that now. Created a new pool. Compiled it with --enable-debug. Created a zvol and formated it with mkswap. It runs through, no messages. But using this zvol as swap space, while stressing the system with pythons, leads immediately to a deadlock once the system starts using the swap space. No messages in syslog. So the situation is pretty the same as with Opensuse.

@behlendorf
Copy link
Contributor

Interesting, it sounds like there are still some gremlins here. I was able to run a python test case with RHEL6.2 and I know @ryao has been using it successfully with Gentoo. But clearly there's still work to be done here.

If your game to keep experimenting you might try two more things:

  • Set your zvol blocksize to 4k to match your page size. Without this you may incur problems because an 8k block (zvol default) will need to be read from disk before a 4k memory page and be written out. This might manifest itself as a hung system which is in fact working, but just making progress very slowly.
  • Be patient. After you think it's locked up let it sit for an hour and see if it's able to recover.

@pyavdr
Copy link
Contributor Author

pyavdr commented Sep 22, 2012

@behlendorf
I have great news. You are right. After setting the bs to 4k as suggested and waiting for about 20 mins, the systems (ubuntu 12.04 and opensuse 12.1) wake up again. Lots of stack traces in messages about hung tasks for more then 120 sec, but nothing special for zfs. So i got 2 systems swapping on a zvol, using about 7 GB of the zvol as swapspace. It takes nearly forever to recover with 16 GB RAM and 50 GB zvol swap, much faster when it uses only 4GB RAM and 10 GB zvol swap, so the RAM size is mainly the problem when starting to use zvolswap.

Is there anything we can do to make this more smooth? To have a hanging system for several minutes isn´t the optimal situation, when it comes to real boxes ... it will take very long time ( more then 60 mins) to recover with more then 16GB RAM.

It looks like, that the bs of 4k is mandatory, if yes, there should be a hint to use zvol swap only with this 4k bs.

It think we can close this issue, but keeping in mind, that using zvolswap is only ok for very small RAM sizes.

@pyavdr pyavdr closed this as completed Sep 22, 2012
pcd1193182 pushed a commit to pcd1193182/zfs that referenced this issue Sep 26, 2023
Bumps [tokio](https://github.com/tokio-rs/tokio) from 1.28.2 to 1.29.1.
- [Release notes](https://github.com/tokio-rs/tokio/releases)
- [Commits](tokio-rs/tokio@tokio-1.28.2...tokio-1.29.1)

---
updated-dependencies:
- dependency-name: tokio
  dependency-type: direct:production
  update-type: version-update:semver-minor
...

Signed-off-by: dependabot[bot] <support@github.com>
Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com>
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

No branches or pull requests

3 participants