Recent update to RELENG_6 creates lots of calcru warnings

Sun Sep 2 04:18:07 PDT 2007

James Long wrote:
> 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 at 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<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,MMX,FXSR,SSE>
> real memory  = 1073725440 (1023 MB)
> avail memory = 1037357056 (989 MB)
> ACPI APIC Table: <COMPAQ 00000083>
> 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 <Version 1.1> irqs 16-31 on motherboard
> ioapic0 <Version 1.1> irqs 0-15 on motherboard
> kbd1 at kbdmux0
> ath_hal: 0.9.20.3 (AR5210, AR5211, AR5212, RF5111, RF5112, RF2413, RF5413)
> acpi0: <COMPAQ P24> 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: <ACPI CPU> on acpi0
> cpu1: <ACPI CPU> on acpi0
> pcib0: <ACPI Host-PCI bridge> on acpi0
> pci0: <ACPI PCI bus> on pcib0
> ciss0: <Compaq Smart Array 5i> port 0x2000-0x20ff mem 0xf5ec0000-0xf5efffff,0xf3ef0000-0xf3ef3fff irq 16 at device 1.0 on pci0
> ciss0: [GIANT-LOCKED]
> fxp0: <Intel 82559 Pro/100 Ethernet> port 0x2400-0x243f mem 0xf5eb0000-0xf5eb0fff,0xf5d00000-0xf5dfffff irq 18 at device 2.0 on pci0
> miibus0: <MII bus> on fxp0
> inphy0: <i82555 10/100 media interface> on miibus0
> inphy0:  10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
> fxp0: Ethernet address: 00:02:a5:ad:82:d5
> fxp1: <Intel 82559 Pro/100 Ethernet> port 0x2440-0x247f mem 0xf5cf0000-0xf5cf0fff,0xf5b00000-0xf5bfffff irq 20 at device 4.0 on pci0
> miibus1: <MII bus> on fxp1
> inphy1: <i82555 10/100 media interface> on miibus1
> inphy1:  10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto
> fxp1: Ethernet address: 00:02:a5:ad:82:d4
> pci0: <base peripheral> at device 6.0 (no driver attached)
> isab0: <PCI-ISA bridge> at device 15.0 on pci0
> isa0: <ISA bus> on isab0
> atapci0: <ServerWorks ROSB4 UDMA33 controller> port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0x2c00-0x2c0f at device 15.1 on pci0
> ata0: <ATA channel 0> on atapci0
> ata1: <ATA channel 1> on atapci0
> ohci0: <OHCI (generic) USB controller> 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: <OHCI (generic) USB controller> 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: <ACPI Host-PCI bridge> on acpi0
> pci1: <ACPI PCI bus> on pcib1
> pcib2: <PCI-PCI bridge> at device 3.0 on pci1
> pci2: <PCI bus> on pcib2
> pci2: <display, VGA> at device 0.0 (no driver attached)
> pci1: <memory> at device 3.1 (no driver attached)
> pcib3: <ACPI Host-PCI bridge> on acpi0
> pci7: <ACPI PCI bus> on pcib3
> pci7: <base peripheral, PCI hot-plug controller> at device 7.0 (no driver attached)
> acpi_tz0: <Thermal Zone> on acpi0
> atkbdc0: <Keyboard controller (i8042)> port 0x60,0x64 irq 1 on acpi0
> atkbd0: <AT Keyboard> irq 1 on atkbdc0
> kbd0 at atkbd0
> atkbd0: [GIANT-LOCKED]
> sio0: <Standard PC COM port> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0
> sio0: type 16550A
> fdc0: <floppy drive controller> 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: <ISA Option ROMs> at iomem 0xc0000-0xc7fff,0xc8000-0xcbfff,0xcc000-0xcd7ff,0xee000-0xeffff 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
> Timecounters tick every 1.000 msec
> acd0: CDROM <COMPAQ CD-ROM SN-124/N102> at ata0-master PIO4
> sa0 at ciss0 bus 32 target 6 lun 0
> sa0: <QUANTUM DLT7000 2255> Removable Sequential Access SCSI-2 device 
> sa0: 135.168MB/s transfers
> da0 at ciss0 bus 0 target 0 lun 0
> da0: <COMPAQ RAID 1  VOLUME OK> 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)
> _______________________________________________
> freebsd-questions at freebsd.org mailing list
> http://lists.freebsd.org/mailman/listinfo/freebsd-questions
> To unsubscribe, send any mail to "freebsd-questions-unsubscribe at freebsd.org"
> 
> 

Does reverting to the older kernel work?  If so, can you isolate which 
commit caused the problem by doing a binary search of date ranges?  This 
should be easy to do since the rate of changes to RELENG_6 is low.

Kris