Re: timekeeping regression?

[Brad Spencer <brad%anduin.eldar.org@localhost>]

"Greg A. Woods" <woods%planix.ca@localhost> writes:

[please forgive me if some of this is well known to you, I don't know
who may be following along at home]

> At Mon, 10 Jun 2024 11:27:53 -0400, Brad Spencer <brad%anduin.eldar.org@localhost> wrote:
> Subject: Re: timekeeping regression?
>>
>> ntpd won't correct time if the drift is beyond 500ppm (that is, in a
>> linear manor.. see your drift file for details on what your local
>> situation is), if I remember correctly.. and it will also give up if
>> the spikes are too intense.
>
> Even on the VM that's now "purposefully" drifting wildly (the one with
> tsc_mode=native) ntpd is doing quite well at dragging the system time
> back into conformance.
>
> It has recorded a drift value just 50.172, though oddly it is not
> updating the file hourly like ntp.conf(5) suggests it should be doing.
> It hasn't written the file since booting.  None of my VMs have drift
> values over 66.

I suspect it hasn't updated the file because the VM has lost sync with
the server.  It appears that the drift file on mine is being updated.

> I don't know what a "too intense" spike might be, but there have been
> some big ones on this machine.  It is slowly getting further out of
> control though:

Been a long time.... but my foggy memory is that if you have frequent
spikes and/or large steps due to the spikes, ntpd can and probably will
give up.

Example... a long time ago when I started working at a previous $DAYJOB
the folks there tried to load balance a set of ntpd servers and provide
a single VIP.  This is a completely awful idea unless your load balancer
is designed very specifically to do UDP ntpd.  The one we had wasn't
designed for ntpd and what would happen is that the clients would round
robin between the actual servers.  This caused all manor of spikes from
the point of view of the clients and was more or less unusable.  This
got fixed by just point all of the clients at all of the ntpd servers
and letting ntpd work out which was the best for each polling interval.

> Jun  7 17:47:13 nbtest ntpdate[466]: no server suitable for synchronization found
> Jun  7 17:47:14 nbtest /etc/rc: ntpdate: WARNING: 'ntpdate_start' failed (and not forcing).

BTW - the above can be caused by the network not quite being ready when
ntpdate runs.  I have had problems with dhcpcd not getting the NIC set
up quick enough.  You can extend the timeouts of ntpdate to allow more
time which might help.  In any case, ntpdate probably didn't do anything
for you.

