Skip site navigation (1)Skip section navigation (2)
Date:      Sun, 7 Oct 2012 21:02:39 -0700
From:      John-Mark Gurney <jmg@funkthat.com>
To:        freebsd-stable@FreeBSD.org
Subject:   time keeps on slipping... slipping...
Message-ID:  <20121008040239.GE1967@funkthat.com>

next in thread | raw e-mail | index | archive | help
I recently put together a new machine w/ a SuperMicro H8SCM and an
AMD Opteron 4228 HE...  I've having an issue where the clock on the
machine skips around...  The wierd part is that it's very sudden when
it happens...  ntp sometimes brings it back, but it can't when the clock
gets too far ahread (1000 seconds), ntp dies...

In order to catch it happening, I ran a sleep 60 loop fetching time
from another server that keeps time correctly via:
while sleep 60; do echo -n h2:; nc h2 13; date; ntpdate h2.funkthat.com; done

here are some snippits:
h2:Sun Oct  7 17:12:54 2012^M
Sun Oct  7 17:12:54 PDT 2012
 7 Oct 17:12:54 ntpdate[31036]: the NTP socket is in use, exiting
h2:Sun Oct  7 17:13:48 2012^M
Sun Oct  7 17:20:21 PDT 2012
 7 Oct 17:20:21 ntpdate[31045]: the NTP socket is in use, exiting

but then ntp brings it back in sync:
h2:Sun Oct  7 17:28:49 2012^M
Sun Oct  7 17:35:21 PDT 2012
 7 Oct 17:35:21 ntpdate[31164]: the NTP socket is in use, exiting
h2:Sun Oct  7 17:29:49 2012^M
Sun Oct  7 17:29:49 PDT 2012
 7 Oct 17:29:49 ntpdate[31170]: the NTP socket is in use, exiting

It happens pretty often:
Oct  7 00:19:13 gold ntpd[3721]: time reset -785.347912 s
Oct  7 00:46:37 gold ntpd[3721]: time reset -392.673256 s
Oct  7 01:04:24 gold ntpd[3721]: time reset -785.346533 s
Oct  7 15:00:59 gold ntpd[3721]: time reset -392.681720 s
Oct  7 16:32:11 gold ntpd[3721]: time reset -392.671268 s
Oct  7 17:29:29 gold ntpd[3721]: time reset -392.671752 s
Oct  7 18:04:37 gold ntpd[3721]: time reset -785.346987 s

but as you can see above, the time slip happens abruptly.. looks like
a rounding error or something...

I'm now reducing the sleep to 5 seconds... but as you can see the sleep
ends a few seconds early and local time suddenly jumped forward 6
minutes 33 seconds...

$ sysctl kern.timecounter
kern.timecounter.fast_gettime: 1
kern.timecounter.tick: 1
kern.timecounter.choice: TSC-low(1000) ACPI-safe(850) HPET(950) i8254(0) dummy(-1000000)
kern.timecounter.hardware: TSC-low
kern.timecounter.stepwarnings: 0
kern.timecounter.tc.i8254.mask: 65535
kern.timecounter.tc.i8254.counter: 11598
kern.timecounter.tc.i8254.frequency: 1193182
kern.timecounter.tc.i8254.quality: 0
kern.timecounter.tc.HPET.mask: 4294967295
kern.timecounter.tc.HPET.counter: 3257069245
kern.timecounter.tc.HPET.frequency: 14318180
kern.timecounter.tc.HPET.quality: 950
kern.timecounter.tc.ACPI-safe.mask: 16777215
kern.timecounter.tc.ACPI-safe.counter: 4219134510
kern.timecounter.tc.ACPI-safe.frequency: 3579545
kern.timecounter.tc.ACPI-safe.quality: 850
kern.timecounter.tc.TSC-low.mask: 4294967295
kern.timecounter.tc.TSC-low.counter: 2854866610
kern.timecounter.tc.TSC-low.frequency: 10937740
kern.timecounter.tc.TSC-low.quality: 1000
kern.timecounter.smp_tsc: 1
kern.timecounter.invariant_tsc: 1
$ sysctl kern.eventtimer
kern.eventtimer.choice: LAPIC(400) i8254(100) RTC(0)
kern.eventtimer.et.LAPIC.flags: 15
kern.eventtimer.et.LAPIC.frequency: 100002217
kern.eventtimer.et.LAPIC.quality: 400
kern.eventtimer.et.i8254.flags: 1
kern.eventtimer.et.i8254.frequency: 1193182
kern.eventtimer.et.i8254.quality: 100
kern.eventtimer.et.RTC.flags: 17
kern.eventtimer.et.RTC.frequency: 32768
kern.eventtimer.et.RTC.quality: 0
kern.eventtimer.periodic: 0
kern.eventtimer.timer: LAPIC
kern.eventtimer.activetick: 1
kern.eventtimer.idletick: 0
kern.eventtimer.singlemul: 2

