From owner-freebsd-questions@FreeBSD.ORG Tue Nov 9 08:55:04 2004 Return-Path: Delivered-To: freebsd-questions@freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 77C3816A4CF for ; Tue, 9 Nov 2004 08:55:04 +0000 (GMT) Received: from ms-smtp-02-eri0.texas.rr.com (ms-smtp-02.texas.rr.com [24.93.47.41]) by mx1.FreeBSD.org (Postfix) with ESMTP id 87B2043D5C for ; Tue, 9 Nov 2004 08:55:03 +0000 (GMT) (envelope-from bombsession@austin.rr.com) Received: from [192.168.0.3] (cs6668117-168.austin.rr.com [66.68.117.168]) iA98t0BE014662 for ; Tue, 9 Nov 2004 02:55:00 -0600 (CST) Message-ID: <419085E9.4050505@austin.rr.com> Date: Tue, 09 Nov 2004 02:55:05 -0600 From: Mike Pederson User-Agent: Mozilla Thunderbird 0.8 (Windows/20040913) X-Accept-Language: en-us, en MIME-Version: 1.0 To: freebsd-questions@freebsd.org X-Enigmail-Version: 0.86.1.0 X-Enigmail-Supports: pgp-inline, pgp-mime Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit X-Virus-Scanned: Symantec AntiVirus Scan Engine Subject: excessive calcru warnings (negative runtime/runtime went backwards) X-BeenThere: freebsd-questions@freebsd.org X-Mailman-Version: 2.1.1 Precedence: list List-Id: User questions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Tue, 09 Nov 2004 08:55:04 -0000 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 - usecs for pid () calcru: runtime went backwards from usecs to usecs for pid () 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 AMD Features=0x80000800 real memory = 327155712 (312 MB) avail memory = 310497280 (296 MB) K6-family MTRR support enabled (2 registers) npx0: [FAST] npx0: on motherboard npx0: INT 16 interface acpi0: 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: on acpi0 acpi_button0: on acpi0 pcib0: port 0xcf8-0xcff on acpi0 pci0: on pcib0 agp0: mem 0x50000000-0x5fffffff at device 0.0 on pci0 atapci0: 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: at device 1.0 on pci0 isa0: on isab0 pci0: at device 1.1 (no driver attached) ohci0: mem 0x40100000-0x40100fff irq 11 at device 1.2 on pci0 ohci0: [GIANT-LOCKED] usb0: OHCI version 1.0, legacy support usb0: 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: at device 2.0 on pci0 pci1: on pcib1 pci1: at device 0.0 (no driver attached) ahc0: 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: port 0x2000-0x20ff mem 0x41000000-0x410003ff irq 10 at device 5.0 on pci0 miibus0: on dc0 ukphy0: 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: at device 10.0 (no driver attached) atkbdc0: port 0x64,0x60 irq 1 on acpi0 atkbd0: irq 1 on atkbdc0 kbd0 at atkbd0 atkbd0: [GIANT-LOCKED] psm0: irq 12 on atkbdc0 psm0: [GIANT-LOCKED] psm0: model MouseMan+, device ID 0 sio0: port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0 sio0: type 16550A fdc0: port 0x3f0-0x3f5 irq 6 drq 2 on acpi0 fdc0: [FAST] orm0: at iomem 0xec000-0xeffff,0xd0000-0xd07ff,0xc0000-0xc7fff on isa0 pmtimer0 on isa0 ppc0: parallel port not found. sc0: 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: at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0 Timecounter "TSC" frequency 450130973 Hz quality 800 Timecounters tick every 10.000 msec ad0: 9541MB [19386/16/63] at ata0-master UDMA33 ad1: 16124MB [32760/16/63] at ata0-slave UDMA33 acd0: CDROM at ata1-master PIO4 ad3: 4121MB [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) ...and so on with the calcru errors ad nauseum. -- GPG Public Key: http://bombsession.com/gpgPubKey.txt