> Jun  7 17:47:16 nbtest ntpd[845]: ntpd 4.2.8p14-o Mon May 25 15:53:34 EDT 2020 (import): Starting
> Jun  7 17:47:16 nbtest ntpd[845]: Command line: /usr/sbin/ntpd -p /var/run/ntpd.pid -g
> Jun  7 17:47:16 nbtest ntpd[845]: ----------------------------------------------------
> Jun  7 17:47:16 nbtest ntpd[845]: ntp-4 is maintained by Network Time Foundation,
> Jun  7 17:47:16 nbtest ntpd[845]: Inc. (NTF), a non-profit 501(c)(3) public-benefit
> Jun  7 17:47:16 nbtest ntpd[845]: corporation.  Support and training for ntp-4 are
> Jun  7 17:47:16 nbtest ntpd[845]: available at https://www.nwtime.org/support
> Jun  7 17:47:16 nbtest ntpd[845]: ----------------------------------------------------
> Jun  7 17:47:16 nbtest ntpd[698]: proto: precision = 0.821 usec (-20)
> Jun  7 17:47:16 nbtest ntpd[698]: basedate set to 2021-11-29
> Jun  7 17:47:16 nbtest ntpd[698]: gps base set to 2021-12-05 (week 2187)
> Jun  7 17:47:16 nbtest ntpd[698]: Listen and drop on 0 v4wildcard 0.0.0.0:123
> Jun  7 17:47:16 nbtest ntpd[698]: Listen normally on 1 xennet0 10.0.1.143:123
> Jun  7 17:47:16 nbtest ntpd[698]: Listen normally on 2 lo0 127.0.0.1:123
> Jun  7 17:47:16 nbtest ntpd[698]: Listening on routing socket on fd #23 for interface updates
> Jun  7 17:47:16 nbtest ntpd[698]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
> Jun  7 17:47:16 nbtest ntpd[698]: 0.0.0.0 c01d 0d kern kernel time sync enabled
> Jun  7 17:47:16 nbtest ntpd[698]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
> Jun  7 17:47:16 nbtest ntpd[698]: 0.0.0.0 c012 02 freq_set kernel 60.507 PPM
> Jun  7 17:47:16 nbtest ntpd[698]: 0.0.0.0 c016 06 restart
> Jun  7 17:47:16 nbtest ntpd[698]: DNS ntp.local -> 10.0.1.140
> Jun  7 17:47:16 nbtest ntpd[698]: 10.0.1.140 8011 81 mobilize assoc 48502
> Jun  7 17:50:34 nbtest ntpd[698]: 10.0.1.140 8014 84 reachable
> Jun  7 17:53:51 nbtest ntpd[698]: 10.0.1.140 901a 8a sys_peer
> Jun  7 17:53:51 nbtest ntpd[698]: 0.0.0.0 c615 05 clock_sync
> Jun  7 18:24:25 nbtest ntpd[698]: 0.0.0.0 0613 03 spike_detect -0.167483 s
> Jun  7 18:26:35 nbtest ntpd[698]: 0.0.0.0 061c 0c clock_step -0.192934 s
> Jun  7 18:26:35 nbtest ntpd[698]: 0.0.0.0 0615 05 clock_sync
> Jun  7 18:27:40 nbtest ntpd[698]: 0.0.0.0 c618 08 no_sys_peer
> Jun  7 18:27:40 nbtest ntpd[698]: 10.0.1.140 8014 84 reachable
> Jun  7 18:36:21 nbtest ntpd[698]: 10.0.1.140 901a 8a sys_peer
> Jun  7 18:36:21 nbtest ntpd[698]: 0.0.0.0 c613 03 spike_detect -0.148030 s
> Jun  7 18:38:33 nbtest ntpd[698]: 0.0.0.0 c61c 0c clock_step -0.198244 s
> Jun  7 18:38:33 nbtest ntpd[698]: 0.0.0.0 c615 05 clock_sync
> Jun  7 18:39:40 nbtest ntpd[698]: 0.0.0.0 c618 08 no_sys_peer
> Jun  7 18:39:40 nbtest ntpd[698]: 10.0.1.140 8014 84 reachable
> Jun  7 18:48:25 nbtest ntpd[698]: 10.0.1.140 901a 8a sys_peer

[snip]

The spikes in this area are not huge, but pretty often in my opinion.

> Jun  7 23:33:19 nbtest ntpd[698]: 0.0.0.0 c613 03 spike_detect -1.634751 s
> Jun  7 23:41:59 nbtest ntpd[698]: 0.0.0.0 c618 08 no_sys_peer
> Jun  7 23:55:03 nbtest ntpd[698]: 10.0.1.140 902a 8a sys_peer
> Jun  7 23:55:03 nbtest ntpd[698]: 0.0.0.0 c61c 0c clock_step -12.830691 s
> Jun  7 23:54:50 nbtest ntpd[698]: 0.0.0.0 c615 05 clock_sync

That is a pretty big step that you wouldn't want to see.

[snip]

