instability of timekeeping

Tue Oct 20 11:06:57 UTC 2015

I performed a small observation.  With ntpd disabled I ran `ntpdate -d` at 10
second intervals in a loop (done via `sleep 10`).  It looks like for about 25
minutes the time offset between a reference server and my machine was quite
stable. But then it sort of jumped about 2.5 seconds between two consecutive
ntpdate invocations.

20 Oct 13:21:02 ntpdate[85157]: ntpdate 4.2.8p3-a (1)
Looking for host ntp.time.in.ua and service ntp
62.149.0.30 reversed to ntp.time.in.ua
transmit(62.149.0.30)
receive(62.149.0.30)
transmit(62.149.0.30)
receive(62.149.0.30)
transmit(62.149.0.30)
receive(62.149.0.30)
transmit(62.149.0.30)
receive(62.149.0.30)
server 62.149.0.30, port 123
stratum 1, precision -20, leap 00, trust 000
refid [GPS], delay 0.03326, dispersion 0.00014
transmitted 4, in filter 4
reference time:    d9d09422.65c26838  Tue, Oct 20 2015 13:21:22.397
originate timestamp: d9d0942f.a03ebee7  Tue, Oct 20 2015 13:21:35.625
transmit timestamp:  d9d09414.e9ed230c  Tue, Oct 20 2015 13:21:08.913
filter delay:  0.03372  0.03491  0.03378  0.03326
         0.00000  0.00000  0.00000  0.00000
filter offset: 26.70845 26.70896 26.70834 26.70832
         0.000000 0.000000 0.000000 0.000000
delay 0.03326, dispersion 0.00014
offset 26.708320

20 Oct 13:21:08 ntpdate[85157]: step time server 62.149.0.30 offset 26.708320 sec

[...]

20 Oct 13:45:20 ntpdate[87088]: ntpdate 4.2.8p3-a (1)
Looking for host ntp.time.in.ua and service ntp
62.149.0.30 reversed to ntp.time.in.ua
transmit(62.149.0.30)
receive(62.149.0.30)
transmit(62.149.0.30)
receive(62.149.0.30)
transmit(62.149.0.30)
receive(62.149.0.30)
transmit(62.149.0.30)
receive(62.149.0.30)
server 62.149.0.30, port 123
stratum 1, precision -20, leap 00, trust 000
refid [GPS], delay 0.03442, dispersion 0.00018
transmitted 4, in filter 4
reference time:    d9d099d3.67703742  Tue, Oct 20 2015 13:45:39.404
originate timestamp: d9d099e1.8a1b6c78  Tue, Oct 20 2015 13:45:53.539
transmit timestamp:  d9d099c6.d34c1e00  Tue, Oct 20 2015 13:45:26.825
filter delay:  0.03481  0.03442  0.03448  0.03458
         0.00000  0.00000  0.00000  0.00000
filter offset: 26.70957 26.70943 26.70913 26.70957
         0.000000 0.000000 0.000000 0.000000
delay 0.03442, dispersion 0.00018
offset 26.709437

20 Oct 13:45:26 ntpdate[87088]: step time server 62.149.0.30 offset 26.709437 sec

20 Oct 13:45:36 ntpdate[87094]: ntpdate 4.2.8p3-a (1)
Looking for host ntp.time.in.ua and service ntp
62.149.0.30 reversed to ntp.time.in.ua
transmit(62.149.0.30)
receive(62.149.0.30)
transmit(62.149.0.30)
receive(62.149.0.30)
transmit(62.149.0.30)
receive(62.149.0.30)
transmit(62.149.0.30)
receive(62.149.0.30)
server 62.149.0.30, port 123
stratum 1, precision -20, leap 00, trust 000
refid [GPS], delay 0.03349, dispersion 0.00012
transmitted 4, in filter 4
reference time:    d9d099e5.63ead89c  Tue, Oct 20 2015 13:45:57.390
originate timestamp: d9d099f4.6364c717  Tue, Oct 20 2015 13:46:12.388
transmit timestamp:  d9d099d7.00939943  Tue, Oct 20 2015 13:45:43.002
filter delay:  0.03349  0.03413  0.03419  0.03455
         0.00000  0.00000  0.00000  0.00000
filter offset: 29.38105 29.38106 29.38134 29.38149
         0.000000 0.000000 0.000000 0.000000
delay 0.03349, dispersion 0.00012
offset 29.381055

20 Oct 13:45:43 ntpdate[87094]: step time server 62.149.0.30 offset 29.381055 sec