dmesg:
Copyright (c) 1992-2012 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 9.1-PRERELEASE #3 r241041M: Sat Sep 29 22:38:03 PDT 2012
    jmg@gold.funkthat.com:/usr/src.9stable/sys/amd64/compile/gold amd64
CPU: AMD Opteron(tm) Processor 4228 HE               (2800.06-MHz K8-class CPU)
  Origin = "AuthenticAMD"  Id = 0x600f12  Family = 0x15  Model = 0x1  Stepping = 2
  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=0x1e98220b<SSE3,PCLMULQDQ,MON,SSSE3,CX16,SSE4.1,SSE4.2,POPCNT,AESNI,XSAVE,OSXSAVE,AVX>
  AMD Features=0x2e500800<SYSCALL,NX,MMX+,FFXSR,Page1GB,RDTSCP,LM>
  AMD Features2=0x1c9bfff<LAHF,CMP,SVM,ExtAPIC,CR8,ABM,SSE4A,MAS,Prefetch,OSVW,IBS,XOP,SKINIT,WDT,LWP,FMA4,NodeId,Topology,<b23>,<b24>>
  TSC: P-state invariant, performance statistics
real memory  = 17179869184 (16384 MB)
avail memory = 16520966144 (15755 MB)
Event timer "LAPIC" quality 400
ACPI APIC Table: <111111 APIC1503>
FreeBSD/SMP: Multiprocessor System Detected: 6 CPUs
FreeBSD/SMP: 1 package(s) x 6 core(s)
 cpu0 (BSP): APIC ID: 16
 cpu1 (AP): APIC ID: 17
 cpu2 (AP): APIC ID: 18
 cpu3 (AP): APIC ID: 19
 cpu4 (AP): APIC ID: 20
 cpu5 (AP): APIC ID: 21