> Jun  8 01:20:42 nbtest ntpd[698]: 0.0.0.0 c613 03 spike_detect -2.966584 s
> Jun  8 01:21:47 nbtest ntpd[698]: 0.0.0.0 c618 08 no_sys_peer
> Jun  8 01:52:28 nbtest ntpd[698]: 10.0.1.140 902a 8a sys_peer
> Jun  8 01:52:28 nbtest ntpd[698]: 0.0.0.0 c61c 0c clock_step -22.895367 s
> Jun  8 01:52:05 nbtest ntpd[698]: 0.0.0.0 c615 05 clock_sync
> Jun  8 01:53:13 nbtest ntpd[698]: 0.0.0.0 c618 08 no_sys_peer
> Jun  8 01:53:13 nbtest ntpd[698]: 10.0.1.140 8014 84 reachable
> Jun  8 02:19:13 nbtest ntpd[698]: 10.0.1.140 901a 8a sys_peer
> Jun  8 02:19:13 nbtest ntpd[698]: 0.0.0.0 c613 03 spike_detect -14.495190 s
> Jun  8 02:23:38 nbtest ntpd[698]: 0.0.0.0 c618 08 no_sys_peer
> Jun  8 02:25:50 nbtest ntpd[698]: 10.0.1.140 902a 8a sys_peer
> Jun  8 02:25:50 nbtest ntpd[698]: 0.0.0.0 c61c 0c clock_step -18.756659 s
> Jun  8 02:25:31 nbtest ntpd[698]: 0.0.0.0 c615 05 clock_sync
> Jun  8 02:26:39 nbtest ntpd[698]: 0.0.0.0 c618 08 no_sys_peer
> Jun  8 02:26:39 nbtest ntpd[698]: 10.0.1.140 8014 84 reachable
> Jun  8 04:25:34 nbtest ntpd[698]: 10.0.1.140 901a 8a sys_peer
> Jun  8 04:25:34 nbtest ntpd[698]: 0.0.0.0 c613 03 spike_detect -138.348001 s
> Jun  8 04:27:46 nbtest ntpd[698]: 0.0.0.0 c61c 0c clock_step -139.086792 s
> Jun  8 04:25:27 nbtest ntpd[698]: 0.0.0.0 c615 05 clock_sync
> Jun  8 04:26:31 nbtest ntpd[698]: 0.0.0.0 c618 08 no_sys_peer
> Jun  8 04:26:31 nbtest ntpd[698]: 10.0.1.140 8014 84 reachable
> Jun  8 04:31:57 nbtest ntpd[698]: 10.0.1.140 901a 8a sys_peer

Those spikes and the resulting step are very bad.

[snip]

As for the rest, the spike behavior isn't constant, but it comes in
bursts such that I would suggest that it is a problem.  The magnitude of
some of those steps is large and probably causing trouble with ntpd.

>
> I don't think it will recover this time, but I'll wait and see:

I would agree...

> # ntpq -p
>      remote           refid      st t when poll reach   delay   offset  jitter
> ==============================================================================
>  xentastic.local 192.75.191.6     3 u   36   64  377    0.079  -859408 22202.4
>
> # ntpq -n -c rv
> associd=0 status=c018 leap_alarm, sync_unspec, 1 event, no_sys_peer,
> version="ntpd 4.2.8p14-o Mon May 25 15:53:34 EDT 2020 (import)",
> processor="amd64", system="NetBSD/9.99.81", leap=11, stratum=3,
> precision=-20, rootdelay=54.096, rootdisp=647399.296, refid=10.0.1.140,
> reftime=ea11d112.4d4d6e34  Mon, Jun 10 2024 12:22:58.301,
> clock=ea11e1aa.fb6496c7  Mon, Jun 10 2024 13:33:46.982, peer=0, tc=6,
> mintc=5, offset=+0.000000, frequency=+50.172, sys_jitter=0.000000,
> clk_jitter=0.001, clk_wander=0.122
>

That system is already unsynced.  The sync_unspec and no_sys_peer....
the rootdisp (root dispersion) is off the charts. and a root delay that
large would usually suggest a far remote system, which I don't think is
the case here.  I can't rule out that the rootdelay and rootdisp values
have not been updated due to a lack of sync... (I plead foggy memory
again).  Is is likely that ntpd is doing it best at this point, but
without being synced to a reliable source, it is more or less running in
local mode and will start to lose sooner or later.


This is one of mine:

