calcru: runtime went backwards

From: Gardner Bell <gbell72_at_rogers.com>
Date: Fri, 6 Jun 2008 15:11:00 -0400 (EDT)
Hello,

I'm seeing the following printed on my screen after my system became
unresponsive while background fsck was running for ~10 mins or so. 
Previous to this, my machine crashed after a power outage in my
neighborhood.

Copyright (c) 1992-2008 The FreeBSD Project.
Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993,
1994
        The Regents of the University of California. All rights
reserved.
FreeBSD is a registered trademark of The FreeBSD Foundation.
FreeBSD 8.0-CURRENT #0: Wed May 28 10:43:47 EDT 2008
    root_at_home:/usr/obj/usr/src/sys/TYAN

lock order reversal:
 1st 0xffffff0001282430 snaplk (snaplk) _at_
/usr/src/sys/kern/vfs_vnops.c:292
 2nd 0xffffff0001750270 ufs (ufs) _at_
/usr/src/sys/ufs/ffs/ffs_snapshot.c:1578
KDB: stack backtrace:
db_trace_self_wrapper() at db_trace_self_wrapper+0x2a
witness_checkorder() at witness_checkorder+0x665
__lockmgr_args() at __lockmgr_args+0x521
ffs_snapremove() at ffs_snapremove+0xe7
softdep_releasefile() at softdep_releasefile+0x139
ufs_inactive() at ufs_inactive+0x1ea
vinactive() at vinactive+0x72
vput() at vput+0x22b
vn_close() at vn_close+0xbb
vn_closefile() at vn_closefile+0x80
_fdrop() at _fdrop+0x23
closef() at closef+0x1e2
kern_close() at kern_close+0x10c
syscall() at syscall+0x1bf
Xfast_syscall() at Xfast_syscall+0xab
--- syscall (6, FreeBSD ELF64, close), rip = 0x80081789c, rsp =
0x7ffffffee6b8, rbp = 0x80 ---
KDB: enter: witness_checkorder
exclusive lockmgr snaplk r = 0 (0xffffff0001282430) locked _at_
/usr/src/sys/kern/vfs_vnops.c:292
exclusive lockmgr snaplk r = 0 (0xffffff0001282430) locked _at_
/usr/src/sys/kern/vfs_vnops.c:292

0xffffff00013c01d8: tag ufs, type VREG
    usecount 1, writecount 0, refcount 2 mountedhere 0
    flags (VV_SYSTEM)
     lock type snaplk: EXCL by thread 0xffffff0001289360 (pid 1013)

        ino 5, on dev ad0s1h

0xffffff00013c0000: tag ufs, type VREG
    usecount 1, writecount 0, refcount 1569 mountedhere 0
    flags (VV_SYSTEM)
     lock type snaplk: EXCL by thread 0xffffff0001289360 (pid 1013)

        ino 6, on dev ad0s1h

0xffffff0001382ce8: tag ufs, type VREG
    usecount 1, writecount 0, refcount 1736 mountedhere 0
    flags (VV_SYSTEM)
     lock type snaplk: EXCL by thread 0xffffff0001289360 (pid 1013)

        ino 4, on dev ad0s1h

0xffffff0001382b10: tag ufs, type VREG
    usecount 1, writecount 0, refcount 1736 mountedhere 0
    flags (VV_SYSTEM)
     lock type snaplk: EXCL by thread 0xffffff0001289360 (pid 1013)

        ino 7, on dev ad0s1h

0xffffff00017501d8: tag ufs, type VREG
    usecount 0, writecount 0, refcount 2063 mountedhere 0
    flags (VV_SYSTEM|VI_DOINGINACT)
    v_object 0xffffff0001739bb8 ref 0 pages 80
     lock type snaplk: EXCL by thread 0xffffff0001289360 (pid 1013)

        ino 8, on dev ad0s1h

0xffffff00013c01d8: tag ufs, type VREG
    usecount 1, writecount 0, refcount 2 mountedhere 0
    flags (VV_SYSTEM)
     lock type snaplk: EXCL by thread 0xffffff0001289360 (pid 1013)

        ino 5, on dev ad0s1h

