excessive calcru warnings (negative runtime/runtime went backwards)

Tue Nov 9 00:55:04 PST 2004

Howdy,

For starters, uname -a gives
FreeBSD reactor.bombsession.com 5.3-RELEASE FreeBSD 5.3-RELEASE #0: Fri 
Nov  5 04:19:18 UTC 2004 
root at harlow.cse.buffalo.edu:/usr/obj/usr/src/sys/GENERIC  i386

After an install of 5.3-Release on a freshly formatted drive, I am 
getting loads of calcru errors:

calcru: negative runtime of -<someNumber> usecs for pid <pid> (<process>)
calcru: runtime went backwards from <someNumber> usecs to <someNumber> 
usecs for pid <pid> (<process>)

Nothing seems wrong with the system's ability to keep time correctly, 
and the system is not SMP, so a lot of the info I've found doesn't 
exactly apply.  The system doesn't freeze or become unstable, though I 
haven't done much with it.  This same hardware did not have the problem 
with FreeBSD 4.9-Release.  I understand there were some changes to 
things timecounter going into 5.0, and I'm skeptical this is a hardware 
problem.  The messages are so frequent they can't be ignored.  As far as 
timekeeping goes, my hardware clock is set to UTC, the system keeps CST 
-600 time just fine and is not set up to sync with a timeserver.

There are two FAQ entries that may apply.
http://www.freebsd.org/doc/en_US.ISO8859-1/books/faq/troubleshoot.html#CALCRU-NEGATIVE

sysctl kern.timecounter.method no longer exists, and I don't find the 
NTIMECOUNTER option in the GENERIC conf.  Is the NTIMECOUNTER option 
something I can/should add (if so I'd love advice on the placing if it 
matters) or is it outdated as well?

http://www.freebsd.org/doc/en_US.ISO8859-1/books/faq/troubleshoot.html#LAPTOP-CLOCK-SKEW

I thought this might be related, but the behavior doesn't change with 
kern.timecounter.hardware set to ACPI-safe (the default), TSC, or i8254. 
  I see all three in dmesg:
Timecounter "i8254" frequency 1193182 Hz quality 0
Timecounter "ACPI-safe" frequency 3579545 Hz quality 1000
Timecounter "TSC" frequency 450130973 Hz quality 800

ps shows -2341043 in each negative entry like
   PID  TT  STAT      TIME COMMAND
    30  ??  DL   -2341043:-52.36 [yarrow]
and it doesn't seem to discriminate among processes, showing 15-30 such 
negative-timed processes with each ps.

Even the dmesg below doesn't isn't complete because there are too many 
calcru errors.  sorry for the length, nothing follows.  Thanks for any 
help; please let me know if there's a better forum for my problem or if 
I can provide any further info.
-----------------
Copyright (c) 1992-2004 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 5.3-RELEASE #0: Fri Nov  5 04:19:18 UTC 2004
     root at harlow.cse.buffalo.edu:/usr/obj/usr/src/sys/GENERIC
Timecounter "i8254" frequency 1193182 Hz quality 0
CPU: AMD-K6(tm) 3D processor (450.13-MHz 586-class CPU)
   Origin = "AuthenticAMD"  Id = 0x58c  Stepping = 12
   Features=0x8021bf<FPU,VME,DE,PSE,TSC,MSR,MCE,CX8,PGE,MMX>
   AMD Features=0x80000800<SYSCALL,3DNow!>
