From owner-freebsd-fs@FreeBSD.ORG Mon Oct 13 18:40:12 2014 Return-Path: Delivered-To: freebsd-fs@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [8.8.178.115]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by hub.freebsd.org (Postfix) with ESMTPS id BC8CF7D1; Mon, 13 Oct 2014 18:40:12 +0000 (UTC) Received: from mail-yh0-x22d.google.com (mail-yh0-x22d.google.com [IPv6:2607:f8b0:4002:c01::22d]) (using TLSv1 with cipher ECDHE-RSA-RC4-SHA (128/128 bits)) (Client CN "smtp.gmail.com", Issuer "Google Internet Authority G2" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id 6CDE0D6E; Mon, 13 Oct 2014 18:40:12 +0000 (UTC) Received: by mail-yh0-f45.google.com with SMTP id b6so3886715yha.32 for ; Mon, 13 Oct 2014 11:40:11 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=mime-version:sender:in-reply-to:references:date:message-id:subject :from:to:cc:content-type:content-transfer-encoding; bh=GdkDgud9ZwTDGxKB4JcbBLYVup8Tc1bc/vmglFgvaPQ=; b=v5kmjvXon+D/5MwtcYJEB9SNU1KjAZzTQYAHkNmseDvyUpcNC4FrPpEd0d2QUHbgYi LhgTBQvf30lBJVM/Un1bFKUGcr4G5yspEYIZLRH4tjVGO2WsNCpgDqjpMIG5DY/NM4nO y/J5FFk4mK6Suel9TjXHelawJyEBgE7DOF3SxIpDjbP4vsqjkD343ZMvcnCc2nB8A+pu Y87QUFc45YrOZIdM0vMFcHAM0Bn3bwkA+3P5FjBgW7QpHN5MkuXKc4uDMjl2zxfLoArX JBFgJ6cfqa2SG5WxXauBzNOi0e2lk2LNjxqlDOtWWHq8hEE+lvwCVHj+J5uKiXGBiN1e GZTQ== MIME-Version: 1.0 X-Received: by 10.236.96.197 with SMTP id r45mr536807yhf.52.1413225611417; Mon, 13 Oct 2014 11:40:11 -0700 (PDT) Sender: kmacybsd@gmail.com Received: by 10.170.82.197 with HTTP; Mon, 13 Oct 2014 11:40:11 -0700 (PDT) In-Reply-To: References: <54372173.1010100@ijs.si> <644FA8299BF848E599B82D2C2C298EA7@multiplay.co.uk> <54372EBA.1000908@ijs.si> <543731F3.8090701@ijs.si> <543AE740.7000808@ijs.si> <6E01BBEDA9984CCDA14F290D26A8E14D@multiplay.co.uk> Date: Mon, 13 Oct 2014 11:40:11 -0700 X-Google-Sender-Auth: Fs7HlWehuGXSlb7kaqKeWaNiw2E Message-ID: Subject: Re: zfs pool import hangs on [tx->tx_sync_done_cv] From: "K. Macy" To: Steven Hartland Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: quoted-printable Cc: "freebsd-fs@FreeBSD.org" , FreeBSD Stable X-BeenThere: freebsd-fs@freebsd.org X-Mailman-Version: 2.1.18-1 Precedence: list List-Id: Filesystems List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 13 Oct 2014 18:40:12 -0000 >> Yer I would have got the zio details but typically its "optimised out" b= y >> the >> compiler, so will need some effort to track that down unfortunately :( > > > Well, let me know if you can. Re-creating a new 10.x VM is taking a while= as > it's taking me forever to checkout the sources. > > Things like that need to somehow continue to be accessible. So there is an outstanding child, but it isn't clear what state it's in because the child pointer in the zio_link isn't valid. It's as if the memory got re-used for something else. I'm dumping my findings below on the off-chance that it helps you push this along. (kgdb) thread 459 [Switching to thread 459 (Thread 101524)]#0 sched_switch (td=3D0xfffff80063111000, newtd=3D, flags=3D) at /usr/home/kmacy/devel/svn/10/sys/kern/sched_ule.c:1945 1945 cpuid =3D PCPU_GET(cpuid); Current language: auto; currently minimal (kgdb) bt #0 sched_switch (td=3D0xfffff80063111000, newtd=3D, flags=3D) at /usr/home/kmacy/devel/svn/10/sys/kern/sched_ule.c:1945 #1 0xffffffff807aa199 in mi_switch (flags=3D260, newtd=3D0x0) at /usr/home/kmacy/devel/svn/10/sys/kern/kern_synch.c:494 #2 0xffffffff807e6e82 in sleepq_switch (wchan=3D, pri=3D) at /usr/home/kmacy/devel/svn/10/sys/kern/subr_sleepqueue.c:538 #3 0xffffffff807e6ce3 in sleepq_wait (wchan=3D0xfffff8004ddf4a50, pri=3D0) at /usr/home/kmacy/devel/svn/10/sys/kern/subr_sleepqueue.c:617 #4 0xffffffff80750d7a in _cv_wait (cvp=3D0xfffff8004ddf4a50, lock=3D0xfffff8004ddf4a30) at /usr/home/kmacy/devel/svn/10/sys/kern/kern_condvar.c:139 #5 0xffffffff817d145b in zio_wait (zio=3D) at /usr/home/kmacy/devel/svn/10/sys/modules/zfs/../../cddl/contrib/open= solaris/uts/common/fs/zfs/zio.c:1442 #6 0xffffffff81779d3c in dsl_pool_sync (dp=3D0xfffff8004d364800, txg=3D117= 33518) at /usr/home/kmacy/devel/svn/10/sys/modules/zfs/../../cddl/contrib/open= solaris/uts/common/fs/zfs/dsl_pool.c:531 #7 0xffffffff8179d800 in spa_sync (spa=3D0xfffffe000372f000, txg=3D1173351= 8) at /usr/home/kmacy/devel/svn/10/sys/modules/zfs/../../cddl/contrib/open= solaris/uts/common/fs/zfs/spa.c:6604 #8 0xffffffff817a7e9d in txg_sync_thread (arg=3D0xfffff8004d364800) at /usr/home/kmacy/devel/svn/10/sys/modules/zfs/../../cddl/contrib/open= solaris/uts/common/fs/zfs/txg.c:518 #9 0xffffffff8076ed34 in fork_exit (callout=3D0xffffffff817a7c50 , arg=3D0xfffff8004d364800, frame=3D0xfffffe012043fac0) at /usr/home/kmacy/devel/svn/10/sys/kern/kern_fork.c:996 #10 0xffffffff80b96b3e in fork_trampoline () at /usr/home/kmacy/devel/svn/10/sys/amd64/amd64/exception.S:606 #11 0x0000000000000000 in ?? () (kgdb) f 5 #5 0xffffffff817d145b in zio_wait (zio=3D) at /usr/home/kmacy/devel/svn/10/sys/modules/zfs/../../cddl/contrib/open= solaris/uts/common/fs/zfs/zio.c:1442 1442 cv_wait(&zio->io_cv, &zio->io_lock); (kgdb) disassemble zio_wait Dump of assembler code for function zio_wait: 0xffffffff817d13c0 : push %rbp 0xffffffff817d13c1 : mov %rsp,%rbp 0xffffffff817d13c4 : push %r15 0xffffffff817d13c6 : push %r14 0xffffffff817d13c8 : push %r12 0xffffffff817d13ca : push %rbx 0xffffffff817d13cb : mov %rdi,%r14 0xffffffff817d13ce : cmpl $0x1,0x254(%r14) 0xffffffff817d13d6 : je 0xffffffff817d13f0 0xffffffff817d13d8 : mov $0xffffffff81883de9,%rdi 0xffffffff817d13df : mov $0xffffffff81883b20,%rsi 0xffffffff817d13e6 : mov $0x599,%edx 0xffffffff817d13eb : callq 0xffffffff81a19200 0xffffffff817d13f0 : cmpq $0x0,0x2f0(%r14) 0xffffffff817d13f8 : je 0xffffffff817d1412 0xffffffff817d13fa : mov $0xffffffff8188410c,%rdi 0xffffffff817d1401 : mov $0xffffffff81883b20,%rsi 0xffffffff817d1408 : mov $0x59a,%edx 0xffffffff817d140d : callq 0xffffffff81a19200 0xffffffff817d1412 : mov %gs:0x0,%rax 0xffffffff817d141b : mov %rax,0x2f8(%r14) 0xffffffff817d1422 : mov %r14,%rdi 0xffffffff817d1425 : callq 0xffffffff817d24c0 0xffffffff817d142a : lea 0x300(%r14),%r15 0xffffffff817d1431 : xor %esi,%esi 0xffffffff817d1433 : mov $0xffffffff81883b20,%rdx 0xffffffff817d143a : mov $0x5a0,%ecx 0xffffffff817d143f : mov %r15,%rdi 0xffffffff817d1442 : callq 0xffffffff807a8270 <_sx_xloc= k> 0xffffffff817d1447 : lea 0x320(%r14),%rbx 0xffffffff817d144e : jmp 0xffffffff817d145b 0xffffffff817d1450 : mov %rbx,%rdi 0xffffffff817d1453 : mov %r15,%rsi 0xffffffff817d1456 : callq 0xffffffff80750ba0 <_cv_wait= > 0xffffffff817d145b : cmpq $0x0,0x2f0(%r14) 0xffffffff817d1463 : jne 0xffffffff817d1450 0xffffffff817d1465 : mov $0xffffffff81883b20,%rsi 0xffffffff817d146c : mov $0x5a3,%edx 0xffffffff817d1471 : mov %r15,%rdi 0xffffffff817d1474 : callq 0xffffffff807a8630 <_sx_xunl= ock> 0xffffffff817d1479 : mov 0x268(%r14),%r12d 0xffffffff817d1480 : lea 0xf0(%r14),%rdi 0xffffffff817d1487 : callq 0xffffffff8172d480 0xffffffff817d148c : lea 0x110(%r14),%rdi 0xffffffff817d1493 : callq 0xffffffff8172d480 0xffffffff817d1498 : mov %r15,%rdi 0xffffffff817d149b : callq 0xffffffff807a8010 0xffffffff817d14a0 : mov %rbx,%rdi 0xffffffff817d14a3 : callq 0xffffffff80750b50 0xffffffff817d14a8 : mov 0xffffffff818af6e0,%rdi 0xffffffff817d14b0 : mov %r14,%rsi 0xffffffff817d14b3 : callq 0xffffffff81a19400 0xffffffff817d14b8 : mov %r12d,%eax 0xffffffff817d14bb : pop %rbx 0xffffffff817d14bc : pop %r12 0xffffffff817d14be : pop %r14 0xffffffff817d14c0 : pop %r15 0xffffffff817d14c2 : pop %rbp 0xffffffff817d14c3 : retq End of assembler dump. 0xffffffff817d1422 : mov %r14,%rdi 0xffffffff817d1425 : callq 0xffffffff817d24c0 0xffffffff817d142a : lea 0x300(%r14),%r15 0xffffffff817d1431 : xor %esi,%esi 0xffffffff817d1433 : mov $0xffffffff81883b20,%rdx 0xffffffff817d143a : mov $0x5a0,%ecx 0xffffffff817d143f : mov %r15,%rdi 0xffffffff817d1442 : callq 0xffffffff807a8270 <_sx_xloc= k> 0xffffffff817d1447 : lea 0x320(%r14),%rbx 0xffffffff817d144e : jmp 0xffffffff817d145b 0xffffffff817d1450 : mov %rbx,%rdi 0xffffffff817d1453 : mov %r15,%rsi 0xffffffff817d1456 : callq 0xffffffff80750ba0 <_cv_wait= > (kgdb) p *(zio_t *)$r14 $1 =3D { io_bookmark =3D { zb_objset =3D 0, zb_object =3D 0, zb_level =3D 0, zb_blkid =3D 0 }, io_prop =3D { zp_checksum =3D ZIO_CHECKSUM_INHERIT, zp_compress =3D ZIO_COMPRESS_INHERIT, zp_type =3D DMU_OT_NONE, zp_level =3D 0 '\0', zp_copies =3D 0 '\0', zp_dedup =3D 0, zp_dedup_verify =3D 0, zp_nopwrite =3D 0 }, io_type =3D ZIO_TYPE_NULL, io_child_type =3D ZIO_CHILD_LOGICAL, io_cmd =3D 0, io_priority =3D ZIO_PRIORITY_NOW, io_reexecute =3D 2 '\002', io_state =3D "\001\001", io_txg =3D 0, io_spa =3D 0xfffffe000372f000, io_bp =3D 0x0, io_bp_override =3D 0x0, io_bp_copy =3D { blk_dva =3D {{ dva_word =3D {0, 0} }, { dva_word =3D {0, 0} }, { dva_word =3D {0, 0} }}, blk_prop =3D 0, blk_pad =3D {0, 0}, blk_phys_birth =3D 0, blk_birth =3D 0, blk_fill =3D 0, blk_cksum =3D { zc_word =3D {0, 0, 0, 0} } }, io_parent_list =3D { list_size =3D 48, list_offset =3D 16, list_head =3D { list_next =3D 0xfffff800b435c850, list_prev =3D 0xfffff800b435c850 } }, io_child_list =3D { list_size =3D 48, list_offset =3D 32, list_head =3D { list_next =3D 0xfffff80003585770, list_prev =3D 0xfffff80003585770 } }, io_walk_link =3D 0x0, io_logical =3D 0x0, io_transform_stack =3D 0x0, io_ready =3D 0, io_physdone =3D 0, io_done =3D 0, io_private =3D 0x0, io_prev_space_delta =3D 0, io_bp_orig =3D { blk_dva =3D {{ dva_word =3D {0, 0} }, { dva_word =3D {0, 0} }, { dva_word =3D {0, 0} }}, blk_prop =3D 0, blk_pad =3D {0, 0}, blk_phys_birth =3D 0, blk_birth =3D 0, blk_fill =3D 0, blk_cksum =3D { zc_word =3D {0, 0, 0, 0} } }, io_data =3D 0x0, io_orig_data =3D 0x0, io_size =3D 0, io_orig_size =3D 0, io_vd =3D 0x0, io_vsd =3D 0x0, io_vsd_ops =3D 0x0, io_offset =3D 0, io_timestamp =3D 0, io_queue_node =3D { avl_child =3D {0x0, 0x0}, avl_pcb =3D 0 }, io_flags =3D 0, io_stage =3D ZIO_STAGE_DONE, io_pipeline =3D 2162688, io_orig_flags =3D 0, io_orig_stage =3D ZIO_STAGE_OPEN, io_orig_pipeline =3D 2162688, io_error =3D 0, io_child_error =3D {0, 0, 0, 0}, io_children =3D {{0, 0}, {0, 0}, {0, 0}, {0, 0}}, io_child_count =3D 1, io_phys_children =3D 0, io_parent_count =3D 1, io_stall =3D 0x0, io_gang_leader =3D 0x0, io_gang_tree =3D 0x0, io_executor =3D 0xfffff8006314a000, io_waiter =3D 0xfffff80063111000, io_lock =3D { lock_object =3D { lo_name =3D 0xffffffff8188655c "zio->io_lock", lo_flags =3D 41091072, lo_data =3D 0, lo_witness =3D 0xfffffe00006eca80 }, sx_lock =3D 1 }, io_cv =3D { cv_description =3D 0xffffffff8188656a "zio->io_cv", cv_waiters =3D 1 }, io_cksum_report =3D 0x0, io_ena =3D 0, io_tqent =3D { tqent_task =3D { ta_link =3D { stqe_next =3D 0x0 }, ta_pending =3D 0, ta_priority =3D 0, ta_func =3D 0, ta_context =3D 0x0 }, tqent_func =3D 0, tqent_arg =3D 0x0 }, io_trim_node =3D { avl_child =3D {0x0, 0x0}, avl_pcb =3D 0 }, io_trim_link =3D { list_next =3D 0x0, list_prev =3D 0x0 } } All of its children have called zio_notify_parent on this zio and are error free: io_child_error =3D {0, 0, 0, 0}, io_children =3D {{0, 0}, {0, 0}, {0, 0}, {0, 0}}, (kgdb) p ((zio_t *)$r14)->io_stall $5 =3D (uint64_t *) 0x0 One child has itself not reached the end of zio_done: io_child_count =3D 1, (kgdb) p ((zio_t *)$r14)->io_child_list $2 =3D { list_size =3D 48, list_offset =3D 32, list_head =3D { list_next =3D 0xfffff80003585770, list_prev =3D 0xfffff80003585770 } (kgdb) p *(zio_link_t *)0xfffff80003585770 $15 =3D { zl_parent =3D 0xfffff8004ddf4850, zl_child =3D 0xfffff8004ddf4850, zl_parent_node =3D { list_next =3D 0xfffff8004dd62398, list_prev =3D 0xfffff8004d4d2730 }, zl_child_node =3D { list_next =3D 0x0, list_prev =3D 0x0 } } I don't understand why the parent and child are the same, of course that could be part of the problem. That address isn't a valid zio and there and the child node entry doesn't point to anything. It has a thread executing it (which itself is probably in cv_wait): io_executor =3D 0xfffff8006314a000, (kgdb) p *((struct thread *)0xfffff8006314a000) $11 =3D { td_lock =3D 0xffffffff81224b30, td_proc =3D 0xffffffff814438d8, td_plist =3D { tqe_next =3D 0xfffff8006312b920, tqe_prev =3D 0xfffff8006312a4a0 }, td_runq =3D { tqe_next =3D 0x0, tqe_prev =3D 0xffffffff811ef378 }, td_slpq =3D { tqe_next =3D 0x0, tqe_prev =3D 0xfffff80020e204c0 }, td_lockq =3D { tqe_next =3D 0x0, tqe_prev =3D 0x0 }, td_hash =3D { le_next =3D 0x0, le_prev =3D 0xfffffe0000879fc8 }, td_cpuset =3D 0xfffff800631d2318, td_sel =3D 0x0, td_sleepqueue =3D 0x0, td_turnstile =3D 0xfffff80063128480, td_rlqe =3D 0x0, td_umtxq =3D 0xfffff8004d7a6380, td_tid =3D 100345, td_sigqueue =3D { sq_signals =3D { __bits =3D {0, 0, 0, 0} }, sq_kill =3D { __bits =3D {0, 0, 0, 0} }, sq_list =3D { tqh_first =3D 0x0, tqh_last =3D 0xfffff8006314a0b8 }, sq_proc =3D 0xffffffff814438d8, sq_flags =3D 1 }, td_lend_user_pri =3D 255 '=C3=BF', td_flags =3D 4, td_inhibitors =3D 2, td_pflags =3D 2097152, td_dupfd =3D 0, td_sqqueue =3D 0, td_wchan =3D 0xfffff800b48a2900, td_wmesg =3D 0xffffffff80d64d7e "-", td_lastcpu =3D 0 '\0', td_oncpu =3D 255 '=C3=BF', td_owepreempt =3D 0 '\0', td_tsqueue =3D 0 '\0', td_locks =3D 0, td_rw_rlocks =3D 0, td_lk_slocks =3D 0, td_stopsched =3D 0, td_blocked =3D 0x0, td_lockname =3D 0x0, td_contested =3D { lh_first =3D 0x0 }, td_sleeplocks =3D 0xffffffff81369470, ---Type to continue, or q to quit--- td_intr_nesting_level =3D 0, td_pinned =3D 0, td_ucred =3D 0xfffff800027f1e00, td_estcpu =3D 0, td_slptick =3D 226829, td_blktick =3D 0, td_swvoltick =3D 226829, td_cow =3D 0, td_ru =3D { ru_utime =3D { tv_sec =3D 0, tv_usec =3D 0 }, ru_stime =3D { tv_sec =3D 0, tv_usec =3D 0 }, ru_maxrss =3D 0, ru_ixrss =3D 0, ru_idrss =3D 0, ru_isrss =3D 0, ru_minflt =3D 0, ru_majflt =3D 0, ru_nswap =3D 0, ru_inblock =3D 0, ru_oublock =3D 0, ru_msgsnd =3D 0, ru_msgrcv =3D 0, ru_nsignals =3D 0, ru_nvcsw =3D 6, ru_nivcsw =3D 0 }, td_rux =3D { rux_runtime =3D 0, rux_uticks =3D 0, rux_sticks =3D 0, rux_iticks =3D 0, rux_uu =3D 0, rux_su =3D 0, rux_tu =3D 0 }, td_incruntime =3D 410296, td_runtime =3D 410296, td_pticks =3D 0, td_sticks =3D 0, td_iticks =3D 0, td_uticks =3D 0, td_intrval =3D 0, td_oldsigmask =3D { __bits =3D {0, 0, 0, 0} }, td_generation =3D 6, td_sigstk =3D { ss_sp =3D 0x0, ss_size =3D 0, ss_flags =3D 0 }, td_xsig =3D 0, td_profil_addr =3D 0, td_profil_ticks =3D 0, td_name =3D "zio_write_intr_7\000\000\000", td_fpop =3D 0x0, td_dbgflags =3D 0, td_dbgksi =3D { ksi_link =3D { tqe_next =3D 0x0, tqe_prev =3D 0x0 }, ksi_info =3D { si_signo =3D 0, si_errno =3D 0, si_code =3D 0, si_pid =3D 0, si_uid =3D 0, si_status =3D 0, si_addr =3D 0x0, si_value =3D { sival_int =3D 0, sival_ptr =3D 0x0, sigval_int =3D 0, sigval_ptr =3D 0x0 }, _reason =3D { _fault =3D { _trapno =3D 0 }, _timer =3D { _timerid =3D 0, _overrun =3D 0 }, _mesgq =3D { _mqd =3D 0 }, _poll =3D { _band =3D 0 }, __spare__ =3D { __spare1__ =3D 0, __spare2__ =3D {0, 0, 0, 0, 0, 0, 0} } } }, ksi_flags =3D 0, ksi_sigq =3D 0x0 }, td_ng_outbound =3D 0, td_osd =3D { osd_nslots =3D 0, osd_slots =3D 0x0, osd_next =3D { le_next =3D 0x0, le_prev =3D 0x0 } }, td_map_def_user =3D 0x0, td_dbg_forked =3D 0, td_vp_reserv =3D 0, td_no_sleeping =3D 0, td_dom_rr_idx =3D 0, td_sigmask =3D { __bits =3D {0, 0, 0, 0} }, td_rqindex =3D 21 '\025', td_base_pri =3D 84 'T', td_priority =3D 84 'T', td_pri_class =3D 3 '\003', td_user_pri =3D 172 '=C2=AC', td_base_user_pri =3D 172 '=C2=AC', td_pcb =3D 0xfffffe012060eb80, td_state =3D TDS_INHIBITED, td_retval =3D {0, 0}, td_slpcallout =3D { ---Type to continue, or q to quit--- c_links =3D { le =3D { le_next =3D 0x0, le_prev =3D 0x0 }, sle =3D { sle_next =3D 0x0 }, tqe =3D { tqe_next =3D 0x0, tqe_prev =3D 0x0 } }, c_time =3D 0, c_precision =3D 0, c_arg =3D 0x0, c_func =3D 0, c_lock =3D 0x0, c_flags =3D 16, c_cpu =3D 0 }, td_frame =3D 0xfffffe012060eac0, td_kstack_obj =3D 0xfffff8006314cd00, td_kstack =3D 18446741879524470784, td_kstack_pages =3D 4, td_critnest =3D 1, td_md =3D { md_spinlock_count =3D 1, md_saved_flags =3D 582, md_spurflt_addr =3D 0 }, td_sched =3D 0xfffff8006314a468, td_ar =3D 0x0, td_lprof =3D {{ lh_first =3D 0x0 }, { lh_first =3D 0x0 }}, td_dtrace =3D 0xfffff800b437ce00, td_errno =3D 0, td_vnet =3D 0x0, td_vnet_lpush =3D 0x0, td_intr_frame =3D 0x0, td_rfppwait_p =3D 0x0, td_ma =3D 0x0, td_ma_cnt =3D 0 } Interesting bits about the executing thread: td_name =3D "zio_write_intr_7\000\000\000", td_critnest =3D 1, td_md =3D { md_spinlock_count =3D 1, md_saved_flags =3D 582, md_spurflt_addr =3D 0 }, Unfortunately executor is never cleared, so this is just the last thread that happened to execute this i/o.