logging

[Hal Murray]

Here is a typical batch of the confusing CLOCK printout:

Apr 12 14:37:35 box.local ntpd[2109]: CLOCK: ts_prev 1555072655 s +
712154322 ns, ts_min 1555072655 s + 712153764 ns
Apr 12 14:37:35 box.local ntpd[2109]: CLOCK: ts 1555072655 s + 712154322 ns
Apr 12 14:37:35 box.local ntpd[2109]: CLOCK: sys_fuzz 1816 nsec, prior
fuzz 0.000001594
Apr 12 14:37:35 box.local ntpd[2109]: CLOCK: this fuzz -0.000001722
Apr 12 14:37:35 box.local ntpd[2109]: CLOCK: prev get_systime
0xe05b050f.b64fb1ce is 0.000000942 later than 0xe05b050f.b64fa201

It looks like something is screwed up with your system clock.

This comes from an area of ntpd that I don't really understand.  I don't 
remember investigating anything like this before.

The general idea is that if your system clock goes tick, tick, tick, in great 
big steps, you want to fill in the bottom bits with randomness.  The code does 
that by assuming that the tick size is the time it takes to read the clock - 
difference in times between 2 back-to-back readings.  That's not right, but 
doesn't normally cause any troubles.  Maybe it skips samples that don't change.

That made sense a long time ago when the system clock was updated on a 10 ms 
clock interrupt.

The error messages say that filling in the low bits made clock go backwards.

I'd really like to rip out all that stuff, but I have at least one Raspberry 
Pi where I can read the clock faster than it ticks.


> Fedora 29 on x86_64 with Garmin gps18x on rs232.

x86_64 covers a lot of ground.  Anything interesting about that system?  Did 
it work correctly a while ago?  Does it work without any refclocks?  Did you 
update the kernel recently?  ...

What do we know about the system timekeeping?  I'm looking for two things.  
The first is from ntpd, probably in your syslog, before switching logging to 
the typical log file.  It should be something like this:
  Apr 12 22:51:29 hgm ntpd[724]: INIT: precision = 0.157 usec (-23)

The other comes from the Linux kernel at boot time.  I don't know a simple 
grep expression to get what I want.  Grep for clocksource is a good start, but 
poke around to see if there is anything interesting nearby.  Grep for MHz may 
be interesting.

Here is what is in my system:
Apr 12 22:50:01 hgm kernel: tsc: Refined TSC clocksource calibration: 3292.520 
MHz
Apr 12 22:50:01 hgm kernel: clocksource: tsc: mask: 0xffffffffffffffff 
max_cycles: 0x2f75b1eac7a, max_idle_ns: 440795210882 ns
Apr 12 22:50:01 hgm kernel: clocksource: Switched to clocksource tsc

That says it's using the TSC on a 3.3 GHz system.

TSC is Intel's TimeStampCounter.  It's a register that counts CPU clock 
cycles.  (or maybe it runs off a pseudo clock so timekeeping works when the 
CPU speed is adjusted to save power)

The basic idea is that you read and save the TSC when you set the clock.  
Then, when you want to know the time, read the TSC again, subtract to get the 
ticks since the last known time, multiply by the time per tick (inverse of 
clock frequency) and add that the the last known time.

You need to be careful with the arithmetic.  The ns per tick variable gets 
adjusted by the clock drift.



-- 
These are my opinions.  I hate spam.