real memory  = 327155712 (312 MB)
avail memory = 310497280 (296 MB)
K6-family MTRR support enabled (2 registers)
npx0: [FAST]
npx0: <math processor> on motherboard
npx0: INT 16 interface
acpi0: <COMPAQ CARS6U2> on motherboard
acpi0: Power Button (fixed)
Timecounter "ACPI-safe" frequency 3579545 Hz quality 1000
acpi_timer0: <24-bit timer at 3.579545MHz> port 0x8008-0x800b on acpi0
cpu0: <ACPI CPU (2 Cx states)> on acpi0
acpi_button0: <Power Button> on acpi0
pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0
pci0: <ACPI PCI bus> on pcib0
agp0: <SiS 530 host to AGP bridge> mem 0x50000000-0x5fffffff at device 
0.0 on pci0
atapci0: <SiS 530 UDMA66 controller> port 
0x2840-0x284f,0x376,0x170-0x177,0x3f6,0x1f0-0x1f7 at device 0.1 on pci0
ata0: channel #0 on atapci0
ata1: channel #1 on atapci0
isab0: <PCI-ISA bridge> at device 1.0 on pci0
isa0: <ISA bus> on isab0
pci0: <unknown> at device 1.1 (no driver attached)
ohci0: <SiS 5571 USB controller> mem 0x40100000-0x40100fff irq 11 at 
device 1.2 on pci0
ohci0: [GIANT-LOCKED]
usb0: OHCI version 1.0, legacy support
usb0: <SiS 5571 USB controller> on ohci0
usb0: USB revision 1.0
uhub0: SiS OHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub0: 2 ports with 2 removable, self powered
uhub1: Cypress Semiconductor product 0x0100, class 9/1, rev 1.00/0.01, 
addr 2
uhub1: 4 ports with 4 removable, self powered
pcib1: <PCI-PCI bridge> at device 2.0 on pci0
pci1: <PCI bus> on pcib1
pci1: <display, VGA> at device 0.0 (no driver attached)
ahc0: <Adaptec 2940 Ultra SCSI adapter> port 0x2400-0x24ff mem 
0x41100000-0x41100fff irq 3 at device 4.0 on pci0
ahc0: [GIANT-LOCKED]
aic7880: Ultra Single Channel A, SCSI Id=7, 16/253 SCBs
dc0: <ADMtek AN985 10/100BaseTX> port 0x2000-0x20ff mem 
0x41000000-0x410003ff irq 10 at device 5.0 on pci0
miibus0: <MII bus> on dc0
ukphy0: <Generic IEEE 802.3u media interface> on miibus0
ukphy0:  10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
dc0: Ethernet address: 00:04:5a:62:81:fd
dc0: if_start running deferred for Giant
dc0: [GIANT-LOCKED]
pci0: <multimedia, audio> at device 10.0 (no driver attached)
atkbdc0: <Keyboard controller (i8042)> port 0x64,0x60 irq 1 on acpi0
atkbd0: <AT Keyboard> irq 1 on atkbdc0
kbd0 at atkbd0
atkbd0: [GIANT-LOCKED]
psm0: <PS/2 Mouse> irq 12 on atkbdc0
psm0: [GIANT-LOCKED]
psm0: model MouseMan+, device ID 0
sio0: <Standard PC COM port> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0
sio0: type 16550A
fdc0: <floppy drive controller> port 0x3f0-0x3f5 irq 6 drq 2 on acpi0
fdc0: [FAST]
orm0: <ISA Option ROMs> at iomem 
0xec000-0xeffff,0xd0000-0xd07ff,0xc0000-0xc7fff on isa0
pmtimer0 on isa0
ppc0: parallel port not found.
sc0: <System console> at flags 0x100 on isa0
sc0: VGA <16 virtual consoles, flags=0x300>
sio1: configured irq 3 not in bitmap of probed irqs 0
sio1: port may not be enabled
vga0: <Generic ISA VGA> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
Timecounter "TSC" frequency 450130973 Hz quality 800
Timecounters tick every 10.000 msec
ad0: 9541MB <QUANTUM BIGFOOT TS10.0A/A21.0G00> [19386/16/63] at 
ata0-master UDMA33
ad1: 16124MB <IBM-DTTA-351680/T51OA70B> [32760/16/63] at ata0-slave UDMA33
acd0: CDROM <LTN323/DQ17> at ata1-master PIO4
ad3: 4121MB <Maxtor 90432D3/WAS82739> [8374/16/63] at ata1-slave UDMA33
Mounting root from ufs:/dev/ad0s1a
calcru: negative runtime of -571446 usec for pid 59 (rcorder)
calcru: negative runtime of -671976 usec for pid 61 (sysctl)
calcru: negative runtime of -674815 usec for pid 63 (dd)
calcru: negative runtime of -263 usec for pid 53 (nfsiod 3)
calcru: negative runtime of -529 usec for pid 50 (nfsiod 0)
calcru: negative runtime of -686610 usec for pid 48 (vnlru)
calcru: negative runtime of -686868 usec for pid 46 (bufdaemon)
calcru: negative runtime of -1194425 usec for pid 45 (pagezero)
calcru: negative runtime of -257 usec for pid 42 (fdc0)
calcru: negative runtime of -674815 usec for pid 63 (dd)
calcru: negative runtime of -263 usec for pid 53 (nfsiod 3)
calcru: negative runtime of -529 usec for pid 50 (nfsiod 0)
calcru: negative runtime of -686610 usec for pid 48 (vnlru)
calcru: negative runtime of -686868 usec for pid 46 (bufdaemon)
calcru: negative runtime of -1194425 usec for pid 45 (pagezero)
calcru: negative runtime of -257 usec for pid 42 (fdc0)
calcru: negative runtime of -636150 usec for pid 65 (ps)
calcru: negative runtime of -676141 usec for pid 66 (sysctl)
calcru: negative runtime of -669155 usec for pid 63 (dd)
calcru: negative runtime of -263 usec for pid 53 (nfsiod 3)
calcru: negative runtime of -529 usec for pid 50 (nfsiod 0)
calcru: negative runtime of -686610 usec for pid 48 (vnlru)
calcru: negative runtime of -686868 usec for pid 46 (bufdaemon)
calcru: negative runtime of -1112500 usec for pid 45 (pagezero)
calcru: negative runtime of -257 usec for pid 42 (fdc0)
calcru: runtime went backwards from 688036 usec to 1204 usec for pid 30 
(yarrow)
calcru: negative runtime of -669322 usec for pid 66 (sysctl)
calcru: negative runtime of -669155 usec for pid 63 (dd)
calcru: negative runtime of -263 usec for pid 53 (nfsiod 3)
calcru: negative runtime of -529 usec for pid 50 (nfsiod 0)
calcru: negative runtime of -686610 usec for pid 48 (vnlru)
calcru: negative runtime of -686868 usec for pid 46 (bufdaemon)
calcru: negative runtime of -1112500 usec for pid 45 (pagezero)
calcru: negative runtime of -257 usec for pid 42 (fdc0)
calcru: runtime went backwards from 688036 usec to 1204 usec for pid 30 
(yarrow)
calcru: negative runtime of -662605 usec for pid 66 (sysctl)
calcru: negative runtime of -669155 usec for pid 63 (dd)
calcru: negative runtime of -263 usec for pid 53 (nfsiod 3)
calcru: negative runtime of -529 usec for pid 50 (nfsiod 0)
calcru: negative runtime of -686610 usec for pid 48 (vnlru)
calcru: negative runtime of -686868 usec for pid 46 (bufdaemon)
calcru: negative runtime of -1112500 usec for pid 45 (pagezero)
calcru: negative runtime of -257 usec for pid 42 (fdc0)
calcru: runtime went backwards from 688036 usec to 1204 usec for pid 30 
(yarrow)
calcru: negative runtime of -656954 usec for pid 66 (sysctl)
calcru: negative runtime of -669155 usec for pid 63 (dd)
calcru: negative runtime of -263 usec for pid 53 (nfsiod 3)
calcru: negative runtime of -529 usec for pid 50 (nfsiod 0)
calcru: negative runtime of -686610 usec for pid 48 (vnlru)
calcru: negative runtime of -686868 usec for pid 46 (bufdaemon)
calcru: negative runtime of -1112500 usec for pid 45 (pagezero)
calcru: negative runtime of -257 usec for pid 42 (fdc0)
calcru: runtime went backwards from 688036 usec to 1204 usec for pid 30 
(yarrow)
calcru: negative runtime of -650410 usec for pid 66 (sysctl)
calcru: negative runtime of -669155 usec for pid 63 (dd)
calcru: negative runtime of -263 usec for pid 53 (nfsiod 3)
calcru: negative runtime of -529 usec for pid 50 (nfsiod 0)
calcru: negative runtime of -686610 usec for pid 48 (vnlru)
calcru: negative runtime of -686868 usec for pid 46 (bufdaemon)
calcru: negative runtime of -1112500 usec for pid 45 (pagezero)
calcru: negative runtime of -257 usec for pid 42 (fdc0)
calcru: runtime went backwards from 688036 usec to 1204 usec for pid 30 
(yarrow)
calcru: negative runtime of -643892 usec for pid 66 (sysctl)
calcru: negative runtime of -669155 usec for pid 63 (dd)
calcru: negative runtime of -263 usec for pid 53 (nfsiod 3)
calcru: negative runtime of -529 usec for pid 50 (nfsiod 0)
calcru: negative runtime of -686610 usec for pid 48 (vnlru)
calcru: negative runtime of -686868 usec for pid 46 (bufdaemon)
calcru: negative runtime of -1112500 usec for pid 45 (pagezero)
calcru: negative runtime of -257 usec for pid 42 (fdc0)
calcru: runtime went backwards from 688036 usec to 1204 usec for pid 30 
(yarrow)
calcru: runtime went backwards from 3443715 usec to 3443475 usec for pid 
27 (swi5: clock sio)
calcru: negative runtime of -1284991 usec for pid 63 (dd)
calcru: negative runtime of -263 usec for pid 53 (nfsiod 3)
calcru: negative runtime of -529 usec for pid 50 (nfsiod 0)
calcru: negative runtime of -686610 usec for pid 48 (vnlru)
calcru: negative runtime of -686868 usec for pid 46 (bufdaemon)
calcru: negative runtime of -1077423 usec for pid 45 (pagezero)
calcru: negative runtime of -225 usec for pid 42 (fdc0)
calcru: negative runtime of -676268 usec for pid 30 (yarrow)
calcru: negative runtime of -661212 usec for pid 3 (g_up)
calcru: runtime went backwards from 700778 usec to 700753 usec for pid 
25 (irq14: ata0)
calcru: negative runtime of -1284991 usec for pid 63 (dd)
<snip>
...and so on with the calcru errors ad nauseum.

-- 
GPG Public Key: http://bombsession.com/gpgPubKey.txt