ioapic0 <Version 2.1> irqs 0-23 on motherboard
kbd1 at kbdmux0
hpt27xx: RocketRAID 27xx controller driver v1.0 (Sep 28 2012 20:26:23)
cryptosoft0: <software crypto> on motherboard
acpi0: <SMCI > on motherboard
acpi0: Power Button (fixed)
acpi0: reservation of fee00000, 1000 (3) failed
acpi0: reservation of ffb80000, 80000 (3) failed
acpi0: reservation of fec10000, 20 (3) failed
acpi0: reservation of 0, a0000 (3) failed
acpi0: reservation of 100000, dff00000 (3) failed
cpu0: <ACPI CPU> on acpi0
cpu1: <ACPI CPU> on acpi0
cpu2: <ACPI CPU> on acpi0
cpu3: <ACPI CPU> on acpi0
cpu4: <ACPI CPU> on acpi0
cpu5: <ACPI CPU> on acpi0
attimer0: <AT timer> port 0x40-0x43 irq 0 on acpi0
Timecounter "i8254" frequency 1193182 Hz quality 0
Event timer "i8254" frequency 1193182 Hz quality 100
atrtc0: <AT realtime clock> port 0x70-0x71 irq 8 on acpi0
Event timer "RTC" frequency 32768 Hz quality 0
hpet0: <High Precision Event Timer> iomem 0xfed00000-0xfed003ff on acpi0
Timecounter "HPET" frequency 14318180 Hz quality 950
Timecounter "ACPI-safe" frequency 3579545 Hz quality 850
acpi_timer0: <24-bit timer at 3.579545MHz> port 0x808-0x80b on acpi0
pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0
pci0: <ACPI PCI bus> on pcib0
pcib1: <ACPI PCI-PCI bridge> irq 16 at device 4.0 on pci0
pci1: <ACPI PCI bus> on pcib1
hpt27xx0: <odin> mem 0xfe8a0000-0xfe8bffff,0xfe8c0000-0xfe8fffff irq 16 at device 0.0 on pci1
hpt27xx: adapter at PCI 1:0:0, IRQ 16
pcib2: <ACPI PCI-PCI bridge> irq 17 at device 9.0 on pci0
pci2: <ACPI PCI bus> on pcib2
em0: <Intel(R) PRO/1000 Network Connection 7.3.2> port 0xd800-0xd81f mem 0xfe9e0000-0xfe9fffff,0xfe9dc000-0xfe9dffff irq 17 at device 0.0 on pci2
em0: Using MSIX interrupts with 3 vectors
em0: Ethernet address: 00:25:90:xx:xx:xx
pcib3: <ACPI PCI-PCI bridge> irq 18 at device 10.0 on pci0
pci3: <ACPI PCI bus> on pcib3
em1: <Intel(R) PRO/1000 Network Connection 7.3.2> port 0xe800-0xe81f mem 0xfeae0000-0xfeafffff,0xfeadc000-0xfeadffff irq 18 at device 0.0 on pci3
em1: Using MSIX interrupts with 3 vectors
em1: Ethernet address: 00:25:90:xx:xx:xx
ahci0: <ATI IXP700 AHCI SATA controller> port 0xc000-0xc007,0xb000-0xb003,0xa000-0xa007,0x9000-0x9003,0x8000-0x800f mem 0xfebfbc00-0xfebfbfff irq 22 at device 17.0 on pci0
ahci0: AHCI v1.10 with 6 3Gbps ports, Port Multiplier supported
ahcich0: <AHCI channel> at channel 0 on ahci0
ahcich1: <AHCI channel> at channel 1 on ahci0
ahcich2: <AHCI channel> at channel 2 on ahci0
ahcich3: <AHCI channel> at channel 3 on ahci0
ahcich4: <AHCI channel> at channel 4 on ahci0
ahcich5: <AHCI channel> at channel 5 on ahci0
ohci0: <AMD SB7x0/SB8x0/SB9x0 USB controller> mem 0xfebf9000-0xfebf9fff irq 16 at device 18.0 on pci0
usbus0 on ohci0
ohci1: <OHCI (generic) USB controller> mem 0xfebfa000-0xfebfafff irq 16 at device 18.1 on pci0
usbus1 on ohci1
ehci0: <AMD SB7x0/SB8x0/SB9x0 USB 2.0 controller> mem 0xfebfb800-0xfebfb8ff irq 17 at device 18.2 on pci0
usbus2: EHCI version 1.0
usbus2 on ehci0
ohci2: <AMD SB7x0/SB8x0/SB9x0 USB controller> mem 0xfebf7000-0xfebf7fff irq 18 at device 19.0 on pci0
usbus3 on ohci2
ohci3: <OHCI (generic) USB controller> mem 0xfebf8000-0xfebf8fff irq 18 at device 19.1 on pci0
usbus4 on ohci3
ehci1: <AMD SB7x0/SB8x0/SB9x0 USB 2.0 controller> mem 0xfebfb400-0xfebfb4ff irq 19 at device 19.2 on pci0
usbus5: EHCI version 1.0
usbus5 on ehci1
pci0: <serial bus, SMBus> at device 20.0 (no driver attached)
atapci0: <ATI IXP700/800 UDMA133 controller> port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0xff00-0xff0f at device 20.1 on pci0
ata1: <ATA channel> at channel 1 on atapci0
isab0: <PCI-ISA bridge> at device 20.3 on pci0
isa0: <ISA bus> on isab0
pcib4: <ACPI PCI-PCI bridge> at device 20.4 on pci0
pci4: <ACPI PCI bus> on pcib4
vgapci0: <VGA-compatible display> mem 0xfc000000-0xfcffffff,0xfdffc000-0xfdffffff,0xfe000000-0xfe7fffff irq 20 at device 4.0 on pci4
ohci4: <AMD SB7x0/SB8x0/SB9x0 USB controller> mem 0xfebf6000-0xfebf6fff irq 18 at device 20.5 on pci0
usbus6 on ohci4
acpi_button0: <Power Button> 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]
uart0: <16550 or compatible> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0
uart1: <16550 or compatible> port 0x2f8-0x2ff irq 3 on acpi0
orm0: <ISA Option ROM> at iomem 0xc0000-0xc7fff 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
ctl: CAM Target Layer loaded
acpi_throttle0: <ACPI CPU Throttling> on cpu0
hwpstate0: <Cool`n'Quiet 2.0> on cpu0
ZFS filesystem version 5
ZFS storage pool version 28
Timecounters tick every 1.000 msec
hpt27xx: Attached device index 00 (Path 00 | Target 00 | E0/Sff)  00000000
hpt27xx: Attached device index 01 (Path 01 | Target 00 | E0/Sff)  00000000
hpt27xx: Attached device index 02 (Path 02 | Target 00 | E0/Sff)  00000000
hpt27xx: Attached device index 03 (Path 03 | Target 00 | E0/Sff)  00000000
hpt27xx: Device error information 0x80400002
hpt27xx: Device error information 0x80400002
hpt27xx: Attached device index 40 (Path 05 | Target 00 | E0/Sff)  00000000
hpt27xx: Attached device index 41 (Path 06 | Target 00 | E0/Sff)  00000000
hpt27xx: Attached device index 42 (Path 07 | Target 00 | E0/Sff)  00000000
hpt27xx0: [GIANT-LOCKED]
usbus0: 12Mbps Full Speed USB v1.0
usbus1: 12Mbps Full Speed USB v1.0
usbus2: 480Mbps High Speed USB v2.0
usbus3: 12Mbps Full Speed USB v1.0
usbus4: 12Mbps Full Speed USB v1.0
usbus5: 480Mbps High Speed USB v2.0
usbus6: 12Mbps Full Speed USB v1.0
ugen0.1: <ATI> at usbus0
uhub0: <ATI OHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus0
ugen1.1: <ATI> at usbus1
uhub1: <ATI OHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus1
ugen2.1: <ATI> at usbus2
uhub2: <ATI EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus2
ugen3.1: <ATI> at usbus3
uhub3: <ATI OHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus3
ugen4.1: <ATI> at usbus4
uhub4: <ATI OHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus4
ugen5.1: <ATI> at usbus5
uhub5: <ATI EHCI root HUB, class 9/0, rev 2.00/1.00, addr 1> on usbus5
ugen6.1: <ATI> at usbus6
uhub6: <ATI OHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus6
uhub6: 2 ports with 2 removable, self powered
uhub0: 3 ports with 3 removable, self powered
uhub1: 3 ports with 3 removable, self powered
uhub3: 3 ports with 3 removable, self powered
uhub4: 3 ports with 3 removable, self powered
(probe7:hpt27xx0:0:7:0): INQUIRY. CDB: 12 0 0 0 24 0 
(probe7:hpt27xx0:0:7:0): CAM status: Invalid Target ID
(probe7:hpt27xx0:0:7:0): Error 22, Unretryable error

[lots more hpt27xx probe lines through 254 deleted]

da0 at hpt27xx0 bus 0 scbus8 target 0 lun 0
da0: <HPT DISK 0_0 4.00> Fixed Direct Access SCSI-0 device 
da0: 2861588MB (5860533168 512 byte sectors: 255H 63S/T 364801C)
da1 at hpt27xx0 bus 0 scbus8 target 1 lun 0
da1: <HPT DISK 0_1 4.00> Fixed Direct Access SCSI-0 device 
da1: 2861588MB (5860533168 512 byte sectors: 255H 63S/T 364801C)
da2 at hpt27xx0 bus 0 scbus8 target 2 lun 0
da2: <HPT DISK 0_2 4.00> Fixed Direct Access SCSI-0 device 
da2: 2861588MB (5860533168 512 byte sectors: 255H 63S/T 364801C)
da3 at hpt27xx0 bus 0 scbus8 target 3 lun 0
da3: <HPT DISK 0_3 4.00> Fixed Direct Access SCSI-0 device 
da3: 2861588MB (5860533168 512 byte sectors: 255H 63S/T 364801C)
da4 at hpt27xx0 bus 0 scbus8 target 4 lun 0
da4: <HPT DISK 0_4 4.00> Fixed Direct Access SCSI-0 device 
da4: 1907729MB (3907029168 512 byte sectors: 255H 63S/T 243201C)
da5 at hpt27xx0 bus 0 scbus8 target 5 lun 0
da5: <HPT DISK 0_5 4.00> Fixed Direct Access SCSI-0 device 
da5: 953869MB (1953525168 512 byte sectors: 255H 63S/T 121601C)
da6 at hpt27xx0 bus 0 scbus8 target 6 lun 0
da6: <HPT DISK 0_6 4.00> Fixed Direct Access SCSI-0 device 
da6: 1907729MB (3907029168 512 byte sectors: 255H 63S/T 243201C)
ada0 at ahcich0 bus 0 scbus0 target 0 lun 0
ada0: <OCZ-VERTEX4 1.5> ATA-9 SATA 3.x device
ada0: 300.000MB/s transfers (SATA 2.x, UDMA6, PIO 8192bytes)
ada0: Command Queueing enabled
ada0: 122104MB (250069680 512 byte sectors: 16H 63S/T 16383C)
ada0: Previously was known as ad0
ada1 at ahcich1 bus 0 scbus1 target 0 lun 0
ada1: <OCZ-VERTEX4 1.5> ATA-9 SATA 3.x device
ada1: 300.000MB/s transfers (SATA 2.x, UDMA6, PIO 8192bytes)
ada1: Command Queueing enabled
ada1: 122104MB (250069680 512 byte sectors: 16H 63S/T 16383C)
ada1: Previously was known as ad1
ada2 at ahcich2 bus 0 scbus2 target 0 lun 0
ada2: <ST31000340AS SD04> ATA-7 SATA 1.x device
ada2: 150.000MB/s transfers (SATA 1.x, UDMA6, PIO 8192bytes)
ada2: Command Queueing enabled
ada2: 953869MB (1953525168 512 byte sectors: 16H 63S/T 16383C)
ada2: Previously was known as ad2
ada3 at ahcich3 bus 0 scbus3 target 0 lun 0
ada3: <ST2000DL003-9VT166 CC32> ATA-8 SATA 3.x device
ada3: 300.000MB/s transfers (SATA 2.x, UDMA6, PIO 8192bytes)
ada3: Command Queueing enabled
ada3: 1907729MB (3907029168 512 byte sectors: 16H 63S/T 16383C)
ada3: Previously was known as ad3
SMP: AP CPU #1 Launched!
SMP: AP CPU #3 Launched!
SMP: AP CPU #5 Launched!
SMP: AP CPU #2 Launched!
SMP: AP CPU #4 Launched!
Timecounter "TSC-low" frequency 10937740 Hz quality 1000
Enter passphrase for ada0p3: uhub5: 6 ports with 6 removable, self powered
uhub2: 6 ports with 6 removable, self powered
Trying to mount root from zfs:zroot []...

I have switched my timecounter to HPET to see if things are different...

Any clues?

-- 
  John-Mark Gurney				Voice: +1 415 225 5579

     "All that I will do, has been done, All that I have, has not."



Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20121008040239.GE1967>