Hi, I''ve been following these forums for a long time but this is my first post. I''m looking for some advice on debugging an issue. I''ve been looking at all the bug reports and updates though b146 but I can''t find a good match. I tried the fix for 6937998 but it didn''t help. Running Nexenta NCP3 and when I attempt to do a simple zfs send of my root pool (syspool) > /dev/null, it sends all the volume streams but then all IO hangs at the moment the send seems like it should be completed. I have to restart the box at this point. The following mdb output is from the hung system (from a savecore -L). I''m still learning my way around mdb and kernel debugging so any suggestions on how to track this down would be really appreciated. It seems like it''s stuck waiting for txg_wait_synced.> ::ptreeffffff02e8d97718 sshd ffffff02e74c3570 sshd ffffff02e8d95e48 tcsh ffffff02d1cc3e20 bash ffffff02e7f4a720 bash ffffff02e6bec900 zfs> ffffff02e6bec900::walk threadffffff02d1954720> ffffff02d1954720::threadlist -vADDR PROC LWP CLS PRI WCHAN ffffff02d1954720 ffffff02e6bec900 ffffff02cf543850 1 60 ffffff02cd54054a PC: _resume_from_idle+0xf1 CMD: zfs send -Rvp syspool at 20100824 stack pointer for thread ffffff02d1954720: ffffff0010b6ca90 [ ffffff0010b6ca90 _resume_from_idle+0xf1() ] swtch+0x145() cv_wait+0x61() txg_wait_synced+0x7c() dsl_sync_task_group_wait+0xee() dsl_dataset_user_release+0x101() zfs_ioc_release+0x51() zfsdev_ioctl+0x177() cdev_ioctl+0x45() spec_ioctl+0x5a() fop_ioctl+0x7b() ioctl+0x18e() sys_syscall32+0xff()> ffffff02d1954720::findstack -vstack pointer for thread ffffff02d1954720: ffffff0010b6ca90 [ ffffff0010b6ca90 _resume_from_idle+0xf1() ] ffffff0010b6cac0 swtch+0x145() ffffff0010b6caf0 cv_wait+0x61(ffffff02cd54054a, ffffff02cd540510) ffffff0010b6cb40 txg_wait_synced+0x7c(ffffff02cd540380, 9291) ffffff0010b6cb80 dsl_sync_task_group_wait+0xee(ffffff02d0b1a868) ffffff0010b6cc10 dsl_dataset_user_release+0x101(ffffff02d1336000, ffffff02d1336400, ffffff02d1336c00, 1) ffffff0010b6cc40 zfs_ioc_release+0x51(ffffff02d1336000) ffffff0010b6ccc0 zfsdev_ioctl+0x177(b600000000, 5a32, 8045660, 100003, ffffff02cd646588, ffffff0010b6cde4) ffffff0010b6cd00 cdev_ioctl+0x45(b600000000, 5a32, 8045660, 100003, ffffff02cd646588, ffffff0010b6cde4) ffffff0010b6cd40 spec_ioctl+0x5a(ffffff02d17c3180, 5a32, 8045660, 100003, ffffff02cd646588, ffffff0010b6cde4, 0) ffffff0010b6cdc0 fop_ioctl+0x7b(ffffff02d17c3180, 5a32, 8045660, 100003, ffffff02cd646588, ffffff0010b6cde4, 0) ffffff0010b6cec0 ioctl+0x18e(3, 5a32, 8045660) ffffff0010b6cf10 sys_syscall32+0xff()> ffffff02cd540380::print dsl_pool_t dp_txdp_tx = { dp_tx.tx_cpu = 0xffffff02cd540680 dp_tx.tx_sync_lock = { _opaque = [ 0 ] } dp_tx.tx_open_txg = 0x9292 dp_tx.tx_quiesced_txg = 0 dp_tx.tx_syncing_txg = 0x9291 dp_tx.tx_synced_txg = 0x9290 dp_tx.tx_sync_txg_waiting = 0x9292 dp_tx.tx_quiesce_txg_waiting = 0x9292 dp_tx.tx_sync_more_cv = { _opaque = 0 } dp_tx.tx_sync_done_cv = { _opaque = 0x2 } dp_tx.tx_quiesce_more_cv = { _opaque = 0x1 } dp_tx.tx_quiesce_done_cv = { _opaque = 0 } dp_tx.tx_timeout_cv = { _opaque = 0 } dp_tx.tx_exit_cv = { _opaque = 0 } dp_tx.tx_threads = 0x2 dp_tx.tx_exiting = 0 dp_tx.tx_sync_thread = 0xffffff000fa05c60 dp_tx.tx_quiesce_thread = 0xffffff000f9fcc60 dp_tx.tx_commit_cb_taskq = 0> ffffff02cd540380::print dsl_pool_t dp_tx.tx_sync_threaddp_tx.tx_sync_thread = 0xffffff000fa05c60> 0xffffff000fa05c60::findstack -vstack pointer for thread ffffff000fa05c60: ffffff000fa05860 [ ffffff000fa05860 _resume_from_idle+0xf1() ] ffffff000fa05890 swtch+0x145() ffffff000fa058c0 cv_wait+0x61(ffffff000fa05e3e, ffffff000fa05e40) ffffff000fa05900 delay_common+0xab(1) ffffff000fa05940 delay+0xc4(1) ffffff000fa05960 dnode_special_close+0x28(ffffff02e8aa2050) ffffff000fa05990 dmu_objset_evict+0x160(ffffff02e5b91100) ffffff000fa05a20 dsl_dataset_user_release_sync+0x52(ffffff02e000b928, ffffff02d0b1a868, ffffff02e5b9c6e0) ffffff000fa05a70 dsl_sync_task_group_sync+0xf3(ffffff02d0b1a868, ffffff02e5b9c6e0) ffffff000fa05af0 dsl_pool_sync+0x1ec(ffffff02cd540380, 9291) ffffff000fa05ba0 spa_sync+0x37b(ffffff02cdd40b00, 9291) ffffff000fa05c40 txg_sync_thread+0x247(ffffff02cd540380) ffffff000fa05c50 thread_start+8()> ::spaADDR STATE NAME ffffff02cdd40b00 ACTIVE syspool> ffffff02cdd40b00::print spa_t spa_dsl_pool->dp_tx.tx_sync_thread|::findstack -v stack pointer for thread ffffff000fa05c60: ffffff000fa05860 [ ffffff000fa05860 _resume_from_idle+0xf1() ] ffffff000fa05890 swtch+0x145() ffffff000fa058c0 cv_wait+0x61(ffffff000fa05e3e, ffffff000fa05e40) ffffff000fa05900 delay_common+0xab(1) ffffff000fa05940 delay+0xc4(1) ffffff000fa05960 dnode_special_close+0x28(ffffff02e8aa2050) ffffff000fa05990 dmu_objset_evict+0x160(ffffff02e5b91100) ffffff000fa05a20 dsl_dataset_user_release_sync+0x52(ffffff02e000b928, ffffff02d0b1a868, ffffff02e5b9c6e0) ffffff000fa05a70 dsl_sync_task_group_sync+0xf3(ffffff02d0b1a868, ffffff02e5b9c6e0) ffffff000fa05af0 dsl_pool_sync+0x1ec(ffffff02cd540380, 9291) ffffff000fa05ba0 spa_sync+0x37b(ffffff02cdd40b00, 9291) ffffff000fa05c40 txg_sync_thread+0x247(ffffff02cd540380) ffffff000fa05c50 thread_start+8() -- This message posted from opensolaris.org
What does ::zio_state show? Dave On 08/25/10 07:41, Bryan Leaman wrote:> Hi, I''ve been following these forums for a long time but this is my first post. I''m looking for some advice on debugging an issue. I''ve been looking at all the bug reports and updates though b146 but I can''t find a good match. I tried the fix for 6937998 but it didn''t help. > > Running Nexenta NCP3 and when I attempt to do a simple zfs send of my root pool (syspool) > /dev/null, it sends all the volume streams but then all IO hangs at the moment the send seems like it should be completed. I have to restart the box at this point. > > The following mdb output is from the hung system (from a savecore -L). I''m still learning my way around mdb and kernel debugging so any suggestions on how to track this down would be really appreciated. It seems like it''s stuck waiting for txg_wait_synced. > > >> ::ptree >> > ffffff02e8d97718 sshd > ffffff02e74c3570 sshd > ffffff02e8d95e48 tcsh > ffffff02d1cc3e20 bash > ffffff02e7f4a720 bash > ffffff02e6bec900 zfs > > >> ffffff02e6bec900::walk thread >> > ffffff02d1954720 > > >> ffffff02d1954720::threadlist -v >> > ADDR PROC LWP CLS PRI WCHAN > ffffff02d1954720 ffffff02e6bec900 ffffff02cf543850 1 60 ffffff02cd54054a > PC: _resume_from_idle+0xf1 CMD: zfs send -Rvp syspool at 20100824 > stack pointer for thread ffffff02d1954720: ffffff0010b6ca90 > [ ffffff0010b6ca90 _resume_from_idle+0xf1() ] > swtch+0x145() > cv_wait+0x61() > txg_wait_synced+0x7c() > dsl_sync_task_group_wait+0xee() > dsl_dataset_user_release+0x101() > zfs_ioc_release+0x51() > zfsdev_ioctl+0x177() > cdev_ioctl+0x45() > spec_ioctl+0x5a() > fop_ioctl+0x7b() > ioctl+0x18e() > sys_syscall32+0xff() > > >> ffffff02d1954720::findstack -v >> > stack pointer for thread ffffff02d1954720: ffffff0010b6ca90 > [ ffffff0010b6ca90 _resume_from_idle+0xf1() ] > ffffff0010b6cac0 swtch+0x145() > ffffff0010b6caf0 cv_wait+0x61(ffffff02cd54054a, ffffff02cd540510) > ffffff0010b6cb40 txg_wait_synced+0x7c(ffffff02cd540380, 9291) > ffffff0010b6cb80 dsl_sync_task_group_wait+0xee(ffffff02d0b1a868) > ffffff0010b6cc10 dsl_dataset_user_release+0x101(ffffff02d1336000, > ffffff02d1336400, ffffff02d1336c00, 1) > ffffff0010b6cc40 zfs_ioc_release+0x51(ffffff02d1336000) > ffffff0010b6ccc0 zfsdev_ioctl+0x177(b600000000, 5a32, 8045660, 100003, > ffffff02cd646588, ffffff0010b6cde4) > ffffff0010b6cd00 cdev_ioctl+0x45(b600000000, 5a32, 8045660, 100003, > ffffff02cd646588, ffffff0010b6cde4) > ffffff0010b6cd40 spec_ioctl+0x5a(ffffff02d17c3180, 5a32, 8045660, 100003, > ffffff02cd646588, ffffff0010b6cde4, 0) > ffffff0010b6cdc0 fop_ioctl+0x7b(ffffff02d17c3180, 5a32, 8045660, 100003, > ffffff02cd646588, ffffff0010b6cde4, 0) > ffffff0010b6cec0 ioctl+0x18e(3, 5a32, 8045660) > ffffff0010b6cf10 sys_syscall32+0xff() > > >> ffffff02cd540380::print dsl_pool_t dp_tx >> > dp_tx = { > dp_tx.tx_cpu = 0xffffff02cd540680 > dp_tx.tx_sync_lock = { > _opaque = [ 0 ] > } > dp_tx.tx_open_txg = 0x9292 > dp_tx.tx_quiesced_txg = 0 > dp_tx.tx_syncing_txg = 0x9291 > dp_tx.tx_synced_txg = 0x9290 > dp_tx.tx_sync_txg_waiting = 0x9292 > dp_tx.tx_quiesce_txg_waiting = 0x9292 > dp_tx.tx_sync_more_cv = { > _opaque = 0 > } > dp_tx.tx_sync_done_cv = { > _opaque = 0x2 > } > dp_tx.tx_quiesce_more_cv = { > _opaque = 0x1 > } > dp_tx.tx_quiesce_done_cv = { > _opaque = 0 > } > dp_tx.tx_timeout_cv = { > _opaque = 0 > } > dp_tx.tx_exit_cv = { > _opaque = 0 > } > dp_tx.tx_threads = 0x2 > dp_tx.tx_exiting = 0 > dp_tx.tx_sync_thread = 0xffffff000fa05c60 > dp_tx.tx_quiesce_thread = 0xffffff000f9fcc60 > dp_tx.tx_commit_cb_taskq = 0 > > >> ffffff02cd540380::print dsl_pool_t dp_tx.tx_sync_thread >> > dp_tx.tx_sync_thread = 0xffffff000fa05c60 > > >> 0xffffff000fa05c60::findstack -v >> > stack pointer for thread ffffff000fa05c60: ffffff000fa05860 > [ ffffff000fa05860 _resume_from_idle+0xf1() ] > ffffff000fa05890 swtch+0x145() > ffffff000fa058c0 cv_wait+0x61(ffffff000fa05e3e, ffffff000fa05e40) > ffffff000fa05900 delay_common+0xab(1) > ffffff000fa05940 delay+0xc4(1) > ffffff000fa05960 dnode_special_close+0x28(ffffff02e8aa2050) > ffffff000fa05990 dmu_objset_evict+0x160(ffffff02e5b91100) > ffffff000fa05a20 dsl_dataset_user_release_sync+0x52(ffffff02e000b928, > ffffff02d0b1a868, ffffff02e5b9c6e0) > ffffff000fa05a70 dsl_sync_task_group_sync+0xf3(ffffff02d0b1a868, > ffffff02e5b9c6e0) > ffffff000fa05af0 dsl_pool_sync+0x1ec(ffffff02cd540380, 9291) > ffffff000fa05ba0 spa_sync+0x37b(ffffff02cdd40b00, 9291) > ffffff000fa05c40 txg_sync_thread+0x247(ffffff02cd540380) > ffffff000fa05c50 thread_start+8() > > >> ::spa >> > ADDR STATE NAME > ffffff02cdd40b00 ACTIVE syspool > > >> ffffff02cdd40b00::print spa_t spa_dsl_pool->dp_tx.tx_sync_thread|::findstack - >> > v > stack pointer for thread ffffff000fa05c60: ffffff000fa05860 > [ ffffff000fa05860 _resume_from_idle+0xf1() ] > ffffff000fa05890 swtch+0x145() > ffffff000fa058c0 cv_wait+0x61(ffffff000fa05e3e, ffffff000fa05e40) > ffffff000fa05900 delay_common+0xab(1) > ffffff000fa05940 delay+0xc4(1) > ffffff000fa05960 dnode_special_close+0x28(ffffff02e8aa2050) > ffffff000fa05990 dmu_objset_evict+0x160(ffffff02e5b91100) > ffffff000fa05a20 dsl_dataset_user_release_sync+0x52(ffffff02e000b928, > ffffff02d0b1a868, ffffff02e5b9c6e0) > ffffff000fa05a70 dsl_sync_task_group_sync+0xf3(ffffff02d0b1a868, > ffffff02e5b9c6e0) > ffffff000fa05af0 dsl_pool_sync+0x1ec(ffffff02cd540380, 9291) > ffffff000fa05ba0 spa_sync+0x37b(ffffff02cdd40b00, 9291) > ffffff000fa05c40 txg_sync_thread+0x247(ffffff02cd540380) > ffffff000fa05c50 thread_start+8() >-- -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://mail.opensolaris.org/pipermail/zfs-discuss/attachments/20100825/9a612389/attachment.html>
More info:> ::zio_stateADDRESS TYPE STAGE WAITER ffffff02cf248c88 NULL OPEN - ffffff02e3dec348 NULL OPEN - ffffff02e3e6d6a0 NULL OPEN - -- This message posted from opensolaris.org
So I don''t know if I''m on the right track, but I''ve been looking at the threadlist and findstack output from above, specifically this thread which seems to be what zpool-syspool is stuck on:> 0xffffff000fa05c60::findstack -vstack pointer for thread ffffff000fa05c60: ffffff000fa05860 [ ffffff000fa05860 _resume_from_idle+0xf1() ] ffffff000fa05890 swtch+0x145() ffffff000fa058c0 cv_wait+0x61(ffffff000fa05e3e, ffffff000fa05e40) ffffff000fa05900 delay_common+0xab(1) ffffff000fa05940 delay+0xc4(1) ffffff000fa05960 dnode_special_close+0x28(ffffff02e8aa2050) ffffff000fa05990 dmu_objset_evict+0x160(ffffff02e5b91100) ffffff000fa05a20 dsl_dataset_user_release_sync+0x52(ffffff02e000b928, ffffff02d0b1a868, ffffff02e5b9c6e0) ffffff000fa05a70 dsl_sync_task_group_sync+0xf3(ffffff02d0b1a868, ffffff02e5b9c6e0) ffffff000fa05af0 dsl_pool_sync+0x1ec(ffffff02cd540380, 9291) ffffff000fa05ba0 spa_sync+0x37b(ffffff02cdd40b00, 9291) ffffff000fa05c40 txg_sync_thread+0x247(ffffff02cd540380) ffffff000fa05c50 thread_start+8() It seems to be trying to sync txg 9291. dmu_objset_evict is called with:> ffffff02e5b91100::print objset_t{ os_dsl_dataset = 0xffffff02cd748880 os_spa = 0xffffff02cdd40b00 os_phys_buf = 0xffffff02cf426a88 os_phys = 0xffffff02e570d800 os_meta_dnode = 0xffffff02e8aa2050 os_userused_dnode = 0xffffff02e8aa1758 os_groupused_dnode = 0xffffff02e8aa1478 and the ds_snapname indeed matches the name of the snapshot I was copying with zfs send when the system hung:> ffffff02cd748880::print dsl_dataset_t ds_snapnameds_snapname = [ "20100824" ] within dmu_objset_evict() it executes: /* * We should need only a single pass over the dnode list, since * nothing can be added to the list at this point. */ (void) dmu_objset_evict_dbufs(os); dnode_special_close(os->os_meta_dnode); if (os->os_userused_dnode) { dnode_special_close(os->os_userused_dnode); dnode_special_close(os->os_groupused_dnode); and in the stack, it''s calling dnode_special_close+0x28(ffffff02e8aa2050) which matches the value for os->os_meta_dnode. So I guess that means it''s stuck in dnode_special_close() handling the os_meta_dnode? Looking at the code for dnode_special_close() in dnode.c seems to explain the delay+0xc4(1) in the stack:> ffffff02e8aa2050::print dnode_t dn_holdsdn_holds = { dn_holds.rc_count = 0x20 } void dnode_special_close(dnode_t *dn) { /* * Wait for final references to the dnode to clear. This can * only happen if the arc is asyncronously evicting state that * has a hold on this dnode while we are trying to evict this * dnode. */ while (refcount_count(&dn->dn_holds) > 0) delay(1); dnode_destroy(dn); } But now I''m reaching the limit of what I''m able to debug, as my understanding of the inner workings of ZFS is very limited. Any thoughts or suggestions based on this analysis? At least I''ve learned quite a bit about mdb. :) -- This message posted from opensolaris.org
Just to update everyone...this turned out to be OpenSolaris bug 6884007 "zfs_send() can leave temporary holds around". It was fixed in b142 and I was able to apply the patch to NCP3 and the issue is resolved on my system. Apparently the system was stuck in dnode_special_close() due to some snapshot holds that were not cleaned up properly by zfs send. -- This message posted from opensolaris.org