Re: CAM hangs in 9-STABLE? [Was: NFS/ZFS hangs after upgrading from 9.0-RELEASE to -STABLE]
Dear All, Still experiencing the same hangs I reported earlier with 9.1. I've been running a kernel with WITNESS enabled to provide more information. During an occurrence of the hang, running show alllocks gave Process 25777 (sysctl) thread 0xfe014c5b2920 (102567) exclusive sleep mutex Giant (Giant) r = 0 (0x811e34c0) locked @ /usr/src/sys/dev/usb/usb_transfer.c:3171 Process 25750 (sshd) thread 0xfe015a688000 (104313) exclusive sx so_rcv_sx (so_rcv_sx) r = 0 (0xfe0204e0bb98) locked @ /usr/src/sys/kern/uipc_sockbuf.c:148 Process 24922 (cnid_dbd) thread 0xfe0187ac4920 (103597) shared lockmgr zfs (zfs) r = 0 (0xfe0973062488) locked @ /usr/src/sys/kern/vfs_syscalls.c:3591 Process 24117 (sshd) thread 0xfe07bd914490 (104195) exclusive sx so_rcv_sx (so_rcv_sx) r = 0 (0xfe0204e0a8f0) locked @ /usr/src/sys/kern/uipc_sockbuf.c:148 Process 1243 (java) thread 0xfe01ca85d000 (102704) exclusive sleep mutex pmap (pmap) r = 0 (0xfe015aec1440) locked @ /usr/src/sys/amd64/amd64/pmap.c:4840 exclusive rw pmap pv global (pmap pv global) r = 0 (0x81409780) locked @ /usr/src/sys/amd64/amd64/pmap.c:4802 exclusive sleep mutex vm page (vm page) r = 0 (0x813f0a80) locked @ /usr/src/sys/vm/vm_object.c:1128 exclusive sleep mutex vm object (standard object) r = 0 (0xfe01458e43a0) locked @ /usr/src/sys/vm/vm_object.c:1076 shared sx vm map (user) (vm map (user)) r = 0 (0xfe015aec1388) locked @ /usr/src/sys/vm/vm_map.c:2045 Process 994 (nfsd) thread 0xfe015a0df000 (102426) shared lockmgr zfs (zfs) r = 0 (0xfe0c3b505878) locked @ /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vfsops.c:1760 Process 994 (nfsd) thread 0xfe015a0f8490 (102422) exclusive lockmgr zfs (zfs) r = 0 (0xfe02db3b3e60) locked @ /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vfsops.c:1760 Process 931 (syslogd) thread 0xfe015af18920 (102365) shared lockmgr zfs (zfs) r = 0 (0xfe0141dd6680) locked @ /usr/src/sys/kern/vfs_syscalls.c:3591 Process 22 (syncer) thread 0xfe0125077000 (100279) exclusive lockmgr syncer (syncer) r = 0 (0xfe015a2ff680) locked @ /usr/src/sys/kern/vfs_subr.c:1809 I don't have full show lockedvnods output because the output does not get captured by ddb after using capture on, it doesn't fit on a single screen, and doesn't get piped into a more equivalent. What I did manage to get (copied by hand, typos possible) is: 0xfe0c3b5057e0: 0xfe0c3b5057e0: tag zfs, type VREG tag zfs, type VREG usecount 1, writecount 0, refcount 1 mountedhere 0 usecount 1, writecount 0, refcount 1 mountedhere 0 flags (VI_ACTIVE) flags (VI_ACTIVE) v_object 0xfe089bc1b828 ref 0 pages 0 v_object 0xfe089bc1b828 ref 0 pages 0 lock type zfs: SHARED (count 1) lock type zfs: SHARED (count 1) 0xfe02db3b3dc8: 0xfe02db3b3dc8: tag zfs, type VREG tag zfs, type VREG usecount 6, writecount 0, refcount 6 mountedhere 0 usecount 6, writecount 0, refcount 6 mountedhere 0 flags (VI_ACTIVE) flags (VI_ACTIVE) v_object 0xfe0b79583ae0 ref 0 pages 0 v_object 0xfe0b79583ae0 ref 0 pages 0 lock type zfs: EXCL by thread 0xfe015a0f8490 (pid 994) lock type zfs: EXCL by thread 0xfe015a0f8490 (pid 994) with exclusive waiters pending with exclusive waiters pending The output of show witness is at http://pastebin.com/eSRb3FEu The output of alltrace is at http://pastebin.com/X1LruNrf (a number of threads are stuck in zio_wait, none I can find in zio_interrupt, and according to gstat and disks eventually going to sleep all disk IO seems to be stuck for good; I think Andriy explained earlier that these criteria might indicate this is a ZFS hang). The output of show geom is at http://pastebin.com/6nwQbKr4 The output of vmstat -i is at http://pastebin.com/9LcZ7Mi0 Interrupts are occurring at a normal rate during the hang, as far as I can tell. Any help would be greatly appreciated. Thanks Olivier PS: my kernel was compiled from 9-STABLE from December, with CAM and ahci from 9.0 (in the hope it would fix the hangs I was experiencing in plain 9-STABLE; obviously the hangs are still occurring). The rest of my configuration is the same as posted earlier. On Mon, Dec 24, 2012 at 9:42 PM, olivier olivier77...@gmail.com wrote: Dear All It turns out that reverting to an older version of the mps driver did not fix the ZFS hangs I've been struggling with in 9.1 and 9-STABLE after all (they just took a bit longer to occur again, possibly just by chance). I followed steps along lines suggested by Andriy to collect more information when the problem occurs. Hopefully this will help figure out what's going on. As far as I can tell, what happens is that at some point IO operations to a bunch of drives that belong to different pools get stuck. For these drives, gstat shows no activity but 1 pending operation, as such: L(q) ops/sr/s kBps ms/rw/s kBps ms/wd/s kBps ms/d %busy Name 1
Re: CAM hangs in 9-STABLE? [Was: NFS/ZFS hangs after upgrading from 9.0-RELEASE to -STABLE]
I don't know if this is relevant or not, but I deadlock was recently fixed in the VFS code: http://svnweb.freebsd.org/base?view=revisionrevision=244795 On Tue, Jan 15, 2013 at 12:55 PM, olivier olivier77...@gmail.com wrote: Dear All, Still experiencing the same hangs I reported earlier with 9.1. I've been running a kernel with WITNESS enabled to provide more information. During an occurrence of the hang, running show alllocks gave Process 25777 (sysctl) thread 0xfe014c5b2920 (102567) exclusive sleep mutex Giant (Giant) r = 0 (0x811e34c0) locked @ /usr/src/sys/dev/usb/usb_transfer.c:3171 Process 25750 (sshd) thread 0xfe015a688000 (104313) exclusive sx so_rcv_sx (so_rcv_sx) r = 0 (0xfe0204e0bb98) locked @ /usr/src/sys/kern/uipc_sockbuf.c:148 Process 24922 (cnid_dbd) thread 0xfe0187ac4920 (103597) shared lockmgr zfs (zfs) r = 0 (0xfe0973062488) locked @ /usr/src/sys/kern/vfs_syscalls.c:3591 Process 24117 (sshd) thread 0xfe07bd914490 (104195) exclusive sx so_rcv_sx (so_rcv_sx) r = 0 (0xfe0204e0a8f0) locked @ /usr/src/sys/kern/uipc_sockbuf.c:148 Process 1243 (java) thread 0xfe01ca85d000 (102704) exclusive sleep mutex pmap (pmap) r = 0 (0xfe015aec1440) locked @ /usr/src/sys/amd64/amd64/pmap.c:4840 exclusive rw pmap pv global (pmap pv global) r = 0 (0x81409780) locked @ /usr/src/sys/amd64/amd64/pmap.c:4802 exclusive sleep mutex vm page (vm page) r = 0 (0x813f0a80) locked @ /usr/src/sys/vm/vm_object.c:1128 exclusive sleep mutex vm object (standard object) r = 0 (0xfe01458e43a0) locked @ /usr/src/sys/vm/vm_object.c:1076 shared sx vm map (user) (vm map (user)) r = 0 (0xfe015aec1388) locked @ /usr/src/sys/vm/vm_map.c:2045 Process 994 (nfsd) thread 0xfe015a0df000 (102426) shared lockmgr zfs (zfs) r = 0 (0xfe0c3b505878) locked @ /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vfsops.c:1760 Process 994 (nfsd) thread 0xfe015a0f8490 (102422) exclusive lockmgr zfs (zfs) r = 0 (0xfe02db3b3e60) locked @ /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vfsops.c:1760 Process 931 (syslogd) thread 0xfe015af18920 (102365) shared lockmgr zfs (zfs) r = 0 (0xfe0141dd6680) locked @ /usr/src/sys/kern/vfs_syscalls.c:3591 Process 22 (syncer) thread 0xfe0125077000 (100279) exclusive lockmgr syncer (syncer) r = 0 (0xfe015a2ff680) locked @ /usr/src/sys/kern/vfs_subr.c:1809 I don't have full show lockedvnods output because the output does not get captured by ddb after using capture on, it doesn't fit on a single screen, and doesn't get piped into a more equivalent. What I did manage to get (copied by hand, typos possible) is: 0xfe0c3b5057e0: 0xfe0c3b5057e0: tag zfs, type VREG tag zfs, type VREG usecount 1, writecount 0, refcount 1 mountedhere 0 usecount 1, writecount 0, refcount 1 mountedhere 0 flags (VI_ACTIVE) flags (VI_ACTIVE) v_object 0xfe089bc1b828 ref 0 pages 0 v_object 0xfe089bc1b828 ref 0 pages 0 lock type zfs: SHARED (count 1) lock type zfs: SHARED (count 1) 0xfe02db3b3dc8: 0xfe02db3b3dc8: tag zfs, type VREG tag zfs, type VREG usecount 6, writecount 0, refcount 6 mountedhere 0 usecount 6, writecount 0, refcount 6 mountedhere 0 flags (VI_ACTIVE) flags (VI_ACTIVE) v_object 0xfe0b79583ae0 ref 0 pages 0 v_object 0xfe0b79583ae0 ref 0 pages 0 lock type zfs: EXCL by thread 0xfe015a0f8490 (pid 994) lock type zfs: EXCL by thread 0xfe015a0f8490 (pid 994) with exclusive waiters pending with exclusive waiters pending The output of show witness is at http://pastebin.com/eSRb3FEu The output of alltrace is at http://pastebin.com/X1LruNrf (a number of threads are stuck in zio_wait, none I can find in zio_interrupt, and according to gstat and disks eventually going to sleep all disk IO seems to be stuck for good; I think Andriy explained earlier that these criteria might indicate this is a ZFS hang). The output of show geom is at http://pastebin.com/6nwQbKr4 The output of vmstat -i is at http://pastebin.com/9LcZ7Mi0 Interrupts are occurring at a normal rate during the hang, as far as I can tell. Any help would be greatly appreciated. Thanks Olivier PS: my kernel was compiled from 9-STABLE from December, with CAM and ahci from 9.0 (in the hope it would fix the hangs I was experiencing in plain 9-STABLE; obviously the hangs are still occurring). The rest of my configuration is the same as posted earlier. On Mon, Dec 24, 2012 at 9:42 PM, olivier olivier77...@gmail.com wrote: Dear All It turns out that reverting to an older version of the mps driver did not fix the ZFS hangs I've been struggling with in 9.1 and 9-STABLE after all (they just took a bit longer to occur again, possibly just by chance). I followed steps along lines suggested by Andriy to collect more information when the problem occurs. Hopefully this will help figure out what's going on.
Re: CAM hangs in 9-STABLE? [Was: NFS/ZFS hangs after upgrading from 9.0-RELEASE to -STABLE]
My understanding is that the locks (and pieces of kernel code) involved are different. Maybe someone more knowledgeable than I am can comment. Thanks for the suggestion... Olivier On Tue, Jan 15, 2013 at 4:07 PM, Reed A. Cartwright cartwri...@asu.eduwrote: I don't know if this is relevant or not, but I deadlock was recently fixed in the VFS code: http://svnweb.freebsd.org/base?view=revisionrevision=244795 On Tue, Jan 15, 2013 at 12:55 PM, olivier olivier77...@gmail.com wrote: Dear All, Still experiencing the same hangs I reported earlier with 9.1. I've been running a kernel with WITNESS enabled to provide more information. During an occurrence of the hang, running show alllocks gave Process 25777 (sysctl) thread 0xfe014c5b2920 (102567) exclusive sleep mutex Giant (Giant) r = 0 (0x811e34c0) locked @ /usr/src/sys/dev/usb/usb_transfer.c:3171 Process 25750 (sshd) thread 0xfe015a688000 (104313) exclusive sx so_rcv_sx (so_rcv_sx) r = 0 (0xfe0204e0bb98) locked @ /usr/src/sys/kern/uipc_sockbuf.c:148 Process 24922 (cnid_dbd) thread 0xfe0187ac4920 (103597) shared lockmgr zfs (zfs) r = 0 (0xfe0973062488) locked @ /usr/src/sys/kern/vfs_syscalls.c:3591 Process 24117 (sshd) thread 0xfe07bd914490 (104195) exclusive sx so_rcv_sx (so_rcv_sx) r = 0 (0xfe0204e0a8f0) locked @ /usr/src/sys/kern/uipc_sockbuf.c:148 Process 1243 (java) thread 0xfe01ca85d000 (102704) exclusive sleep mutex pmap (pmap) r = 0 (0xfe015aec1440) locked @ /usr/src/sys/amd64/amd64/pmap.c:4840 exclusive rw pmap pv global (pmap pv global) r = 0 (0x81409780) locked @ /usr/src/sys/amd64/amd64/pmap.c:4802 exclusive sleep mutex vm page (vm page) r = 0 (0x813f0a80) locked @ /usr/src/sys/vm/vm_object.c:1128 exclusive sleep mutex vm object (standard object) r = 0 (0xfe01458e43a0) locked @ /usr/src/sys/vm/vm_object.c:1076 shared sx vm map (user) (vm map (user)) r = 0 (0xfe015aec1388) locked @ /usr/src/sys/vm/vm_map.c:2045 Process 994 (nfsd) thread 0xfe015a0df000 (102426) shared lockmgr zfs (zfs) r = 0 (0xfe0c3b505878) locked @ /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vfsops.c:1760 Process 994 (nfsd) thread 0xfe015a0f8490 (102422) exclusive lockmgr zfs (zfs) r = 0 (0xfe02db3b3e60) locked @ /usr/src/sys/modules/zfs/../../cddl/contrib/opensolaris/uts/common/fs/zfs/zfs_vfsops.c:1760 Process 931 (syslogd) thread 0xfe015af18920 (102365) shared lockmgr zfs (zfs) r = 0 (0xfe0141dd6680) locked @ /usr/src/sys/kern/vfs_syscalls.c:3591 Process 22 (syncer) thread 0xfe0125077000 (100279) exclusive lockmgr syncer (syncer) r = 0 (0xfe015a2ff680) locked @ /usr/src/sys/kern/vfs_subr.c:1809 I don't have full show lockedvnods output because the output does not get captured by ddb after using capture on, it doesn't fit on a single screen, and doesn't get piped into a more equivalent. What I did manage to get (copied by hand, typos possible) is: 0xfe0c3b5057e0: 0xfe0c3b5057e0: tag zfs, type VREG tag zfs, type VREG usecount 1, writecount 0, refcount 1 mountedhere 0 usecount 1, writecount 0, refcount 1 mountedhere 0 flags (VI_ACTIVE) flags (VI_ACTIVE) v_object 0xfe089bc1b828 ref 0 pages 0 v_object 0xfe089bc1b828 ref 0 pages 0 lock type zfs: SHARED (count 1) lock type zfs: SHARED (count 1) 0xfe02db3b3dc8: 0xfe02db3b3dc8: tag zfs, type VREG tag zfs, type VREG usecount 6, writecount 0, refcount 6 mountedhere 0 usecount 6, writecount 0, refcount 6 mountedhere 0 flags (VI_ACTIVE) flags (VI_ACTIVE) v_object 0xfe0b79583ae0 ref 0 pages 0 v_object 0xfe0b79583ae0 ref 0 pages 0 lock type zfs: EXCL by thread 0xfe015a0f8490 (pid 994) lock type zfs: EXCL by thread 0xfe015a0f8490 (pid 994) with exclusive waiters pending with exclusive waiters pending The output of show witness is at http://pastebin.com/eSRb3FEu The output of alltrace is at http://pastebin.com/X1LruNrf (a number of threads are stuck in zio_wait, none I can find in zio_interrupt, and according to gstat and disks eventually going to sleep all disk IO seems to be stuck for good; I think Andriy explained earlier that these criteria might indicate this is a ZFS hang). The output of show geom is at http://pastebin.com/6nwQbKr4 The output of vmstat -i is at http://pastebin.com/9LcZ7Mi0 Interrupts are occurring at a normal rate during the hang, as far as I can tell. Any help would be greatly appreciated. Thanks Olivier PS: my kernel was compiled from 9-STABLE from December, with CAM and ahci from 9.0 (in the hope it would fix the hangs I was experiencing in plain 9-STABLE; obviously the hangs are still occurring). The rest of my configuration is the same as posted earlier. On Mon, Dec 24, 2012 at 9:42 PM, olivier olivier77...@gmail.com wrote: Dear All It turns out
CAM hangs in 9-STABLE? [Was: NFS/ZFS hangs after upgrading from 9.0-RELEASE to -STABLE]
Dear All It turns out that reverting to an older version of the mps driver did not fix the ZFS hangs I've been struggling with in 9.1 and 9-STABLE after all (they just took a bit longer to occur again, possibly just by chance). I followed steps along lines suggested by Andriy to collect more information when the problem occurs. Hopefully this will help figure out what's going on. As far as I can tell, what happens is that at some point IO operations to a bunch of drives that belong to different pools get stuck. For these drives, gstat shows no activity but 1 pending operation, as such: L(q) ops/sr/s kBps ms/rw/s kBps ms/wd/s kBps ms/d %busy Name 1 0 0 00.0 0 00.0 0 00.0 0.0 da1 I've been running gstat in a loop (every 100s) to monitor the machine. Just before the hang occurs, everything seems fine (see full gstat output below). Right after the hang occurs a number of drives seem stuck (see full gstat output below). Notably, some stuck drives are seen through the mps driver and others through the mpt driver. So the problem doesn't seem to be driver-specific. I have had the problem occur (at a lower frequency) on similar machines that don't use the mpt driver (and only have 1 disk provided through mps), so the problem doesn't seem to be caused by the mpt driver (and is likely not caused by defective hardware). Since based on the information I provided earlier Andriy thinks the problem might not originate in ZFS, perhaps that means that the problem is in the CAM layer? camcontrol tags -v (as suggested by Andriy) in the hung state shows for example (pass56:mpt1:0:8:20): dev_openings 254 (pass56:mpt1:0:8:20): dev_active1 (pass56:mpt1:0:8:20): devq_openings 254 (pass56:mpt1:0:8:20): devq_queued 0 (pass56:mpt1:0:8:20): held 0 (pass56:mpt1:0:8:20): mintags 2 (pass56:mpt1:0:8:20): maxtags 255 (I'm not providing full camcontrol tags output below because I couldn't get it to run during the specific hang I documented most thoroughly; the example above is from a different occurrence of the hang). The buses don't seem completely frozen: if I manually remove drives while the machine is hanging, that's picked up by the mpt driver, which prints out corresponding messages to the console. But camcontrol reset all or rescan all don't seem to do anything. I've tried reducing vfs.zfs.vdev.min_pending and vfs.zfs.vdev.max_pending to 1, to no avail. Any suggestions to resolve this problem, work around it, or further investigate it would be greatly appreciated! Thanks a lot Olivier Detailed information: Output of procstat -a -kk when the machine is hanging is available at http://pastebin.com/7D2KtT35 (not putting it here because it's pretty long) dmesg is available at http://pastebin.com/9zJQwWJG . Note that I'm using LUN masking, so the illegal requests reported aren't really errors. Maybe one day if I get my problems sorted out I'll use geom multipathing instead. My kernel config is include GENERIC ident MYKERNEL options IPSEC device crypto options OFED # Infiniband protocol device mlx4ib # ConnectX Infiniband support device mlxen # ConnectX Ethernet support device mthca # Infinihost cards device ipoib # IP over IB devices options ATA_CAM # Handle legacy controllers with CAM options ATA_STATIC_ID # Static device numbering options KDB options DDB Full output of gstat just before the hang (at most 100s before the hang): L(q) ops/sr/s kBps ms/rw/s kBps ms/wd/s kBps ms/d %busy Name 0 0 0 00.0 0 00.0 0 00.0 0.0 da2 0 0 0 00.0 0 00.0 0 00.0 0.0 da0 0 0 0 00.0 0 00.0 0 00.0 0.0 DEV/da2/da2 0 0 0 00.0 0 00.0 0 00.0 0.0 DEV/da0/da0 1 85 48 794.7 35 840.5 0 00.0 24.3 da1 0 0 0 00.0 0 00.0 0 00.0 0.0 DEV/da1/da1 1 83 47 774.3 34 790.5 0 00.0 22.1 da4 1 1324 1303 214330.6 19 420.7 0 00.0 79.8 da3 0 0 0 00.0 0 00.0 0 00.0 0.0 da5 0 0 0 00.0 0 00.0 0 00.0 0.0 da6 0 0 0 00.0 0 00.0 0 00.0 0.0 da7 0 0 0 00.0 0 00.0 0 00.0 0.0 da8 0 0 0 00.0 0 00.0 0 00.0 0.0 da9 0 0 0 00.0 0 00.0 0 00.0 0.0 da10 0 0 0 00.0 0 00.0 0 00.0 0.0 da11 0 0 0 00.0 0 0
