Date: Fri, 25 May 2007 21:01:07 -0400 From: "Andrew Edwards" <aedwards@sandvine.com> To: <freebsd-fs@freebsd.org>, <freebsd-performance@freebsd.org> Subject: RE: Ufs dead-locks on freebsd 6.2 Message-ID: <5230D3C40B842D4F9FB3CD368021BEF72F09AC@exchange-2.sandvine.com> In-Reply-To: <5230D3C40B842D4F9FB3CD368021BEF72F093F@exchange-2.sandvine.com>
next in thread | previous in thread | raw e-mail | index | archive | help
I guess I feel similar to Gore Jarold with his posting about being
frustrated with ufs. I have a serious problem, it's preventing me from
upgrading my production systems to freebsd 6+, I can reproduce this
problem easily but I can't seem to get anyone to assist me. At the
suggestion of one of our internal developers I have enabled memguard to
help find the cause of the panic and I'm posting the current backtrace
etc. as recommended from the developers handbook on debgging dead-locks.
If someone can help me it would be greatly appreciated.
db> bt
Tracing pid 26543 tid 105117 td 0xd41c6a80
kdb_enter(c0785f13) at kdb_enter+0x2b
vfs_badlock(c0785f2c,c0786051,cd3dc414) at vfs_badlock+0x47
assert_vop_locked(cd3dc414,c0786051) at assert_vop_locked+0x4a
vop_lock_post(fa048bec,0,1002,cd3dc414,fa048c08,...) at
vop_lock_post+0x2a
VOP_LOCK_APV(c07dc2e0,fa048bec) at VOP_LOCK_APV+0xa0
vn_lock(cd3dc414,1002,d41c6a80,0,0,...) at vn_lock+0xac
vn_statfile(cd3f0870,fa048c74,cd39f280,d41c6a80) at vn_statfile+0x63
kern_fstat(d41c6a80,3,fa048c74) at kern_fstat+0x35
fstat(d41c6a80,fa048d04) at fstat+0x19
syscall(3b,805003b,bfbf003b,8054000,8054000,...) at syscall+0x25b
Xint0x80_syscall() at Xint0x80_syscall+0x1f
--- syscall (189, FreeBSD ELF32, fstat), eip =3D 0x6814b08f, esp =3D
0xbfbfec2c, ebp =3D 0xbfbfeca8 ---
db> show pcpu
cpuid =3D 1
curthread =3D 0xd41c6a80: pid 26543 "cron"
curpcb =3D 0xfa048d90
fpcurthread =3D none
idlethread =3D 0xccb5c600: pid 10 "idle: cpu1"
APIC ID =3D 6
currentldt =3D 0x50
spin locks held:
db> show allpcpu
Current CPU: 1
cpuid =3D 0
curthread =3D 0xcd01ec00: pid 898 "cron"
curpcb =3D 0xf5ad7d90
fpcurthread =3D none
idlethread =3D 0xccb5c780: pid 11 "idle: cpu0"
APIC ID =3D 0
currentldt =3D 0x50
spin locks held:
cpuid =3D 1
curthread =3D 0xd41c6a80: pid 26543 "cron"
curpcb =3D 0xfa048d90
fpcurthread =3D none
idlethread =3D 0xccb5c600: pid 10 "idle: cpu1"
APIC ID =3D 6
currentldt =3D 0x50
spin locks held:
db> show locks
exclusive sx user map r =3D 0 (0xd4135734) locked @
/usr/src/sys/vm/vm_map.c:3074
db> show alllocks
Process 26543 (cron) thread 0xd41c6a80 (105117)
exclusive sx user map r =3D 0 (0xd4135734) locked @
/usr/src/sys/vm/vm_map.c:3074
db> show lockedvnods
Locked vnodes
0xce00cc3c: tag ufs, type VREG
usecount 1, writecount 1, refcount 11 mountedhere 0
flags ()
v_object 0xcdae9b58 ref 0 pages 96
lock type ufs: EXCL (count 1) by thread 0xccffb300 (pid 18081) with
1 pending#0 0xc0593f0d at lockmgr+0x4ed
#1 0xc06b8e0e at ffs_lock+0x76
#2 0xc0739787 at VOP_LOCK_APV+0x87
#3 0xc0601c28 at vn_lock+0xac
#4 0xc06015c4 at vn_write+0x138
#5 0xc05c4544 at dofilewrite+0x7c
#6 0xc05c43e3 at kern_writev+0x3b
#7 0xc05c4309 at write+0x45
#8 0xc0723e2b at syscall+0x25b
#9 0xc070ee0f at Xint0x80_syscall+0x1f
ino 494730, on dev amrd0s1d
0xccf936cc: tag ufs, type VDIR
usecount 1, writecount 0, refcount 2494 mountedhere 0
flags (VV_ROOT)
v_object 0xd18598c4 ref 0 pages 0
lock type ufs: EXCL (count 1) by thread 0xcdff7000 (pid 19300) with
2492 pending#0 0xc0593f0d at lockmgr+0x4ed
#1 0xc06b8e0e at ffs_lock+0x76
#2 0xc0739787 at VOP_LOCK_APV+0x87
#3 0xc0601c28 at vn_lock+0xac
#4 0xc05f5d12 at vget+0xbe
#5 0xc05ed9f9 at vfs_hash_get+0x8d
#6 0xc06b7b8f at ffs_vget+0x27
#7 0xc06c1435 at ufs_root+0x19
#8 0xc05eef1c at lookup+0x7c8
#9 0xc05ee4b2 at namei+0x39a
#10 0xc0600a13 at vn_open_cred+0x5b
#11 0xc06009b6 at vn_open+0x1e
#12 0xc05fa126 at kern_open+0xb6
#13 0xc05fa03a at open+0x1a
#14 0xc0723e2b at syscall+0x25b
#15 0xc070ee0f at Xint0x80_syscall+0x1f
ino 2, on dev amrd0s1d
0xcd00a000: tag ufs, type VDIR
usecount 1, writecount 0, refcount 3 mountedhere 0
flags ()
v_object 0xce083210 ref 0 pages 0
lock type ufs: EXCL (count 1) by thread 0xcd574d80 (pid 89705) with
1 pending#0 0xc0593f0d at lockmgr+0x4ed
#1 0xc06b8e0e at ffs_lock+0x76
#2 0xc0739787 at VOP_LOCK_APV+0x87
#3 0xc0601c28 at vn_lock+0xac
#4 0xc05f5d12 at vget+0xbe
#5 0xc05ea48e at cache_lookup+0x34a
#6 0xc05ea9c2 at vfs_cache_lookup+0x92
#7 0xc0737847 at VOP_LOOKUP_APV+0x87
#8 0xc05eebf8 at lookup+0x4a4
#9 0xc05ee4b2 at namei+0x39a
#10 0xc0600a13 at vn_open_cred+0x5b
#11 0xc06009b6 at vn_open+0x1e
#12 0xc05fa126 at kern_open+0xb6
#13 0xc05fa03a at open+0x1a
#14 0xc0723e2b at syscall+0x25b
#15 0xc070ee0f at Xint0x80_syscall+0x1f
ino 494592, on dev amrd0s1d
0xcd23f15c: tag ufs, type VREG
usecount 1, writecount 1, refcount 4 mountedhere 0
flags ()
v_object 0xcd16ec60 ref 0 pages 12
lock type ufs: EXCL (count 1) by thread 0xccff8300 (pid 713)#0
0xc0593f0d at lockmgr+0x4ed
#1 0xc06b8e0e at ffs_lock+0x76
#2 0xc0739787 at VOP_LOCK_APV+0x87
#3 0xc0601c28 at vn_lock+0xac
#4 0xc06015c4 at vn_write+0x138
#5 0xc05c4544 at dofilewrite+0x7c
#6 0xc05c43e3 at kern_writev+0x3b
#7 0xc05c4309 at write+0x45
#8 0xc0723e2b at syscall+0x25b
#9 0xc070ee0f at Xint0x80_syscall+0x1f
ino 494620, on dev amrd0s1d
0xd02a0984: tag ufs, type VREG
usecount 1, writecount 1, refcount 3 mountedhere 0
flags ()
v_object 0xcd89fad4 ref 0 pages 3
lock type ufs: EXCL (count 1) by thread 0xccffb000 (pid 603)#0
0xc0593f0d at lockmgr+0x4ed
#1 0xc06b8e0e at ffs_lock+0x76
#2 0xc0739787 at VOP_LOCK_APV+0x87
#3 0xc0601c28 at vn_lock+0xac
#4 0xc05fd950 at fsync+0x9c
#5 0xc0723e2b at syscall+0x25b
#6 0xc070ee0f at Xint0x80_syscall+0x1f
ino 188453, on dev amrd0s1d
0xd0b442b8: tag ufs, type VREG
usecount 1, writecount 1, refcount 2 mountedhere 0
flags ()
v_object 0xcffc88c4 ref 0 pages 1
lock type ufs: EXCL (count 1) by thread 0xcd590480 (pid 18304)#0
0xc0593f0d at lockmgr+0x4ed
#1 0xc06b8e0e at ffs_lock+0x76
#2 0xc0739787 at VOP_LOCK_APV+0x87
#3 0xc0601c28 at vn_lock+0xac
#4 0xc05fd950 at fsync+0x9c
#5 0xc0723e2b at syscall+0x25b
#6 0xc070ee0f at Xint0x80_syscall+0x1f
ino 424403, on dev amrd0s1d
0xd24d3c3c: tag ufs, type VREG
usecount 1, writecount 1, refcount 2 mountedhere 0
flags ()
v_object 0xd13b3ce4 ref 0 pages 1
lock type ufs: EXCL (count 1) by thread 0xcd59ec00 (pid 18735)#0
0xc0593f0d at lockmgr+0x4ed
#1 0xc06b8e0e at ffs_lock+0x76
#2 0xc0739787 at VOP_LOCK_APV+0x87
#3 0xc0601c28 at vn_lock+0xac
#4 0xc05fd950 at fsync+0x9c
#5 0xc0723e2b at syscall+0x25b
#6 0xc070ee0f at Xint0x80_syscall+0x1f
ino 424405, on dev amrd0s1d
0xd09d6414: tag ufs, type VREG
usecount 1, writecount 1, refcount 3 mountedhere 0
flags ()
v_object 0xcfd71b58 ref 0 pages 1
lock type ufs: EXCL (count 1) by thread 0xcd6cfc00 (pid 20083)#0
0xc0593f0d at lockmgr+0x4ed
#1 0xc06b8e0e at ffs_lock+0x76
#2 0xc0739787 at VOP_LOCK_APV+0x87
#3 0xc0601c28 at vn_lock+0xac
#4 0xc05fd950 at fsync+0x9c
#5 0xc0723e2b at syscall+0x25b
#6 0xc070ee0f at Xint0x80_syscall+0x1f
ino 424406, on dev amrd0s1d
0xce0762b8: tag ufs, type VREG
usecount 1, writecount 1, refcount 3 mountedhere 0
flags ()
v_object 0xd14fcdec ref 0 pages 1
lock type ufs: EXCL (count 1) by thread 0xcd01e000 (pid 17274)#0
0xc0593f0d at lockmgr+0x4ed
#1 0xc06b8e0e at ffs_lock+0x76
#2 0xc0739787 at VOP_LOCK_APV+0x87
#3 0xc0601c28 at vn_lock+0xac
#4 0xc05fd950 at fsync+0x9c
#5 0xc0723e2b at syscall+0x25b
#6 0xc070ee0f at Xint0x80_syscall+0x1f
ino 424408, on dev amrd0s1d
0xce91f414: tag ufs, type VREG
usecount 1, writecount 1, refcount 3 mountedhere 0
flags ()
v_object 0xd24af9cc ref 0 pages 1
lock type ufs: EXCL (count 1) by thread 0xce03d780 (pid 20575)#0
0xc0593f0d at lockmgr+0x4ed
#1 0xc06b8e0e at ffs_lock+0x76
#2 0xc0739787 at VOP_LOCK_APV+0x87
#3 0xc0601c28 at vn_lock+0xac
#4 0xc05fd950 at fsync+0x9c
#5 0xc0723e2b at syscall+0x25b
#6 0xc070ee0f at Xint0x80_syscall+0x1f
ino 424409, on dev amrd0s1d
0xd1701d98: tag ufs, type VREG
usecount 1, writecount 1, refcount 3 mountedhere 0
flags ()
v_object 0xd0c8d39c ref 0 pages 1
lock type ufs: EXCL (count 1) by thread 0xcd6ce180 (pid 21143)#0
0xc0593f0d at lockmgr+0x4ed
#1 0xc06b8e0e at ffs_lock+0x76
#2 0xc0739787 at VOP_LOCK_APV+0x87
#3 0xc0601c28 at vn_lock+0xac
#4 0xc05fd950 at fsync+0x9c
#5 0xc0723e2b at syscall+0x25b
#6 0xc070ee0f at Xint0x80_syscall+0x1f
ino 424411, on dev amrd0s1d
0xcedf7828: tag ufs, type VREG
usecount 1, writecount 1, refcount 3 mountedhere 0
flags ()
v_object 0xd2c37948 ref 0 pages 1
lock type ufs: EXCL (count 1) by thread 0xcd576000 (pid 21114)#0
0xc0593f0d at lockmgr+0x4ed
#1 0xc06b8e0e at ffs_lock+0x76
#2 0xc0739787 at VOP_LOCK_APV+0x87
#3 0xc0601c28 at vn_lock+0xac
#4 0xc05fd950 at fsync+0x9c
#5 0xc0723e2b at syscall+0x25b
#6 0xc070ee0f at Xint0x80_syscall+0x1f
ino 424412, on dev amrd0s1d
0xd1679570: tag ufs, type VREG
usecount 1, writecount 1, refcount 69 mountedhere 0
flags ()
v_object 0xd1fd0318 ref 0 pages 9308
lock type ufs: EXCL (count 1) by thread 0xcd59ea80 (pid 65735)#0
0xc0593f0d at lockmgr+0x4ed
#1 0xc06b8e0e at ffs_lock+0x76
#2 0xc0739787 at VOP_LOCK_APV+0x87
#3 0xc0601c28 at vn_lock+0xac
#4 0xc06015c4 at vn_write+0x138
#5 0xc05c4544 at dofilewrite+0x7c
#6 0xc05c43e3 at kern_writev+0x3b
#7 0xc05c4309 at write+0x45
#8 0xc0723e2b at syscall+0x25b
#9 0xc070ee0f at Xint0x80_syscall+0x1f
ino 112037039, on dev amrd1s1d
db> alltrace
Tracing command pid 26548 tid 105114 td 0xd41c7000
*** error reading from address b4ba72d3 ***
-----Original Message-----
From: owner-freebsd-fs@freebsd.org [mailto:owner-freebsd-fs@freebsd.org]
On Behalf Of Andrew Edwards
Sent: Tuesday, May 22, 2007 1:35 PM
To: freebsd-fs@freebsd.org; freebsd-performance@freebsd.org
Subject: RE: Ufs dead-locks on freebsd 6.2
It's been a couple of days with no response, how do I know if anyone is
looking into this problem?
> -----Original Message-----
> From: owner-freebsd-fs@freebsd.org
[mailto:owner-freebsd-fs@freebsd.org]
> On Behalf Of Andrew Edwards
> Sent: Saturday, May 19, 2007 12:34 AM
> To: freebsd-fs@freebsd.org; freebsd-performance@freebsd.org
> Subject: RE: Ufs dead-locks on freebsd 6.2
>=20
> Fsck didn't help but below is a list of processes that were stuck in=20
> disk. Also, one potential problem I've hit is I have mrtg scripts
that
> get launched from cron every min. MRTG is supposed to have a locking=20
> mechanism to prevent the same script from running at the same time but
I
> suspect since the filesystem was unaccessible the cron jobs just kept=20
> piling up and piling up until the system would eventually crash. I=20
> caught it when the load avg. was at 620 and killed all the cron's I=20
> could. That brought the load avg. down to under 1 however system is=20
> still taking up 30% of the processor time and the disks are basically=20
> idle. I can still do an ls -l on the root of all my mounted ufs and
nfs
> filesystems but on one it's taking a considerable amount longer than
the
> rest. This particular rsync that I was running is copying into the
/d2
> fs.
>=20
> The system is still running and I can make tpc connections and=20
> somethings I have running from inetd work but ssh stops responding
right
> away and I can't logon via the console. So, I've captured a core dump
> of the system and rebooted so that I could use it again. Are there
any
> suggestion as to what to do next? I'm debaiting installing an adaptec
> raid and rebuilding the system to see if I get the same problem, my=20
> worry is that it's the intel raid drivers that are causing this
problem
> and I have 4 other systems with the same card.
>=20
>=20
> PID TT STAT TIME COMMAND
> 2 ?? DL 0:04.86 [g_event]
> 3 ?? DL 2:05.90 [g_up]
> 4 ?? DL 1:07.95 [g_down]
> 5 ?? DL 0:00.00 [xpt_thrd]
> 6 ?? DL 0:00.00 [kqueue taskq]
> 7 ?? DL 0:00.00 [thread taskq]
> 8 ?? DL 0:06.96 [pagedaemon]
> 9 ?? DL 0:00.00 [vmdaemon]
> 15 ?? DL 0:22.28 [yarrow]
> 24 ?? DL 0:00.01 [usb0]
> 25 ?? DL 0:00.00 [usbtask]
> 27 ?? DL 0:00.01 [usb1]
> 29 ?? DL 0:00.01 [usb2]
> 36 ?? DL 1:28.73 [pagezero]
> 37 ?? DL 0:08.76 [bufdaemon]
> 38 ?? DL 0:00.54 [vnlru]
> 39 ?? DL 1:08.12 [syncer]
> 40 ?? DL 0:04.00 [softdepflush]
> 41 ?? DL 0:11.05 [schedcpu]
> 27182 ?? Ds 0:05.75 /usr/sbin/syslogd -l /var/run/log -l
> /var/named/var/run/log -b 127.0.0.1 -a 10.128.0.0/10
> 27471 ?? Is 0:01.10 /usr/local/bin/postmaster -D
> /usr/local/pgsql/data (postgres)
> 27594 ?? Is 0:00.04 /usr/libexec/ftpd -m -D -l -l
> 27602 ?? DL 0:00.28 [smbiod1]
> 96581 ?? D 0:00.00 cron: running job (cron)
> 96582 ?? D 0:00.00 cron: running job (cron)
> 96583 ?? D 0:00.00 cron: running job (cron)
> 96585 ?? D 0:00.00 cron: running job (cron)
> 96586 ?? D 0:00.00 cron: running job (cron)
> 96587 ?? D 0:00.00 cron: running job (cron)
> 96588 ?? D 0:00.00 cron: running job (cron)
> 96589 ?? D 0:00.00 cron: running job (cron)
> 96590 ?? D 0:00.00 cron: running job (cron)
> 96591 ?? D 0:00.00 cron: running job (cron)
> 96592 ?? D 0:00.00 cron: running job (cron)
> 96593 ?? D 0:00.00 cron: running job (cron)
> 96594 ?? D 0:00.00 cron: running job (cron)
> 96607 ?? D 0:00.00 cron: running job (cron)
> 96608 ?? D 0:00.00 cron: running job (cron)
> 96609 ?? D 0:00.00 cron: running job (cron)
> 96610 ?? D 0:00.00 cron: running job (cron)
> 96611 ?? D 0:00.00 cron: running job (cron)
> 96612 ?? D 0:00.00 cron: running job (cron)
> 96613 ?? D 0:00.00 cron: running job (cron)
> 96614 ?? D 0:00.00 cron: running job (cron)
> 96615 ?? D 0:00.00 cron: running job (cron)
> 96616 ?? D 0:00.00 cron: running job (cron)
> 96617 ?? D 0:00.00 cron: running job (cron)
> 96631 ?? D 0:00.00 cron: running job (cron)
> 96632 ?? D 0:00.00 cron: running job (cron)
> 96633 ?? D 0:00.00 cron: running job (cron)
> 96634 ?? D 0:00.00 cron: running job (cron)
> 96635 ?? D 0:00.00 cron: running job (cron)
> 96636 ?? D 0:00.00 cron: running job (cron)
> 96637 ?? D 0:00.00 cron: running job (cron)
> 96638 ?? D 0:00.00 cron: running job (cron)
> 96639 ?? D 0:00.00 cron: running job (cron)
> 96642 ?? D 0:00.00 cron: running job (cron)
> 96650 ?? D 0:00.00 cron: running job (cron)
> 29393 p0 D+ 22:04.58 /usr/local/bin/rsync
>=20
> real 0m0.012s
> user 0m0.000s
> sys 0m0.010s
> /
>=20
> real 0m0.019s
> user 0m0.000s
> sys 0m0.016s
> /var
>=20
> real 0m0.028s
> user 0m0.008s
> sys 0m0.018s
> /diskless
>=20
> real 0m0.017s
> user 0m0.008s
> sys 0m0.007s
> /usr
>=20
> real 0m0.016s
> user 0m0.000s
> sys 0m0.015s
> /d2
>=20
> real 0m0.024s
> user 0m0.000s
> sys 0m0.023s
> /exports/home
>=20
> real 0m2.559s
> user 0m0.216s
> sys 0m2.307s
>=20
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?5230D3C40B842D4F9FB3CD368021BEF72F09AC>