Don Lewis
2010-Sep-28 04:44 UTC
CPU time accounting broken on 8-STABLE machine after a few hours of uptime
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@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
Jeremy Chadwick
2010-Sep-28 05:12 UTC
CPU time accounting broken on 8-STABLE machine after a few hours of uptime
On Mon, Sep 27, 2010 at 09:25:10PM -0700, Don Lewis wrote:> 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@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 UPDo you have something called Cool'n'Quiet enabled in your BIOS? Solely as a test, try disabling it. If this solves the problem, add "device cpufreq" to your kernel configuration, buildkernel/installkernel, and re-enable the option in your BIOS. It's worth a shot anyway. Some reference threads which are old and may be centralised around Intel CPUs but I imagine the same problem can happen on any platform which adjusts clock frequencies. http://lists.freebsd.org/pipermail/freebsd-questions/2006-October/133253.html http://www.mail-archive.com/freebsd-stable@freebsd.org/msg95530.html -- | Jeremy Chadwick jdc@parodius.com | | Parodius Networking http://www.parodius.com/ | | UNIX Systems Administrator Mountain View, CA, USA | | Making life hard for others since 1977. PGP: 4BD6C0CB |
Chip Camden
2010-Sep-28 14:40 UTC
CPU time accounting broken on 8-STABLE machine after a few hours of uptime
Quoth Don Lewis on Monday, 27 September 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 ><snip> I notice that before the calcru messages, ntpd reset the clock by 18 seconds -- that probably accounts for that. I don't know if that has any connection to time(1) running slower -- but perhaps ntpd is aggressively adjusting your clock? -- Sterling (Chip) Camden | sterling@camdensoftware.com | 2048D/3A978E4F http://camdensoftware.com | http://chipstips.com | http://chipsquips.com -------------- next part -------------- A non-text attachment was scrubbed... Name: not available Type: application/pgp-signature Size: 488 bytes Desc: not available Url : http://lists.freebsd.org/pipermail/freebsd-stable/attachments/20100928/4f116348/attachment.pgp