Date: Tue, 09 Nov 2004 02:55:05 -0600 From: Mike Pederson <bombsession@austin.rr.com> To: freebsd-questions@freebsd.org Subject: excessive calcru warnings (negative runtime/runtime went backwards) Message-ID: <419085E9.4050505@austin.rr.com>
next in thread | raw e-mail | index | archive | help
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@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@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
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?419085E9.4050505>