Date: Thu, 12 Jul 2012 22:33:59 -0700 From: Dennis Glatting <dg@pki2.com> To: Fabian Keil <freebsd-listen@fabiankeil.de> Cc: freebsd-fs@freebsd.org Subject: Re: ZFS hanging Message-ID: <1342157639.60708.11.camel@btw.pki2.com> In-Reply-To: <20120712151541.7f3a6886@fabiankeil.de> References: <1341864787.32803.43.camel@btw.pki2.com> <20120712151541.7f3a6886@fabiankeil.de>
next in thread | previous in thread | raw e-mail | index | archive | help
On Thu, 2012-07-12 at 15:15 +0200, Fabian Keil wrote: > Dennis Glatting <freebsd@pki2.com> wrote: > > > I have a ZFS array of disks where the system simply stops as if forever > > blocked by some IO mutex. This happens often and the following is the > > output of top: > > > > last pid: 6075; load averages: 0.00, 0.00, 0.00 up 0+16:54:41 > > 13:04:10 > > 135 processes: 1 running, 134 sleeping > > CPU: 0.0% user, 0.0% nice, 0.0% system, 0.0% interrupt, 100% idle > > Mem: 47M Active, 24M Inact, 18G Wired, 120M Buf, 44G Free > > Swap: 32G Total, 32G Free > > > > PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU > > COMMAND > > 2410 root 1 33 0 11992K 2820K zio->i 7 331:25 0.00% > > bzip2 > > 2621 root 1 52 4 28640K 5544K tx->tx 24 245:33 0.00% > > john > > 2624 root 1 48 4 28640K 5544K tx->tx 4 239:08 0.00% > > john > > 2623 root 1 49 4 28640K 5544K tx->tx 7 238:44 0.00% > > john > > Does top continue to run or does it hang as well? > It continues to run. > I believe the locks shown above shouldn't affect already > running applications that don't cause disk traffic. > > > My question is what should I be looking at and how should I look at it? > > There is nothing in the logs or the console, rather the system is > > forever paused and entering commands results in no response (it's as if > > everything is deadlocked). > > If the entered commands actually start you can try sending > SIGINFO with CTRL+T to request a status: > > fk@r500 ~ $zpool status > load: 0.15 cmd: zpool 2698 [spa_namespace_lock] 543.23r 0.00u 0.12s 0% 2908k > > If you can run procstat you can try getting kernel stack traces > for some (or all) processes that should give you a rough idea > of how the lock is reached: > > fk@r500 ~ $procstat -kk $(pgrep zpool) > PID TID COMM TDNAME KSTACK > 2698 100922 zpool - mi_switch+0x196 sleepq_wait+0x42 _sx_xlock_hard+0x525 _sx_xlock+0x75 spa_all_configs+0x5e zfs_ioc_pool_configs+0x29 zfsdev_ioctl+0xe6 devfs_ioctl_f+0x7b kern_ioctl+0x115 sys_ioctl+0xfd amd64_syscall+0x5f9 Xfast_syscall+0xf7 > 2388 100431 zpool - mi_switch+0x196 sleepq_wait+0x42 _sx_xlock_hard+0x525 _sx_xlock+0x75 spa_open_common+0x7a spa_get_stats+0x5b zfs_ioc_pool_stats+0x2c zfsdev_ioctl+0xe6 devfs_ioctl_f+0x7b kern_ioctl+0x115 sys_ioctl+0xfd amd64_syscall+0x5f9 Xfast_syscall+0xf7 > > If procstat hangs as well you could try executing it in a loop > before the problem occurs. If it stays in the cache it may keep > running after most of the other processes stop responding. > > DTrace can be useful for analyzing locking issues as well: > > fk@r500 ~ $sudo ~/scripts/flowtrace.d zfsdev_ioctl > 0 101057 2012 Jul 12 14:59:42.155 00: Trace in progress. Waiting to enter zfsdev_ioctl. Hit CTRL-C to exit. > 0 100979 2012 Jul 12 14:59:43.933 04: --> zfsdev_ioctl:entry > 0 100979 2012 Jul 12 14:59:43.933 05: --> zfs_secpolicy_none:entry > 0 100979 2012 Jul 12 14:59:43.933 05: <-- zfs_secpolicy_none:return > 0 100979 2012 Jul 12 14:59:43.933 05: --> zfs_ioc_pool_configs:entry > 0 100979 2012 Jul 12 14:59:43.933 06: --> spa_all_configs:entry > 0 100979 2012 Jul 12 14:59:43.933 07: --> nvlist_alloc:entry > 0 100979 2012 Jul 12 14:59:43.933 07: [...] > 0 100979 2012 Jul 12 14:59:43.933 07: <-- nvlist_alloc:return > 0 100979 2012 Jul 12 14:59:43.933 07: --> _sx_xlock:entry > 0 100979 2012 Jul 12 14:59:43.933 08: --> _sx_xlock_hard:entry > 0 100979 2012 Jul 12 14:59:43.933 09: --> sleepq_lock:entry > 0 100979 2012 Jul 12 14:59:43.933 10: --> spinlock_enter:entry > 0 100979 2012 Jul 12 14:59:43.933 10: --> critical_enter:entry > 0 100979 2012 Jul 12 14:59:43.933 10: <-- critical_enter:return > 0 100979 2012 Jul 12 14:59:43.933 09: <-- sleepq_lock:return > 0 100979 2012 Jul 12 14:59:43.933 09: --> lockstat_nsecs:entry > 0 100979 2012 Jul 12 14:59:43.933 10: --> binuptime:entry > 0 100979 2012 Jul 12 14:59:43.933 11: --> hpet_get_timecount:entry > 0 100979 2012 Jul 12 14:59:43.933 11: <-- hpet_get_timecount:return > 0 100979 2012 Jul 12 14:59:43.933 10: <-- binuptime:return > 0 100979 2012 Jul 12 14:59:43.933 09: <-- lockstat_nsecs:return > 0 100979 2012 Jul 12 14:59:43.933 09: --> sleepq_add:entry > 0 100979 2012 Jul 12 14:59:43.933 10: --> sleepq_lookup:entry > 0 100979 2012 Jul 12 14:59:43.933 10: <-- sleepq_lookup:return > 0 100979 2012 Jul 12 14:59:43.933 10: --> thread_lock_flags_:entry > 0 100979 2012 Jul 12 14:59:43.933 11: --> spinlock_enter:entry > 0 100979 2012 Jul 12 14:59:43.933 11: --> critical_enter:entry > 0 100979 2012 Jul 12 14:59:43.933 11: <-- critical_enter:return > 0 100979 2012 Jul 12 14:59:43.933 10: <-- thread_lock_flags_:return > 0 100979 2012 Jul 12 14:59:43.933 09: --> spinlock_exit:entry > 0 100979 2012 Jul 12 14:59:43.933 10: --> critical_exit:entry > 0 100979 2012 Jul 12 14:59:43.933 10: <-- critical_exit:return > 0 100979 2012 Jul 12 14:59:43.933 09: <-- spinlock_exit:return > 0 100979 2012 Jul 12 14:59:43.933 09: --> sleepq_wait:entry > 0 100979 2012 Jul 12 14:59:43.933 10: --> thread_lock_flags_:entry > 0 100979 2012 Jul 12 14:59:43.933 11: --> spinlock_enter:entry > 0 100979 2012 Jul 12 14:59:43.933 11: --> critical_enter:entry > 0 100979 2012 Jul 12 14:59:43.933 11: <-- critical_enter:return > 0 100979 2012 Jul 12 14:59:43.933 10: <-- thread_lock_flags_:return > 0 100979 2012 Jul 12 14:59:43.933 10: --> sleepq_switch:entry > 0 100979 2012 Jul 12 14:59:43.933 11: --> sched_sleep:entry > 0 100979 2012 Jul 12 14:59:43.933 11: <-- sched_sleep:return > 0 100979 2012 Jul 12 14:59:43.933 11: --> thread_lock_set:entry > 0 100979 2012 Jul 12 14:59:43.933 11: --> spinlock_exit:entry > 0 100979 2012 Jul 12 14:59:43.933 12: --> critical_exit:entry > 0 100979 2012 Jul 12 14:59:43.933 12: <-- critical_exit:return > 0 100979 2012 Jul 12 14:59:43.933 11: <-- spinlock_exit:return > 0 100979 2012 Jul 12 14:59:43.933 10: --> mi_switch:entry > 0 100979 2012 Jul 12 14:59:43.933 11: --> rdtsc:entry > 0 100979 2012 Jul 12 14:59:43.933 11: <-- rdtsc:return > 0 100979 2012 Jul 12 14:59:43.933 11: --> sched_switch:entry > 0 100979 2012 Jul 12 14:59:43.933 12: --> sched_pctcpu_update:entry > 0 100979 2012 Jul 12 14:59:43.933 12: <-- sched_pctcpu_update:return > 0 100979 2012 Jul 12 14:59:43.933 12: --> spinlock_enter:entry > 0 100979 2012 Jul 12 14:59:43.933 12: --> critical_enter:entry > 0 100979 2012 Jul 12 14:59:43.933 12: <-- critical_enter:return > 0 100979 2012 Jul 12 14:59:43.933 12: --> thread_lock_block:entry > 0 100979 2012 Jul 12 14:59:43.933 13: --> spinlock_exit:entry > 0 100979 2012 Jul 12 14:59:43.933 14: --> critical_exit:entry > 0 100979 2012 Jul 12 14:59:43.933 14: <-- critical_exit:return > 0 100979 2012 Jul 12 14:59:43.933 13: <-- spinlock_exit:return > 0 100979 2012 Jul 12 14:59:43.933 12: <-- thread_lock_block:return > 0 100979 2012 Jul 12 14:59:43.933 12: --> tdq_load_rem:entry > 0 100979 2012 Jul 12 14:59:43.933 12: <-- tdq_load_rem:return > 0 100979 2012 Jul 12 14:59:43.933 12: --> choosethread:entry > 0 100979 2012 Jul 12 14:59:43.933 13: --> sched_choose:entry > 0 100979 2012 Jul 12 14:59:43.933 14: --> tdq_choose:entry > 0 100979 2012 Jul 12 14:59:43.933 15: --> runq_choose:entry > 0 100979 2012 Jul 12 14:59:43.933 15: <-- runq_choose:return > 0 100979 2012 Jul 12 14:59:43.933 15: --> runq_choose_from:entry > 0 100979 2012 Jul 12 14:59:43.933 15: <-- runq_choose_from:return > 0 100979 2012 Jul 12 14:59:43.933 14: --> runq_choose:entry > 0 100979 2012 Jul 12 14:59:43.933 14: <-- runq_choose:return > 0 100979 2012 Jul 12 14:59:43.933 13: <-- sched_choose:return > 0 100979 2012 Jul 12 14:59:43.933 12: <-- choosethread:return > 0 100979 2012 Jul 12 14:59:43.933 12: --> sched_pctcpu_update:entry > 0 100979 2012 Jul 12 14:59:43.933 12: <-- sched_pctcpu_update:return > > Of course once you know where ZFS is hanging you still have to figure > out the why ... > Thanks! I've made several changes to the volumes and rerunning my stuff now (started an hour ago). Rather than having a single volume of hodgepodge disks I now span two RAIDz pools of similar disks, partly because I was curious and partly because I thought it'd be fun. I also asserted ashift=12 and I have replaced/upgraded some of the disks. I have found, but not run, a bit of Seagate code that forces 4k sectors on the ST32000542AS disks -- they report 512 byte sectors but are really 4k. I also ran Seatools against some of my disks. Array now: iirc# zpool status disk-1 pool: disk-1 state: ONLINE scan: none requested config: NAME STATE READ WRITE CKSUM disk-1 ONLINE 0 0 0 raidz1-0 ONLINE 0 0 0 da2 ONLINE 0 0 0 da3 ONLINE 0 0 0 da4 ONLINE 0 0 0 da8 ONLINE 0 0 0 raidz1-1 ONLINE 0 0 0 da1 ONLINE 0 0 0 da5 ONLINE 0 0 0 da6 ONLINE 0 0 0 da7 ONLINE 0 0 0 da9 ONLINE 0 0 0 logs gpt/zil-disk1 ONLINE 0 0 0 cache ada1 ONLINE 0 0 0 errors: No known data errors -- Dennis Glatting <dg@pki2.com>
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?1342157639.60708.11.camel>