From owner-freebsd-stable@FreeBSD.ORG Mon Oct 13 00:54:21 2014 Return-Path: Delivered-To: freebsd-stable@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by hub.freebsd.org (Postfix) with ESMTPS id DE61A9DB; Mon, 13 Oct 2014 00:54:21 +0000 (UTC) Received: from smtp1.multiplay.co.uk (smtp1.multiplay.co.uk [85.236.96.35]) by mx1.freebsd.org (Postfix) with ESMTP id 2CB3368; Mon, 13 Oct 2014 00:54:20 +0000 (UTC) Received: by smtp1.multiplay.co.uk (Postfix, from userid 65534) id 8D0BC20E708AC; Mon, 13 Oct 2014 00:54:13 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on smtp1.multiplay.co.uk X-Spam-Level: * X-Spam-Status: No, score=2.0 required=8.0 tests=AWL,BAYES_00,DOS_OE_TO_MX, FSL_HELO_NON_FQDN_1,RDNS_DYNAMIC autolearn=no version=3.3.1 Received: from r2d2 (82-69-141-170.dsl.in-addr.zen.co.uk [82.69.141.170]) by smtp1.multiplay.co.uk (Postfix) with ESMTPS id A360420E708AA; Mon, 13 Oct 2014 00:54:09 +0000 (UTC) Message-ID: From: "Steven Hartland" To: "Mark Martinec" , , References: <54372173.1010100@ijs.si> <644FA8299BF848E599B82D2C2C298EA7@multiplay.co.uk> <54372EBA.1000908@ijs.si> <543731F3.8090701@ijs.si> <543AE740.7000808@ijs.si> Subject: Re: zfs pool import hangs on [tx->tx_sync_done_cv] Date: Mon, 13 Oct 2014 01:54:05 +0100 MIME-Version: 1.0 Content-Type: text/plain; format=flowed; charset="iso-8859-1"; reply-type=response Content-Transfer-Encoding: 7bit X-Priority: 3 X-MSMail-Priority: Normal X-Mailer: Microsoft Outlook Express 6.00.2900.5931 X-MimeOLE: Produced By Microsoft MimeOLE V6.00.2900.6157 X-BeenThere: freebsd-stable@freebsd.org X-Mailman-Version: 2.1.18-1 Precedence: list List-Id: Production branch of FreeBSD source code List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Mon, 13 Oct 2014 00:54:22 -0000 I have reproduced the issue with your image. It seems like the import is waiting a transation group to complete. It looks like its waiting on the zio from dsl_pool_sync_mos which for some reason is never returning. The pool does seem to be happy importing read only with: zpool import -N -f -o readonly=on sys1boot print dp->dp_tx $3 = { tx_cpu = 0xfffffe0004a05000, tx_sync_lock = { lock_object = { lo_name = 0xffffffff815f2941 "tx->tx_sync_lock", lo_flags = 40960000, lo_data = 0, lo_witness = 0x0 }, sx_lock = 1 }, tx_open_txg = 11733519, tx_quiesced_txg = 0, tx_syncing_txg = 11733518, tx_synced_txg = 0, tx_open_time = 120562502889, tx_sync_txg_waiting = 11733518, tx_quiesce_txg_waiting = 11733519, tx_sync_more_cv = { cv_description = 0xffffffff815f2953 "tx->tx_sync_more_cv", cv_waiters = 0 }, tx_sync_done_cv = { cv_description = 0xffffffff815f2968 "tx->tx_sync_done_cv", cv_waiters = 1 }, tx_quiesce_more_cv = { cv_description = 0xffffffff815f297d "tx->tx_quiesce_more_cv", cv_waiters = 1 }, tx_quiesce_done_cv = { cv_description = 0xffffffff815f2995 "tx->tx_quiesce_done_cv", cv_waiters = 0 }, tx_timeout_cv = { cv_description = 0x0, cv_waiters = 0 }, tx_exit_cv = { cv_description = 0xffffffff815f29ad "tx->tx_exit_cv", cv_waiters = 0 }, tx_threads = 2 '\002', tx_exiting = 0 '\0', tx_sync_thread = 0xfffff80041505490, tx_quiesce_thread = 0xfffff80041509920, tx_commit_cb_taskq = 0x0 } Relavent threads: #0 sched_switch (td=0xfffff800446bc000, newtd=, flags=) at /usr/src/sys/kern/sched_ule.c:1945 #1 0xffffffff806110d9 in mi_switch (flags=260, newtd=0x0) at /usr/src/sys/kern/kern_synch.c:494 #2 0xffffffff8064ddc2 in sleepq_switch (wchan=, pri=) at /usr/src/sys/kern/subr_sleepqueue.c:538 #3 0xffffffff8064dc23 in sleepq_wait (wchan=0xfffff80021f4b220, pri=0) at /usr/src/sys/kern/subr_sleepqueue.c:617 #4 0xffffffff805b7c1a in _cv_wait (cvp=0xfffff80021f4b220, lock=0xfffff80021f4b1b8) at /usr/src/sys/kern/kern_condvar.c:139 #5 0xffffffff8151ec4b in txg_wait_synced (dp=0xfffff80021f4b000, txg=) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/txg.c:631 #6 0xffffffff81510937 in spa_load (spa=0xfffffe0003fe1000, state=SPA_LOAD_IMPORT, type=, mosconfig=) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/spa.c:2777 #7 0xffffffff8150e5df in spa_load_best (spa=0xfffffe0003fe1000, state=SPA_LOAD_IMPORT, mosconfig=1, max_request=, rewind_flags=1) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/spa.c:2873 #8 0xffffffff8150e023 in spa_import (pool=0xfffffe0002e2a000 "sys1boot", config=0xfffff80044f24ba0, props=0x0, flags=) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/spa.c:4207 #9 0xffffffff81566d78 in zfs_ioc_pool_import (zc=0xfffffe0002e2a000) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:1594 #10 0xffffffff81563c4f in zfsdev_ioctl (dev=, zcmd=, arg=, flag=, td=) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_ioctl.c:6158 #11 0xffffffff805299eb in devfs_ioctl_f (fp=0xfffff8004f020aa0, com=3222821378, data=0xfffff80038123e60, cred=, td=0xfffff800446bc000) at /usr/src/sys/fs/devfs/devfs_vnops.c:757 #12 0xffffffff8066201b in kern_ioctl (td=, fd=, com=) at file.h:320 #13 0xffffffff80661d9c in sys_ioctl (td=0xfffff800446bc000, uap=0xfffffe011e49fa40) at /usr/src/sys/kern/sys_generic.c:702 #14 0xffffffff8088defa in amd64_syscall (td=0xfffff800446bc000, traced=0) at subr_syscall.c:134 #15 0xffffffff80870ecb in Xfast_syscall () at /usr/src/sys/amd64/amd64/exception.S:391 Thread 509 (Thread 100533): #0 sched_switch (td=0xfffff800446bf000, newtd=, flags=) at /usr/src/sys/kern/sched_ule.c:1945 #1 0xffffffff806110d9 in mi_switch (flags=260, newtd=0x0) at /usr/src/sys/kern/kern_synch.c:494 #2 0xffffffff8064ddc2 in sleepq_switch (wchan=, pri=) at /usr/src/sys/kern/subr_sleepqueue.c:538 #3 0xffffffff8064e323 in sleepq_timedwait (wchan=0xfffff80044e47210, pri=0) at /usr/src/sys/kern/subr_sleepqueue.c:652 #4 0xffffffff805b84f0 in _cv_timedwait_sbt (cvp=0xfffff80044e47210, lock=0xfffff80044e471b8, sbt=, pr=, flags=) at /usr/src/sys/kern/kern_condvar.c:325 #5 0xffffffff8151f72e in txg_thread_wait (tx=, cpr=0xfffffe011dc76a00, cv=0xfffff80044e47210, time=) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/txg.c:249 #6 0xffffffff8151e930 in txg_sync_thread (arg=0xfffff80044e47000) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/txg.c:483 #7 0xffffffff805d5bd4 in fork_exit (callout=0xffffffff8151e480 , arg=0xfffff80044e47000, frame=0xfffffe011dc76ac0) at /usr/src/sys/kern/kern_fork.c:996 #8 0xffffffff8087111e in fork_trampoline () at /usr/src/sys/amd64/amd64/exception.S:606 #9 0x0000000000000000 in ?? () Thread 508 (Thread 100532): #0 sched_switch (td=0xfffff80048204920, newtd=, flags=) at /usr/src/sys/kern/sched_ule.c:1945 #1 0xffffffff806110d9 in mi_switch (flags=260, newtd=0x0) at /usr/src/sys/kern/kern_synch.c:494 #2 0xffffffff8064ddc2 in sleepq_switch (wchan=, pri=) at /usr/src/sys/kern/subr_sleepqueue.c:538 #3 0xffffffff8064dc23 in sleepq_wait (wchan=0xfffff80044e47230, pri=0) at /usr/src/sys/kern/subr_sleepqueue.c:617 #4 0xffffffff805b7c1a in _cv_wait (cvp=0xfffff80044e47230, lock=0xfffff80044e471b8) at /usr/src/sys/kern/kern_condvar.c:139 #5 0xffffffff8151f73b in txg_thread_wait (tx=, cpr=0xfffffe011dc6da00, cv=, time=) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/txg.c:251 #6 0xffffffff8151e450 in txg_quiesce_thread (arg=0xfffff80044e47000) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/txg.c:556 #7 0xffffffff805d5bd4 in fork_exit (callout=0xffffffff8151e030 , arg=0xfffff80044e47000, frame=0xfffffe011dc6dac0) at /usr/src/sys/kern/kern_fork.c:996 #8 0xffffffff8087111e in fork_trampoline () at /usr/src/sys/amd64/amd64/exception.S:606 #9 0x0000000000000000 in ?? () Thread 512 (Thread 100338): #0 sched_switch (td=0xfffff80041505490, newtd=, flags=) at /usr/src/sys/kern/sched_ule.c:1945 #1 0xffffffff806110d9 in mi_switch (flags=260, newtd=0x0) at /usr/src/sys/kern/kern_synch.c:494 #2 0xffffffff8064ddc2 in sleepq_switch (wchan=, pri=) at /usr/src/sys/kern/subr_sleepqueue.c:538 #3 0xffffffff8064dc23 in sleepq_wait (wchan=0xfffff80044acf320, pri=0) at /usr/src/sys/kern/subr_sleepqueue.c:617 #4 0xffffffff805b7c1a in _cv_wait (cvp=0xfffff80044acf320, lock=0xfffff80044acf300) at /usr/src/sys/kern/kern_condvar.c:139 #5 0xffffffff81547c9b in zio_wait (zio=) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zio.c:1442 #6 0xffffffff814f056c in dsl_pool_sync (dp=0xfffff80021f4b000, txg=11733518) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/dsl_pool.c:531 #7 0xffffffff81514030 in spa_sync (spa=0xfffffe0003fe1000, txg=11733518) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/spa.c:6604 #8 0xffffffff8151e6cd in txg_sync_thread (arg=0xfffff80021f4b000) at /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/txg.c:518 #9 0xffffffff805d5bd4 in fork_exit (callout=0xffffffff8151e480 , arg=0xfffff80021f4b000, frame=0xfffffe011e6fdac0) at /usr/src/sys/kern/kern_fork.c:996 #10 0xffffffff8087111e in fork_trampoline () at /usr/src/sys/amd64/amd64/exception.S:606 #11 0x0000000000000000 in ?? () ----- Original Message ----- From: "Mark Martinec" To: ; Sent: Sunday, October 12, 2014 9:40 PM Subject: Re: zfs pool import hangs on [tx->tx_sync_done_cv] >I made available an image copy (dd) of my 4 GiB partition > (compressed down to a 384 MiB file), holding one of my > partitions (a small bsd root) that can no longer be imported > into a 10.1-RC1 or 10.1-BETA3, as described in my first > posting (below): > > http://www.ijs.si/usr/mark/bsd/ > > I would appreciate if it can be confirmed that such pool > (one of several I have with this symptom) causes > 'zpool import' to hang on 10.1 or 10-STABLE: > > - download, xz -d sys1boot.img.xz > # mdconfig -f sys1boot.img > # zpool import sys1boot > > ... and advise on a solution. > > Considering that 'zdb -e -cc' is happy and there were no > other prior trouble with these pools, except for an upgrade > to 10.1-BETA3/-RC1 from 10-STABLE as of cca. late September, > it is my belief that these pools are still healthy, just > non-importable. I'm reluctant to upgrade any other system > from 10.0 to 10.1 without finding out what went wrong here. > > Mark > > > On 10/10/2014 03:02, Steven Hartland wrote: > > Sorry to be a pain but could you attach the full output or link it > > somewhere as mail has messed up the formatting :( > > Now at > http://www.ijs.si/usr/mark/bsd/procstat-kka-2074.txt > > On 2014-10-10 Mark Martinec wrote: >> In short, after upgrading to 10.1-BETA3 or -RC1 I ended up with several >> zfs pools that can no longer be imported. The zpool import command >> (with no arguments) does show all available pools, but trying to >> import one just hangs and the command cannot be aborted, although >> the rest of the system is still alive and fine: >> >> # zpool import -f >> >> Typing ^T just shows an idle process, waiting on [tx->tx_sync_done_cv]: >> >> load: 0.20 cmd: zpool 939 [tx->tx_sync_done_cv] 5723.65r 0.01u 0.02s 0% 8220k >> load: 0.16 cmd: zpool 939 [tx->tx_sync_done_cv] 5735.73r 0.01u 0.02s 0% 8220k >> load: 0.14 cmd: zpool 939 [tx->tx_sync_done_cv] 5741.83r 0.01u 0.02s 0% 8220k >> load: 0.13 cmd: zpool 939 [tx->tx_sync_done_cv] 5749.16r 0.01u 0.02s 0% 8220k >> >> ps shows (on a system re-booted to a LiveCD running FreeBSD-10.1-RC1): >> >> PID TID COMM TDNAME CPU PRI STATE WCHAN >> 939 100632 zpool - 5 122 sleep tx->tx_s >> UID PID PPID CPU PRI NI VSZ RSS MWCHAN STAT TT TIME COMMAND >> 0 939 801 0 22 0 107732 8236 tx->tx_s D+ v0 0:00.04 >> zpool import -f -o cachefile=/tmp/zpool.cache -R /tmp/sys0boot sys0boot >> >> NWCHAN >> fffff8007b0f2a20 >> >> # procstat -kk 939 >> >> PID TID COMM TDNAME KSTACK >> 939 100632 zpool - mi_switch+0xe1 sleepq_wait+0x3a _cv_wait+0x16d txg_wait_synced+0x85 >> spa_load+0x1cd1 spa_load_best+0x6f spa_import+0x1ff zfs_ioc_pool_import+0x137 zfsdev_ioctl+0x6f0 devfs_ioctl_f+0x114 >> kern_ioctl+0x255 sys_ioctl+0x13c amd64_syscall+0x351 Xfast_syscall+0xfb >> >> >> Background story: the system where this happened was being kept >> to a fairly recent 10-STABLE. The last upgrade was very close to >> a BETA3 release. There are a couple of zfs pools there, one on a >> mirrored pair of SSDs mostly holding the OS, one with a mirrored >> pair of large spindles, and three more small ones (4 GiB each), >> mostly for boot redundancy or testing - these small ones are on >> old smallish disks. These disks are different, and attached to >> different SATA controllers (LSI and onboard Intel). Pools were >> mostly kept up-to-date to the most recent zpool features set >> through their lifetime (some starting their life with 9.0, some >> with 10.0). >> >> About two weeks ago after a reboot to a 10-STABLE of the day >> the small pools became unavailable, but the regular two large >> pools were still normal. At first I wasn't giving much attention >> to that, as these pools were on oldish disks and nonessential >> for normal operation, blaming a potentially crappy hw. >> >> Today I needed to do a reboot (for unrelated reason), and the >> machine was no longer able to mount the boot pool. >> The first instinct was - disks are malfunctioning - but ... >> >> Booting it to a FreeBSD-10.1-RC1 LiveCD was successful. >> smartmon disk test shows no problems. dd is able to read whole >> partititions of each problematic pool. And most importantly, >> running a 'zdb -e -cc' on each (non-imported) pool was churning >> normally and steadily, producing a stats report at the end >> and reported no errors. >> >> As a final proof that disks are fine I sacrificed one of the broken >> 4 GiB GPT partitions with one of the problematic pools, and >> did a fresh 10.1-RC1 install on it from a distribution ISO DVD. >> The installation went fine and the system does boot and run >> fine from the newly installed OS. Trying to import one of the >> remaining old pools hangs the import command as before. >> >> As a final proof, I copied (with dd) one of the broken 4 GiB >> partitions to a file on another system (running 10.1-BETA3, >> which did not suffer from this problem), made a memory disk >> out of this file, then run zfs import on this pool - and it hangs >> there too! So hardware was not a problem - either these partitions >> are truly broken (even though zdb -cc says they are fine), >> or the new OS is somehow no longer able to import them. >> >> Please advise. >> >> I have a copy of the 4 GiB partition on a 400 MB compressed >> file available, if somebody would be willing to play with it. >> >> Also have a ktrace of the 'zpool import' command. It's last >> actions before it hangs are: >> >> 939 zpool RET madvise 0 >> 939 zpool CALL madvise(0x80604e000,0x1000,MADV_FREE) >> 939 zpool RET madvise 0 >> 939 zpool CALL close(0x6) >> 939 zpool RET close 0 >> 939 zpool CALL ioctl(0x3,0xc0185a05,0x7fffffffbf00) >> 939 zpool RET ioctl -1 errno 2 No such file or directory >> 939 zpool CALL madvise(0x802c71000,0x10000,MADV_FREE) >> 939 zpool RET madvise 0 >> 939 zpool CALL madvise(0x802ca5000,0x1000,MADV_FREE) >> 939 zpool RET madvise 0 >> 939 zpool CALL ioctl(0x3,0xc0185a06,0x7fffffffbf60) >> 939 zpool RET ioctl 0 >> 939 zpool CALL ioctl(0x3,0xc0185a06,0x7fffffffbf60) >> 939 zpool RET ioctl 0 >> 939 zpool CALL stat(0x802c380e0,0x7fffffffbc58) >> 939 zpool NAMI "/tmp" >> 939 zpool STRU struct stat {dev=273, ino=2, mode=041777, nlink=8, uid=0, gid=0, rdev=96, atime=1412866648, >> stime=1412871393, ctime=1412871393, birthtime=1412866648, size=512, blksize=32768, blocks=8, flags=0x0 } >> 939 zpool RET stat 0 >> 939 zpool CALL ioctl(0x3,0xc0185a02,0x7fffffffbc60) >> >> >> Mark > > _______________________________________________ > freebsd-stable@freebsd.org mailing list > http://lists.freebsd.org/mailman/listinfo/freebsd-stable > To unsubscribe, send any mail to "freebsd-stable-unsubscribe@freebsd.org" >