From owner-freebsd-questions@FreeBSD.ORG Sun Sep 2 02:05:01 2007 Return-Path: Delivered-To: freebsd-questions@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id B479116A418 for ; Sun, 2 Sep 2007 02:05:01 +0000 (UTC) (envelope-from list@museum.rain.com) Received: from ns.umpquanet.com (ns.umpquanet.com [204.119.0.16]) by mx1.freebsd.org (Postfix) with ESMTP id 7FFE013C45A for ; Sun, 2 Sep 2007 02:05:01 +0000 (UTC) (envelope-from list@museum.rain.com) Received: from ns.umpquanet.com (localhost [127.0.0.1]) by ns.umpquanet.com (8.14.1/8.14.1) with ESMTP id l821Ok1I017186 for ; Sat, 1 Sep 2007 18:24:46 -0700 (PDT) (envelope-from list@museum.rain.com) Received: (from james@localhost) by ns.umpquanet.com (8.14.1/8.14.1/Submit) id l821OkBt017185 for freebsd-questions@freebsd.org; Sat, 1 Sep 2007 18:24:46 -0700 (PDT) (envelope-from list@museum.rain.com) Date: Sat, 1 Sep 2007 18:24:46 -0700 From: James Long To: freebsd-questions@freebsd.org Message-ID: <20070902012446.GA17048@ns.umpquanet.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline User-Agent: Mutt/1.5.16 (2007-06-09) Subject: Recent update to RELENG_6 creates lots of calcru warnings X-BeenThere: freebsd-questions@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: User questions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sun, 02 Sep 2007 02:05:01 -0000 I'm running FreeBSD RELENG_6 on a Compaq DL380 G2 dual PIII-1.4GHz with an SMP kernel. dmesg below. Prior to about August 12, the system had been quite stable. Since that time, I am finding lots of calcru warnings, which often cause system services to fail when they see unorthodox time shifts. Section 5.19 of the handbook appears not to be current any longer, suggesting setting kern.timecounter.method=1. kern.timecounter.hardware=i8254 also does not improve things. Other suggestions? Thanks, Jim Sep 1 18:00:30 ns sudo: james : TTY=ttyp0 ; PWD=/usr/local/www/sites/com.umpquanet/support ; USER=root ; COMMAND=/sbin/sysctl -w kern.timecounter.hardware=i8254 Sep 1 18:02:44 ns kernel: calcru: runtime went backwards from 1343309 usec to 1178478 usec for pid 3663 (hpasmd) Sep 1 18:02:44 ns kernel: calcru: negative runtime of -1274607 usec for pid 3660 (hpasmd) Sep 1 18:02:44 ns kernel: calcru: runtime went backwards from 6470361 usec to 5811413 usec for pid 995 (postgres) Sep 1 18:02:44 ns kernel: calcru: negative runtime of -1099076 usec for pid 36 (pagedaemon) Sep 1 18:02:44 ns kernel: calcru: negative runtime of -5928105 usec for pid 35 (fdc0) Sep 1 18:02:44 ns kernel: calcru: negative runtime of -1526937 usec for pid 32 (acpi_cooling0) Sep 1 18:02:44 ns kernel: calcru: runtime went backwards from 8015143 usec to 1437770 usec for pid 15 (yarrow) Sep 1 18:02:44 ns kernel: calcru: negative runtime of -12360933 usec for pid 2 (g_event) Sep 1 18:02:44 ns kernel: calcru: negative runtime of -2106022786 usec for pid 13 (swi4: clock sio) Sep 1 18:02:44 ns kernel: calcru: runtime went backwards from 295074296 usec to 292484248 usec for pid 1 (init) Sep 1 18:02:44 ns kernel: calcru: runtime went backwards from 1343309 usec to 1178478 usec for pid 3663 (hpasmd) Sep 1 18:02:44 ns kernel: calcru: negative runtime of -1274607 usec for pid 3660 (hpasmd) Sep 1 18:02:44 ns kernel: calcru: runtime went backwards from 6470361 usec to 5811413 usec for pid 995 (postgres) Sep 1 18:02:44 ns kernel: calcru: negative runtime of -1099076 usec for pid 36 (pagedaemon) Sep 1 18:02:44 ns kernel: calcru: negative runtime of -5928105 usec for pid 35 (fdc0) Sep 1 18:02:44 ns kernel: calcru: negative runtime of -1526937 usec for pid 32 (acpi_cooling0) Sep 1 18:02:44 ns kernel: calcru: runtime went backwards from 8015143 usec to 1437770 usec for pid 15 (yarrow) Sep 1 18:02:44 ns kernel: calcru: negative runtime of -12360933 usec for pid 2 (g_event) Sep 1 18:02:44 ns kernel: calcru: negative runtime of -2106022734 usec for pid 13 (swi4: clock sio) Sep 1 18:02:44 ns kernel: calcru: runtime went backwards from 295074296 usec to 292484248 usec for pid 1 (init) dmesg output: Copyright (c) 1992-2007 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 6.2-STABLE #0: Mon Aug 27 17:24:37 PDT 2007 root@ns.umpquanet.com:/usr/obj/usr/src/sys/SMP-UMP Timecounter "i8254" frequency 1193182 Hz quality 0 CPU: Intel(R) Pentium(R) III CPU family 1400MHz (1390.66-MHz 686-class CPU) Origin = "GenuineIntel" Id = 0x6b1 Stepping = 1 Features=0x383fbff real memory = 1073725440 (1023 MB) avail memory = 1037357056 (989 MB) ACPI APIC Table: FreeBSD/SMP: Multiprocessor System Detected: 2 CPUs cpu0 (BSP): APIC ID: 3 cpu1 (AP): APIC ID: 0 MADT: Forcing active-low polarity and level trigger for SCI ioapic1 irqs 16-31 on motherboard ioapic0 irqs 0-15 on motherboard kbd1 at kbdmux0 ath_hal: 0.9.20.3 (AR5210, AR5211, AR5212, RF5111, RF5112, RF2413, RF5413) acpi0: on motherboard acpi0: Power Button (fixed) Timecounter "ACPI-fast" frequency 3579545 Hz quality 1000 acpi_timer0: <24-bit timer at 3.579545MHz> port 0x240-0x243 on acpi0 cpu0: on acpi0 cpu1: on acpi0 pcib0: on acpi0 pci0: on pcib0 ciss0: port 0x2000-0x20ff mem 0xf5ec0000-0xf5efffff,0xf3ef0000-0xf3ef3fff irq 16 at device 1.0 on pci0 ciss0: [GIANT-LOCKED] fxp0: port 0x2400-0x243f mem 0xf5eb0000-0xf5eb0fff,0xf5d00000-0xf5dfffff irq 18 at device 2.0 on pci0 miibus0: on fxp0 inphy0: on miibus0 inphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto fxp0: Ethernet address: 00:02:a5:ad:82:d5 fxp1: port 0x2440-0x247f mem 0xf5cf0000-0xf5cf0fff,0xf5b00000-0xf5bfffff irq 20 at device 4.0 on pci0 miibus1: on fxp1 inphy1: on miibus1 inphy1: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto fxp1: Ethernet address: 00:02:a5:ad:82:d4 pci0: at device 6.0 (no driver attached) isab0: at device 15.0 on pci0 isa0: on isab0 atapci0: port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0x2c00-0x2c0f at device 15.1 on pci0 ata0: on atapci0 ata1: on atapci0 ohci0: mem 0xf3fd0000-0xf3fd0fff irq 22 at device 15.2 on pci0 ohci0: [GIANT-LOCKED] usb0: OHCI version 1.0, legacy support usb0: SMM does not respond, resetting usb0: on ohci0 usb0: USB revision 1.0 uhub0: (0x1166) OHCI root hub, class 9/0, rev 1.00/1.00, addr 1 uhub0: 4 ports with 4 removable, self powered pcib1: on acpi0 pci1: on pcib1 pcib2: at device 3.0 on pci1 pci2: on pcib2 pci2: at device 0.0 (no driver attached) pci1: at device 3.1 (no driver attached) pcib3: on acpi0 pci7: on pcib3 pci7: at device 7.0 (no driver attached) acpi_tz0: on acpi0 atkbdc0: port 0x60,0x64 irq 1 on acpi0 atkbd0: irq 1 on atkbdc0 kbd0 at atkbd0 atkbd0: [GIANT-LOCKED] sio0: port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0 sio0: type 16550A fdc0: port 0x3f2-0x3f5 irq 6 drq 2 on acpi0 fdc0: [FAST] fd0: <1440-KB 3.5" drive> on fdc0 drive 0 pmtimer0 on isa0 orm0: at iomem 0xc0000-0xc7fff,0xc8000-0xcbfff,0xcc000-0xcd7ff,0xee000-0xeffff 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 Timecounters tick every 1.000 msec acd0: CDROM at ata0-master PIO4 sa0 at ciss0 bus 32 target 6 lun 0 sa0: Removable Sequential Access SCSI-2 device sa0: 135.168MB/s transfers da0 at ciss0 bus 0 target 0 lun 0 da0: Fixed Direct Access SCSI-0 device da0: 135.168MB/s transfers da0: 34727MB (71122560 512 byte sectors: 255H 32S/T 8716C) SMP: AP CPU #1 Launched! Trying to mount root from ufs:/dev/da0s1a calcru: negative runtime of -1298258 usec for pid 13 (swi4: clock sio) calcru: negative runtime of -1298243 usec for pid 13 (swi4: clock sio) calcru: negative runtime of -1298218 usec for pid 13 (swi4: clock sio) calcru: negative runtime of -1298218 usec for pid 13 (swi4: clock sio) calcru: negative runtime of -1298201 usec for pid 13 (swi4: clock sio) calcru: negative runtime of -1298201 usec for pid 13 (swi4: clock sio) calcru: negative runtime of -1298201 usec for pid 13 (swi4: clock sio) calcru: negative runtime of -1298201 usec for pid 13 (swi4: clock sio) calcru: negative runtime of -1297853 usec for pid 13 (swi4: clock sio) calcru: negative runtime of -1297853 usec for pid 13 (swi4: clock sio) ... etc. calcru: negative runtime of -1273295 usec for pid 3660 (hpasmd) calcru: runtime went backwards from 6470361 usec to 5829070 usec for pid 995 (postgres) calcru: negative runtime of -1098784 usec for pid 36 (pagedaemon) calcru: negative runtime of -5926871 usec for pid 35 (fdc0) calcru: negative runtime of -1526724 usec for pid 32 (acpi_cooling0) calcru: runtime went backwards from 8015143 usec to 1450174 usec for pid 15 (yarrow) calcru: negative runtime of -12349712 usec for pid 2 (g_event) calcru: negative runtime of -2105724281 usec for pid 13 (swi4: clock sio) calcru: runtime went backwards from 295074296 usec to 292484248 usec for pid 1 (init)