testcurrent# ntpq -n -c rv
associd=0 status=0615 leap_none, sync_ntp, 1 event, clock_sync,
version="ntpd 4.2.8p15-o Fri Apr 19 18:08:22 UTC 2024 (1)",
processor="amd64", system="NetBSD/10.99.10", leap=00, stratum=3,
precision=-21, rootdelay=0.955, rootdisp=31.521, refid=11.192.214.210,
reftime=ea120054.95c1fb75  Mon, Jun 10 2024 18:44:36.584,
clock=ea12052c.1ae0c5ce  Mon, Jun 10 2024 19:05:16.104, peer=17837, tc=9,
mintc=3, offset=-0.480609, frequency=+22.311, sys_jitter=0.061555,
clk_jitter=0.062, clk_wander=0.019

You should see a sync_ntp and clock_sync, a small rootdelay for a local
time source and a low rootdisp (this one is actually a bit high, but I
don't give this Xen guest very much schedule credit).

I notice that your "ntpq -p" output confirms the lack of a sync partner,
which isn't a suprise given the offset.  ntpd won't correct something
that large.

testcurrent# ntpq -pn
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
 0.time.eldar.or .POOL.          16 p    -   64    0    0.000   +0.000   0.000
 1.time.eldar.or .POOL.          16 p    -   64    0    0.000   +0.000   0.000
-10.1.0.240      212.246.247.131  2 u  330  512  377    0.811   -0.526   0.277
-2001:470:c620:2 10.1.0.7         2 u  294  512  377    0.663   -0.322   0.176
*2001:470:c620:4 212.246.247.131  2 u  305  512  377    0.116   -0.498   0.080
+2001:470:c620:0 212.246.247.131  2 u  361  512  377    0.216   -0.483   0.068
-10.1.0.11       10.1.0.7         2 u  481 1024  377    0.686   -0.384   0.104
+2001:470:c620:2 212.246.247.131  2 u   29  512  377    0.671   -0.483   0.048
+10.1.20.1       10.1.0.7         2 u  189  512  377    1.523   -0.469   0.251
+24.106.248.90   212.246.247.131  2 u  514  512  377    0.209   -0.409   0.124

You need to have a '*' in the first column, otherwise you are not
synced.  The '+' are possible candidates and the '-' are candidates that
were rejected (in the last polling interval, that is, they may be
considered again later).  You can also see '#' which is a unconsidered
server, because there were more than enough servers to consider already.
Those will fall off sooner or later probably.

[I run ntpd pools around here, and one of the systems is listed by each
of its network addresses, hence the large number of possible candidates.
I also have a pool for IPv4 and one for IPv6, so many of those addresses
point to the same system.  Sometimes IPv6 will provide for a better
result than IPv4 from the same host]


> BTW, it's configuration is just:
>
> pidfile /var/run/ntpd.pid
> tinker panic 0
> driftfile /var/db/ntp.drift
> logconfig +allall
> mdnstries 0
> discard average 5 minimum 2
> enable mode7
> restrict default limited kod nomodify nopeer notrap noquery noserve
> restrict source nomodify notrap noquery
> restrict 127.0.0.1
> restrict 127.127.1.0
> server  ntp.local
> restrict ntp.local

Nothing very unusual with all of that, except that I usually try to come
up with more than just one server.  Various opinions exist on this
particular matter, but I usually try not to have less than 3 ntpd
servers, and not more than 9 (it doesn't help to have more than 9 in any
case, as the algorithm won't use the rest).  It appears to be the case
that 2 servers is also a problem (as I understand it, also an algorithm
thing, but I don't remember what it didn't like about 2 candidates), so
that is best avoided too.

It is possible that chronyd can help here.  One of its major use cases
is on wondering systems that come and go from networks and it can cope
with spikes and such a bit better than ntpd.  It turns out that
wondering VMs may look a lot like a wondering system.  I have used
chronyd in a number of cases that ntpd won't deal with.

>
> --
> 					Greg A. Woods <gwoods%acm.org@localhost>
>
> Kelowna, BC     +1 250 762-7675           RoboHack <woods%robohack.ca@localhost>
> Planix, Inc. <woods%planix.com@localhost>     Avoncote Farms <woods%avoncote.ca@localhost>





-- 
Brad Spencer - brad%anduin.eldar.org@localhost - KC8VKS - http://anduin.eldar.org