On 20/10/2015 13:12, Andriy Gapon wrote:
> 
> I recently replaced a 2-core Athlon II X2 CPU with a same-family Phenom II X4
> CPU and after that I started noticing problems with the timekeeping.  It seems
> that from time to time the jitter becomes so high that ntpd goes nuts or stops
> synchronizing or panics.
> 
> Here how the current event timer and time counter configurations look (slightly
> trimmed):
> $ sysctl kern.timecounter
> kern.timecounter.tsc_shift: 1
> kern.timecounter.smp_tsc_adjust: 0
> kern.timecounter.smp_tsc: 1
> kern.timecounter.invariant_tsc: 1
> kern.timecounter.fast_gettime: 1
> kern.timecounter.tick: 1
> kern.timecounter.choice: TSC-low(800) ACPI-fast(900) HPET(950) i8254(0)
> dummy(-1000000)
> kern.timecounter.hardware: TSC-low
> kern.timecounter.alloweddeviation: 5
> kern.timecounter.stepwarnings: 0
> kern.timecounter.tc.TSC-low.quality: 800
> kern.timecounter.tc.TSC-low.frequency: 1607357461
> kern.timecounter.tc.TSC-low.counter: 2457319922
> kern.timecounter.tc.TSC-low.mask: 4294967295
> kern.timecounter.tc.ACPI-fast.quality: 900
> kern.timecounter.tc.HPET.quality: 950
> kern.timecounter.tc.i8254.quality: 0
> $ sysctl kern.eventtimer
> kern.eventtimer.periodic: 0
> kern.eventtimer.timer: HPET
> kern.eventtimer.idletick: 0
> kern.eventtimer.singlemul: 2
> kern.eventtimer.choice: HPET(450) HPET1(450) HPET2(450) LAPIC(400) i8254(100) RTC(0)
> kern.eventtimer.et.RTC.quality: 0
> kern.eventtimer.et.HPET2.quality: 450
> kern.eventtimer.et.HPET1.quality: 450
> kern.eventtimer.et.HPET.quality: 450
> kern.eventtimer.et.HPET.frequency: 14318180
> kern.eventtimer.et.HPET.flags: 3
> kern.eventtimer.et.i8254.quality: 100
> kern.eventtimer.et.LAPIC.quality: 400
> 
> Please note is that TSC-low time counter is chosen administratively whereas the
> event timer configuration is fully automatic.
> The previous configuration was produced in the same fashion.
> One notable difference is that the previous CPU was 2-core and so two HPET
> timers were virtually combined into a single timer with per-CPU capability.  In
> other words, two HPET timers used two drive two cores.
> The newer CPU has four cores, so there are not enough HPET timers to drive each
> core independently and thus there is no virtual bundling.  Thus, one HPET timer
> drives one core and that core forwards the interrupts to other cores via IPIs as
> necessary.
> 
> But I am far from sure that the stated difference is actually the source of the
> instability.  There could be other hardware-related reasons, of course.
> 
> I wonder if there is a good way to analyze / debug this situation to see what
> exactly is wrong.  For now I am thinking about trying different time counter and
> event timer configurations, but I would prefer a more guided "scientific"
> approach over a blind trial and error one.
> 
> I would appreciate any help, suggestions, hints.
> 
> The CPUs:
> CPU: AMD Athlon(tm) II X2 250 Processor (3013.79-MHz K8-class CPU)
>   Origin="AuthenticAMD"  Id=0x100f62  Family=0x10  Model=0x6  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=0x802009<SSE3,MON,CX16,POPCNT>
>   AMD Features=0xee500800<SYSCALL,NX,MMX+,FFXSR,Page1GB,RDTSCP,LM,3DNow!+,3DNow!>
>   AMD
> Features2=0x37ff<LAHF,CMP,SVM,ExtAPIC,CR8,ABM,SSE4A,MAS,Prefetch,OSVW,IBS,SKINIT,WDT>
>   SVM: Features=0xf<NP,LbrVirt,SVML,NRIPS>
> Revision=1, ASIDs=64
>   TSC: P-state invariant
> 
> CPU: AMD Phenom(tm) II X4 955 Processor (3214.71-MHz K8-class CPU)
>   Origin="AuthenticAMD"  Id=0x100f43  Family=0x10  Model=0x4  Stepping=3
> 
> 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=0x802009<SSE3,MON,CX16,POPCNT>
>   AMD Features=0xee500800<SYSCALL,NX,MMX+,FFXSR,Page1GB,RDTSCP,LM,3DNow!+,3DNow!>
>   AMD
> Features2=0x37ff<LAHF,CMP,SVM,ExtAPIC,CR8,ABM,SSE4A,MAS,Prefetch,OSVW,IBS,SKINIT,WDT>
>   SVM: Features=0xf<NP,LbrVirt,SVML,NRIPS>
> Revision=1, ASIDs=64
>   TSC: P-state invariant
> 

-- 
Andriy Gapon