0xffffff00013c0000: tag ufs, type VREG
    usecount 1, writecount 0, refcount 1569 mountedhere 0
    flags (VV_SYSTEM)
     lock type snaplk: EXCL by thread 0xffffff0001289360 (pid 1013)

        ino 6, on dev ad0s1h

0xffffff0001382ce8: tag ufs, type VREG
    usecount 1, writecount 0, refcount 1736 mountedhere 0
    flags (VV_SYSTEM)
     lock type snaplk: EXCL by thread 0xffffff0001289360 (pid 1013)

        ino 4, on dev ad0s1h

0xffffff0001382b10: tag ufs, type VREG
    usecount 1, writecount 0, refcount 1736 mountedhere 0
    flags (VV_SYSTEM)
     lock type snaplk: EXCL by thread 0xffffff0001289360 (pid 1013)

        ino 7, on dev ad0s1h

0xffffff00017501d8: tag ufs, type VREG
    usecount 0, writecount 0, refcount 2063 mountedhere 0
    flags (VV_SYSTEM|VI_DOINGINACT)
    v_object 0xffffff0001739bb8 ref 0 pages 80
     lock type snaplk: EXCL by thread 0xffffff0001289360 (pid 1013)

        ino 8, on dev ad0s1h
exclusive lockmgr snaplk r = 0 (0xffffff0001282430) locked _at_
/usr/src/sys/kern/vfs_vnops.c:292
exclusive lockmgr snaplk r = 0 (0xffffff0001282430) locked _at_
/usr/src/sys/kern/vfs_vnops.c:292
calcru: runtime went backwards from 33275 usec to 290 usec for pid 999
(csh)
calcru: runtime went backwards from 469322 usec to 3929 usec for pid
999 (csh)
calcru: runtime went backwards from 13323 usec to 109 usec for pid 998
(su)
calcru: runtime went backwards from 22204 usec to 182 usec for pid 996
(csh)
calcru: runtime went backwards from 931 usec to 7 usec for pid 996
(csh)
calcru: runtime went backwards from 7439 usec to 63 usec for pid 995
(getty)
calcru: runtime went backwards from 7745 usec to 63 usec for pid 994
(getty)
calcru: runtime went backwards from 24782 usec to 204 usec for pid 993
(login)
calcru: runtime went backwards from 6403 usec to 58 usec for pid 937
(cron)
calcru: runtime went backwards from 23019 usec to 258 usec for pid 910
(ntpd)
calcru: runtime went backwards from 11411 usec to 127 usec for pid 809
(syslogd)
calcru: runtime went backwards from 1536 usec to 12 usec for pid 742
(natd)
calcru: runtime went backwards from 376 usec to 3 usec for pid 686
(devd)
calcru: runtime went backwards from 1019 usec to 8 usec for pid 140
(adjkerntz)
calcru: runtime went backwards from 6097 usec to 1477 usec for pid 20
(softdepflush)
calcru: runtime went backwards from 26107 usec to 404 usec for pid 19
(syncer)
calcru: runtime went backwards from 10580 usec to 99 usec for pid 18
(vnlru)
calcru: runtime went backwards from 1251 usec to 19 usec for pid 9
(bufdaemon)
calcru: runtime went backwards from 8 usec to 0 usec for pid 8
(pagezero)
calcru: runtime went backwards from 18 usec to 0 usec for pid 7
(vmdaemon)
calcru: runtime went backwards from 508 usec to 6 usec for pid 6
(pagedaemon)
calcru: runtime went backwards from 39 usec to 0 usec for pid 17 (usb1)
calcru: runtime went backwards from 73 usec to 0 usec for pid 14 (usb0)
calcru: runtime went backwards from 17290 usec to 285 usec for pid 13
(yarrow)
calcru: runtime went backwards from 287038 usec to 4917 usec for pid 4
(g_down)
calcru: runtime went backwards from 355326 usec to 5779 usec for pid 3
(g_up)
calcru: runtime went backwards from 19316 usec to 251 usec for pid 2
(g_event)
calcru: runtime went backwards from 313682281 usec to 5240711 usec for
pid 11 (idle)
calcru: runtime went backwards from 432516 usec to 3561 usec for pid 1
(init)
calcru: runtime went backwards from 11606 usec to 95 usec for pid 0 (kernel)
Received on Fri Jun 06 2008 - 17:11:01 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:39:31 UTC