CPU time accounting broken on 8-STABLE machine after a few hours
of uptime
Don Lewis
truckman at FreeBSD.org
Tue Sep 28 04:44:04 UTC 2010
CPU time accounting is broken on one of my machines running 8-STABLE. I
ran a test with a simple program that just loops and consumes CPU time:
% time ./a.out
94.544u 0.000s 19:14.10 8.1% 62+2054k 0+0io 0pf+0w
The display in top shows the process with WCPU at 100%, but TIME
increments very slowly.
Several hours after booting, I got a bunch of "calcru: runtime went
backwards" messages, but they stopped right away and never appeared
again.
Aug 23 13:40:07 scratch ntpd[1159]: ntpd 4.2.4p5-a (1)
Aug 23 13:43:18 scratch ntpd[1160]: kernel time sync status change 2001
Aug 23 18:05:57 scratch dbus-daemon: [system] Reloaded configuration
Aug 23 18:06:16 scratch dbus-daemon: [system] Reloaded configuration
Aug 23 18:12:40 scratch ntpd[1160]: time reset +18.059948 s
[snip]
Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 6836685136 usec to 5425839798 usec for pid 1526 (csh)
Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 4747 usec to 2403 usec for pid 1519 (csh)
Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 5265 usec to 2594 usec for pid 1494 (hald-addon-mouse-sy)
Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 7818 usec to 3734 usec for pid 1488 (console-kit-daemon)
Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 977 usec to 459 usec for pid 1480 (getty)
Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 958 usec to 450 usec for pid 1479 (getty)
Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 957 usec to 449 usec for pid 1478 (getty)
Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 952 usec to 447 usec for pid 1477 (getty)
Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 959 usec to 450 usec for pid 1476 (getty)
Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 975 usec to 458 usec for pid 1475 (getty)
Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 1026 usec to 482 usec for pid 1474 (getty)
Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 1333 usec to 626 usec for pid 1473 (getty)
Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 2469 usec to 1160 usec for pid 1440 (inetd)
Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 719 usec to 690 usec for pid 1402 (sshd)
Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 120486 usec to 56770 usec for pid 1360 (cupsd)
Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 6204 usec to 2914 usec for pid 1289 (dbus-daemon)
Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 179 usec to 84 usec for pid 1265 (moused)
Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 22156 usec to 10407 usec for pid 1041 (nfsd)
Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 1292 usec to 607 usec for pid 1032 (mountd)
Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 8801 usec to 4134 usec for pid 664 (devd)
Aug 23 23:49:06 scratch kernel: calcru: runtime went backwards from 19 usec to 9 usec for pid 9 (sctp_iterator)
If I reboot and run the test again, the CPU time accounting seems to be
working correctly.
% time ./a.out
1144.226u 0.000s 19:06.62 99.7% 5+168k 0+0io 0pf+0w
I'm not sure how long this problem has been present. I do remember
seeing the calcru messages with an August 23rd kernel. I have not seen
the calcru messages when running -CURRENT on the same hardware. I also
have not seen this same problem on my other Athlon 64 box running the
August 23rd kernel.
Before reboot:
# sysctl kern.timecounter
kern.timecounter.tick: 1
kern.timecounter.choice: TSC(800) ACPI-fast(1000) i8254(0) dummy(-1000000)
kern.timecounter.hardware: ACPI-fast
kern.timecounter.stepwarnings: 0
kern.timecounter.tc.i8254.mask: 4294967295
kern.timecounter.tc.i8254.counter: 3534
kern.timecounter.tc.i8254.frequency: 1193182
kern.timecounter.tc.i8254.quality: 0
kern.timecounter.tc.ACPI-fast.mask: 16777215
kern.timecounter.tc.ACPI-fast.counter: 8685335
kern.timecounter.tc.ACPI-fast.frequency: 3579545
kern.timecounter.tc.ACPI-fast.quality: 1000
kern.timecounter.tc.TSC.mask: 4294967295
kern.timecounter.tc.TSC.counter: 2204228369
kern.timecounter.tc.TSC.frequency: 2500018183
kern.timecounter.tc.TSC.quality: 800
kern.timecounter.invariant_tsc: 0
After reboot:
% sysctl kern.timecounter
kern.timecounter.tick: 1
kern.timecounter.choice: TSC(800) ACPI-fast(1000) i8254(0) dummy(-1000000)
kern.timecounter.hardware: ACPI-fast
kern.timecounter.stepwarnings: 0
kern.timecounter.tc.i8254.mask: 4294967295
kern.timecounter.tc.i8254.counter: 2241
kern.timecounter.tc.i8254.frequency: 1193182
kern.timecounter.tc.i8254.quality: 0
kern.timecounter.tc.ACPI-fast.mask: 16777215
kern.timecounter.tc.ACPI-fast.counter: 4636239
kern.timecounter.tc.ACPI-fast.frequency: 3579545
kern.timecounter.tc.ACPI-fast.quality: 1000
kern.timecounter.tc.TSC.mask: 4294967295
kern.timecounter.tc.TSC.counter: 1429996208
kern.timecounter.tc.TSC.frequency: 2500020459
kern.timecounter.tc.TSC.quality: 800
kern.timecounter.invariant_tsc: 0
Here's my kernel config file (uni-processor i386 kernel running on an
Athlon 64 x2 CPU):
include GENERIC
nocpu I486_CPU
nocpu I586_CPU
nooptions SCHED_4BSD # 4BSD scheduler
options SCHED_ULE
# Debugging for use in -current
options KDB # Enable kernel debugger support.
options DDB # Support DDB.
options GDB # Support remote GDB.
nooptions SMP # Symmetric MultiProcessor Kernel
nodevice apic # I/O APIC
nodevice atapicd # ATAPI CDROM drives
device atapicam # emulate ATAPI devices as SCSI ditto via CAM
/var/run/dmesg.boot:
Copyright (c) 1992-2010 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 8.1-STABLE #6: Thu Sep 23 16:03:29 PDT 2010
dl at scratch.catspoiler.org:/usr/obj/usr/src/sys/GENERICDDB i386
Timecounter "i8254" frequency 1193182 Hz quality 0
CPU: AMD Athlon(tm) 64 X2 Dual Core Processor 4800+ (2500.02-MHz 686-class CPU)
Origin = "AuthenticAMD" Id = 0x60fb1 Family = f Model = 6b Stepping = 1
Features=0x178bfbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CLFLUSH,MMX,FXSR,SSE,SSE2,HTT>
Features2=0x2001<SSE3,CX16>
AMD Features=0xea500800<SYSCALL,NX,MMX+,FFXSR,RDTSCP,LM,3DNow!+,3DNow!>
AMD Features2=0x11f<LAHF,CMP,SVM,ExtAPIC,CR8,Prefetch>
real memory = 4294967296 (4096 MB)
avail memory = 3607351296 (3440 MB)
kbd1 at kbdmux0
ACPI Warning: Optional field Pm2ControlBlock has zero address or length: 0x0000000000000000/0x1 (20100331/tbfadt-655)
acpi0: <Nvidia AWRDACPI> on motherboard
acpi0: [ITHREAD]
acpi0: Power Button (fixed)
acpi0: reservation of 0, a0000 (3) failed
acpi0: reservation of 100000, dbdf0000 (3) failed
Timecounter "ACPI-fast" frequency 3579545 Hz quality 1000
acpi_timer0: <24-bit timer at 3.579545MHz> port 0x1008-0x100b on acpi0
cpu0: <ACPI CPU> on acpi0
acpi_hpet0: <High Precision Event Timer> iomem 0xfeff0000-0xfeff03ff on acpi0
device_attach: acpi_hpet0 attach returned 12
acpi_button0: <Power Button> on acpi0
pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0
pci0: <ACPI PCI bus> on pcib0
pci0: <memory, RAM> at device 0.0 (no driver attached)
isab0: <PCI-ISA bridge> at device 1.0 on pci0
isa0: <ISA bus> on isab0
pci0: <serial bus, SMBus> at device 1.1 (no driver attached)
pci0: <memory, RAM> at device 1.2 (no driver attached)
ohci0: <OHCI (generic) USB controller> mem 0xfe02f000-0xfe02ffff irq 10 at device 2.0 on pci0
ohci0: [ITHREAD]
usbus0: <OHCI (generic) USB controller> on ohci0
ehci0: <EHCI (generic) USB 2.0 controller> mem 0xfe02e000-0xfe02e0ff irq 11 at device 2.1 on pci0
ehci0: [ITHREAD]
usbus1: EHCI version 1.0
usbus1: <EHCI (generic) USB 2.0 controller> on ehci0
ohci1: <OHCI (generic) USB controller> mem 0xfe02d000-0xfe02dfff irq 5 at device 4.0 on pci0
ohci1: [ITHREAD]
usbus2: <OHCI (generic) USB controller> on ohci1
ehci1: <EHCI (generic) USB 2.0 controller> mem 0xfe02c000-0xfe02c0ff irq 10 at device 4.1 on pci0
ehci1: [ITHREAD]
usbus3: EHCI version 1.0
usbus3: <EHCI (generic) USB 2.0 controller> on ehci1
atapci0: <nVidia nForce MCP67 UDMA133 controller> port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0xf000-0xf00f at device 6.0 on pci0
ata0: <ATA channel 0> on atapci0
ata0: [ITHREAD]
ata1: <ATA channel 1> on atapci0
ata1: [ITHREAD]
pci0: <multimedia, HDA> at device 7.0 (no driver attached)
pcib1: <ACPI PCI-PCI bridge> at device 8.0 on pci0
pci1: <ACPI PCI bus> on pcib1
fwohci0: <Texas Instruments TSB43AB22/A> mem 0xfd0ff000-0xfd0ff7ff,0xfd0f8000-0xfd0fbfff irq 11 at device 7.0 on pci1
fwohci0: [ITHREAD]
fwohci0: OHCI version 1.10 (ROM=1)
fwohci0: No. of Isochronous channels is 4.
fwohci0: EUI64 00:50:8d:00:00:99:f0:69
fwohci0: Phy 1394a available S400, 2 ports.
fwohci0: Link S400, max_rec 2048 bytes.
firewire0: <IEEE1394(FireWire) bus> on fwohci0
dcons_crom0: <dcons configuration ROM> on firewire0
dcons_crom0: bus_addr 0x1090000
fwe0: <Ethernet over FireWire> on firewire0
if_fwe0: Fake Ethernet address: 02:50:8d:99:f0:69
fwe0: Ethernet address: 02:50:8d:99:f0:69
fwip0: <IP over FireWire> on firewire0
fwip0: Firewire address: 00:50:8d:00:00:99:f0:69 @ 0xfffe00000000, S400, maxrec 2048
fwohci0: Initiate bus reset
fwohci0: fwohci_intr_core: BUS reset
fwohci0: fwohci_intr_core: node_id=0x00000000, SelfID Count=1, CYCLEMASTER mode
ahc0: <Adaptec 19160B Ultra160 SCSI adapter> port 0xcc00-0xccff mem 0xfd0fe000-0xfd0fefff irq 11 at device 9.0 on pci1
ahc0: [ITHREAD]
aic7892: Ultra160 Wide Channel A, SCSI Id=7, 32/253 SCBs
atapci1: <nVidia nForce MCP67 SATA300 controller> port 0x9f0-0x9f7,0xbf0-0xbf3,0x970-0x977,0xb70-0xb73,0xdc00-0xdc0f mem 0xfe026000-0xfe027fff irq 10 at device 9.0 on pci0
atapci1: [ITHREAD]
atapci1: AHCI v1.10 controller with 4 3Gbps ports, PM supported
ata2: <ATA channel 0> on atapci1
ata2: [ITHREAD]
ata3: <ATA channel 1> on atapci1
ata3: [ITHREAD]
ata4: <ATA channel 2> on atapci1
ata4: [ITHREAD]
ata5: <ATA channel 3> on atapci1
ata5: [ITHREAD]
nfe0: <NVIDIA nForce MCP67 Networking Adapter> port 0xd800-0xd807 mem 0xfe02b000-0xfe02bfff,0xfe02a000-0xfe02a0ff,0xfe029000-0xfe02900f irq 15 at device 10.0 on pci0
miibus0: <MII bus> on nfe0
e1000phy0: <Marvell 88E1116 Gigabit PHY> PHY 1 on miibus0
e1000phy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 1000baseT-FDX, auto
nfe0: Ethernet address: 00:50:8d:9f:6d:e3
nfe0: [FILTER]
pcib2: <ACPI PCI-PCI bridge> at device 11.0 on pci0
pci2: <ACPI PCI bus> on pcib2
pcib3: <ACPI PCI-PCI bridge> at device 12.0 on pci0
pci3: <ACPI PCI bus> on pcib3
atapci2: <SiI 3132 SATA300 controller> port 0xac00-0xac7f mem 0xfdcff000-0xfdcff07f,0xfdcf8000-0xfdcfbfff irq 5 at device 0.0 on pci3
atapci2: [ITHREAD]
ata6: <ATA channel 0> on atapci2
ata6: [ITHREAD]
ata7: <ATA channel 1> on atapci2
ata7: [ITHREAD]
pcib4: <ACPI PCI-PCI bridge> at device 13.0 on pci0
pci4: <ACPI PCI bus> on pcib4
pcib5: <ACPI PCI-PCI bridge> at device 14.0 on pci0
pci5: <ACPI PCI bus> on pcib5
pcib6: <ACPI PCI-PCI bridge> at device 15.0 on pci0
pci6: <ACPI PCI bus> on pcib6
pcib7: <ACPI PCI-PCI bridge> at device 16.0 on pci0
pci7: <ACPI PCI bus> on pcib7
pcib8: <ACPI PCI-PCI bridge> at device 17.0 on pci0
pci8: <ACPI PCI bus> on pcib8
vgapci0: <VGA-compatible display> mem 0xfb000000-0xfbffffff,0xe0000000-0xefffffff,0xfc000000-0xfcffffff irq 10 at device 18.0 on pci0
acpi_tz0: <Thermal Zone> on acpi0
atrtc0: <AT realtime clock> port 0x70-0x73 on acpi0
fdc0: <floppy drive controller> port 0x3f0-0x3f5,0x3f7 irq 6 drq 2 on acpi0
fdc0: [FILTER]
atkbdc0: <Keyboard controller (i8042)> port 0x60,0x64 irq 1 on acpi0
atkbd0: <AT Keyboard> irq 1 on atkbdc0
kbd0 at atkbd0
atkbd0: [GIANT-LOCKED]
atkbd0: [ITHREAD]
psm0: <PS/2 Mouse> irq 12 on atkbdc0
psm0: [GIANT-LOCKED]
psm0: [ITHREAD]
psm0: model MouseMan+, device ID 0
pmtimer0 on isa0
sc0: <System console> at flags 0x100 on isa0
sc0: VGA <16 virtual consoles, flags=0x300>
vga0: <Generic ISA VGA> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
ppc0: parallel port not found.
powernow0: <PowerNow! K8> on cpu0
Timecounter "TSC" frequency 2500018183 Hz quality 800
Timecounters tick every 1.000 msec
firewire0: 1 nodes, maxhop <= 0 cable IRM irm(0) (me)
firewire0: bus manager 0
usbus0: 12Mbps Full Speed USB v1.0
usbus1: 480Mbps High Speed USB v2.0
usbus2: 12Mbps Full Speed USB v1.0
usbus3: 480Mbps High Speed USB v2.0
ugen0.1: <nVidia> at usbus0
uhub0: <nVidia OHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus0
ugen1.1: <nVidia> at usbus1
uhub1: <nVidia EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus1
ugen2.1: <nVidia> at usbus2
uhub2: <nVidia OHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus2
ugen3.1: <nVidia> at usbus3
uhub3: <nVidia EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus3
uhub0: 6 ports with 6 removable, self powered
uhub2: 6 ports with 6 removable, self powered
ad6: 476940MB <SAMSUNG HD501LJ CR100-13> at ata3-master UDMA100 SATA 3Gb/s
uhub1: 6 ports with 6 removable, self powered
uhub3: 6 ports with 6 removable, self powered
unknown: FAILURE - INQUIRY ILLEGAL REQUEST asc=0x24 ascq=0x00 sks=0x40 0x00 0x01
cd0 at ata0 bus 0 scbus1 target 0 lun 0
cd0: <TOSHIBA CD-ROM XM-6602B 1017> Removable CD-ROM SCSI-0 device
cd0: 3.300MB/s transfers
cd0: cd present [138590 x 2048 byte records]
da0 at ahc0 bus 0 scbus0 target 0 lun 0
da0: <SEAGATE ST336706LW 010A> Fixed Direct Access SCSI-3 device
da0: 160.000MB/s transfers (80.000MHz DT, offset 63, 16bit)
da0: Command Queueing enabled
da0: 35003MB (71687370 512 byte sectors: 255H 63S/T 4462C)
Trying to mount root from ufs:/dev/ad6s1a
nfe0: link state changed to UP
More information about the freebsd-stable
mailing list