Hi guys.
I am using NTPD to synchronize the system clock of a BeagleBone Black to an external uBlox GNSS receiver with PPS. We use this as a timeserver on a robotic platform as part of a university project. It serves time to other components using NTP and PTP. This system is often turned on/off and can for some times loose GNSS fix. In normal operation it has GNSS fix and should sync its system clock to it is expected that it might loose fix for a couple of minutes every now and then. Ideally the system should always sync its system clock to GNSS whenever it has fix and there is a PPS.
What often happens is that NTPD gets into an unsynchronized state where it is >100ms out of sync with the PPS. I would expect this value to decrease. But sometimes it just keeps increasing until it suddenly doesnt reach anymore PPS. The ntp.log typically reports something like:
17 Sep 08:20:13 ntpd[716]: GPS_NMEA(0) 8012 82 demobilize assoc 12371
17 Sep 08:20:13 ntpd[716]: 127.127.20.0 local addr 127.0.0.1 -> <null>
17 Sep 08:20:13 ntpd[716]: PPS(0) 8012 82 demobilize assoc 12372
17 Sep 08:20:13 ntpd[716]: 127.127.22.0 local addr 127.0.0.1 -> <null>
17 Sep 08:20:13 ntpd[716]: LOCAL(0) 8012 82 demobilize assoc 12373
17 Sep 08:20:13 ntpd[716]: 127.127.1.0 local addr 127.0.0.1 -> <null>
17 Sep 08:20:13 ntpd[716]: 0.0.0.0 c01d 0d kern kernel time sync disabled
17 Sep 08:20:13 ntpd[859]: Listen and drop on 0 v6wildcard [::]:123
17 Sep 08:20:13 ntpd[859]: Listen and drop on 1 v4wildcard 0.0.0.0:123
17 Sep 08:20:13 ntpd[859]: Listen normally on 2 lo 127.0.0.1:123
17 Sep 08:20:13 ntpd[859]: Listen normally on 3 lo [::1]:123
17 Sep 08:20:13 ntpd[859]: Listening on routing socket on fd #20 for interface updates
17 Sep 08:20:13 ntpd[859]: GPS_NMEA(0) serial /dev/gps0 open at 38400 bps
17 Sep 08:20:13 ntpd[859]: GPS_NMEA(0) 8011 81 mobilize assoc 7612
17 Sep 08:20:13 ntpd[859]: PPS(0) 8011 81 mobilize assoc 7613
17 Sep 08:20:13 ntpd[859]: LOCAL(0) 8011 81 mobilize assoc 7614
17 Sep 08:20:13 ntpd[859]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
17 Sep 08:20:13 ntpd[859]: 0.0.0.0 c01d 0d kern kernel time sync enabled
17 Sep 08:20:13 ntpd[859]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
17 Sep 08:20:13 ntpd[859]: 0.0.0.0 c012 02 freq_set kernel 0.000 PPM
17 Sep 08:20:13 ntpd[859]: 0.0.0.0 c011 01 freq_not_set
17 Sep 08:20:13 ntpd[859]: 0.0.0.0 c016 06 restart
17 Sep 08:20:14 ntpd[859]: GPS_NMEA(0) 801b 8b clock_event clk_bad_format
17 Sep 08:20:14 ntpd[859]: GPS_NMEA(0) 802b 8b clock_event clk_no_reply
17 Sep 08:20:15 ntpd[859]: GPS_NMEA(0) 803b 8b clock_event clk_bad_format
17 Sep 08:20:16 ntpd[859]: LOCAL(0) 8014 84 reachable
17 Sep 08:20:29 ntpd[859]: Listen normally on 4 eth0 192.168.10.181:123
17 Sep 08:20:29 ntpd[859]: bind(24) AF_INET6 fe80::42bd:32ff:fee7:b336%2#123 flags 0x11 failed: Cannot assign requested address
17 Sep 08:20:29 ntpd[859]: unable to create socket on eth0 (5) for fe80::42bd:32ff:fee7:b336%2#123
17 Sep 08:20:29 ntpd[859]: failed to init interface for address fe80::42bd:32ff:fee7:b336%2
17 Sep 08:20:29 ntpd[859]: new interface(s) found: waking up resolver
17 Sep 08:20:30 ntpd[859]: GPS_NMEA(0) 8014 84 reachable
17 Sep 08:20:30 ntpd[859]: GPS_NMEA(0) 901a 8a sys_peer
17 Sep 08:20:30 ntpd[859]: 0.0.0.0 c41c 0c clock_step +519673.185191 s
23 Sep 08:41:44 ntpd[859]: 0.0.0.0 c414 04 freq_mode
23 Sep 08:41:45 ntpd[859]: 0.0.0.0 c418 08 no_sys_peer
23 Sep 08:41:45 ntpd[859]: Listen normally on 6 eth0 [fe80::42bd:32ff:fee7:b336%2]:123
23 Sep 08:41:45 ntpd[859]: new interface(s) found: waking up resolver
23 Sep 08:41:47 ntpd[859]: LOCAL(0) 8024 84 reachable
23 Sep 08:42:00 ntpd[859]: GPS_NMEA(0) 8014 84 reachable
23 Sep 08:42:00 ntpd[859]: GPS_NMEA(0) 901a 8a sys_peer
23 Sep 08:44:56 ntpd[859]: GPS_NMEA(0) 961b 8b clock_event clk_no_reply
23 Sep 08:46:48 ntpd[859]: kernel reports TIME_ERROR: 0x40: Clock Unsynchronized
23 Sep 08:46:48 ntpd[859]: 0.0.0.0 c412 02 freq_set kernel -75.665 PPM
23 Sep 08:46:48 ntpd[859]: 0.0.0.0 c415 05 clock_sync
23 Sep 08:46:49 ntpd[859]: PPS(0) 801b 8b clock_event clk_no_reply
23 Sep 08:46:57 ntpd[859]: PPS(0) 8014 84 reachable
23 Sep 08:46:57 ntpd[859]: PPS(0) 901a 8a sys_peer
23 Sep 08:46:57 ntpd[859]: 0.0.0.0 0113 03 spike_detect +0.133322 s
23 Sep 08:50:19 ntpd[859]: LOCAL(0) 8013 83 unreachable
23 Sep 08:51:53 ntpd[859]: 0.0.0.0 011c 0c clock_step +0.143604 s
23 Sep 08:51:53 ntpd[859]: 0.0.0.0 0115 05 clock_sync
23 Sep 08:51:53 ntpd[859]: 0.0.0.0 c118 08 no_sys_peer
23 Sep 08:51:58 ntpd[859]: LOCAL(0) 8014 84 reachable
23 Sep 08:52:09 ntpd[859]: GPS_NMEA(0) 8014 84 reachable
23 Sep 08:52:09 ntpd[859]: GPS_NMEA(0) 901a 8a sys_peer
23 Sep 08:52:09 ntpd[859]: 0.0.0.0 c413 03 spike_detect -0.153138 s
23 Sep 08:56:57 ntpd[859]: 0.0.0.0 c41c 0c clock_step -0.146502 s
23 Sep 08:56:57 ntpd[859]: 0.0.0.0 c415 05 clock_sync
23 Sep 08:56:58 ntpd[859]: 0.0.0.0 c418 08 no_sys_peer
23 Sep 08:56:59 ntpd[859]: LOCAL(0) 8024 84 reachable
23 Sep 08:57:13 ntpd[859]: GPS_NMEA(0) 8014 84 reachable
23 Sep 08:57:13 ntpd[859]: GPS_NMEA(0) 901a 8a sys_peer
23 Sep 08:57:14 ntpd[859]: PPS(0) 8014 84 reachable
23 Sep 08:57:14 ntpd[859]: PPS(0) 901a 8a sys_peer
23 Sep 08:57:14 ntpd[859]: 0.0.0.0 0113 03 spike_detect +0.155371 s
23 Sep 09:02:18 ntpd[859]: 0.0.0.0 011c 0c clock_step +0.163874 s
23 Sep 09:02:18 ntpd[859]: 0.0.0.0 0115 05 clock_sync
23 Sep 09:02:19 ntpd[859]: 0.0.0.0 c118 08 no_sys_peer
23 Sep 09:02:19 ntpd[859]: LOCAL(0) 8034 84 reachable
23 Sep 09:02:19 ntpd[859]: GPS_NMEA(0) 8014 84 reachable
23 Sep 09:02:19 ntpd[859]: GPS_NMEA(0) 901a 8a sys_peer
23 Sep 09:02:19 ntpd[859]: 0.0.0.0 c413 03 spike_detect -0.139359 s
23 Sep 09:07:23 ntpd[859]: 0.0.0.0 c41c 0c clock_step -0.139128 s
23 Sep 09:07:23 ntpd[859]: 0.0.0.0 c415 05 clock_sync
23 Sep 09:07:24 ntpd[859]: 0.0.0.0 c418 08 no_sys_peer
23 Sep 09:07:24 ntpd[859]: LOCAL(0) 8044 84 reachable
23 Sep 09:07:39 ntpd[859]: GPS_NMEA(0) 8014 84 reachable
23 Sep 09:07:39 ntpd[859]: GPS_NMEA(0) 901a 8a sys_peer
23 Sep 09:07:40 ntpd[859]: PPS(0) 8014 84 reachable
23 Sep 09:07:40 ntpd[859]: PPS(0) 901a 8a sys_peer
23 Sep 09:07:40 ntpd[859]: 0.0.0.0 0113 03 spike_detect +0.147990 s
23 Sep 09:12:44 ntpd[859]: 0.0.0.0 011c 0c clock_step +0.156474 s
23 Sep 09:12:44 ntpd[859]: 0.0.0.0 0115 05 clock_sync
23 Sep 09:12:46 ntpd[859]: 0.0.0.0 c118 08 no_sys_peer
23 Sep 09:12:46 ntpd[859]: LOCAL(0) 8054 84 reachable
23 Sep 09:12:47 ntpd[859]: GPS_NMEA(0) 8014 84 reachable
23 Sep 09:12:47 ntpd[859]: GPS_NMEA(0) 901a 8a sys_peer
23 Sep 09:12:47 ntpd[859]: 0.0.0.0 c413 03 spike_detect -0.136619 s
23 Sep 09:17:51 ntpd[859]: 0.0.0.0 c41c 0c clock_step -0.137690 s
23 Sep 09:17:51 ntpd[859]: 0.0.0.0 c415 05 clock_sync
23 Sep 09:17:53 ntpd[859]: 0.0.0.0 c418 08 no_sys_peer
23 Sep 09:17:53 ntpd[859]: LOCAL(0) 8064 84 reachable
23 Sep 09:18:07 ntpd[859]: GPS_NMEA(0) 8014 84 reachable
23 Sep 09:18:07 ntpd[859]: GPS_NMEA(0) 901a 8a sys_peer
23 Sep 09:18:09 ntpd[859]: PPS(0) 8014 84 reachable
23 Sep 09:18:09 ntpd[859]: PPS(0) 901a 8a sys_peer
23 Sep 09:18:09 ntpd[859]: 0.0.0.0 0113 03 spike_detect +0.146715 s
23 Sep 09:23:13 ntpd[859]: 0.0.0.0 011c 0c clock_step +0.149299 s
23 Sep 09:23:13 ntpd[859]: 0.0.0.0 0115 05 clock_sync
23 Sep 09:23:14 ntpd[859]: 0.0.0.0 c118 08 no_sys_peer
23 Sep 09:23:14 ntpd[859]: LOCAL(0) 8074 84 reachable
23 Sep 09:23:16 ntpd[859]: GPS_NMEA(0) 8014 84 reachable
23 Sep 09:23:16 ntpd[859]: GPS_NMEA(0) 901a 8a sys_peer
23 Sep 09:23:16 ntpd[859]: 0.0.0.0 c413 03 spike_detect -0.138520 s
23 Sep 09:28:20 ntpd[859]: 0.0.0.0 c41c 0c clock_step -0.129804 s
23 Sep 09:28:20 ntpd[859]: 0.0.0.0 c415 05 clock_sync
23 Sep 09:28:21 ntpd[859]: 0.0.0.0 c418 08 no_sys_peer
23 Sep 09:28:21 ntpd[859]: LOCAL(0) 8084 84 reachable
23 Sep 09:28:36 ntpd[859]: GPS_NMEA(0) 8014 84 reachable
23 Sep 09:28:36 ntpd[859]: GPS_NMEA(0) 901a 8a sys_peer
23 Sep 09:28:38 ntpd[859]: PPS(0) 8014 84 reachable
23 Sep 09:28:38 ntpd[859]: PPS(0) 901a 8a sys_peer
23 Sep 09:28:38 ntpd[859]: 0.0.0.0 0113 03 spike_detect +0.138418 s
23 Sep 09:33:42 ntpd[859]: 0.0.0.0 011c 0c clock_step +0.146278 s
23 Sep 09:33:42 ntpd[859]: 0.0.0.0 0115 05 clock_sync
23 Sep 09:33:42 ntpd[859]: 0.0.0.0 c118 08 no_sys_peer
23 Sep 09:33:43 ntpd[859]: LOCAL(0) 8094 84 reachable
23 Sep 09:33:58 ntpd[859]: GPS_NMEA(0) 8014 84 reachable
23 Sep 09:33:58 ntpd[859]: GPS_NMEA(0) 901a 8a sys_peer
23 Sep 09:33:58 ntpd[859]: 0.0.0.0 c413 03 spike_detect -0.137967 s
23 Sep 09:38:46 ntpd[859]: 0.0.0.0 c41c 0c clock_step -0.135548 s
23 Sep 09:38:46 ntpd[859]: 0.0.0.0 c415 05 clock_sync
23 Sep 09:38:47 ntpd[859]: 0.0.0.0 c418 08 no_sys_peer
23 Sep 09:38:49 ntpd[859]: LOCAL(0) 80a4 84 reachable
23 Sep 09:39:02 ntpd[859]: GPS_NMEA(0) 8014 84 reachable
23 Sep 09:39:02 ntpd[859]: GPS_NMEA(0) 901a 8a sys_peer
23 Sep 09:39:03 ntpd[859]: PPS(0) 8014 84 reachable
23 Sep 09:39:03 ntpd[859]: PPS(0) 901a 8a sys_peer
23 Sep 09:39:03 ntpd[859]: 0.0.0.0 0113 03 spike_detect +0.143968 s
23 Sep 09:44:07 ntpd[859]: 0.0.0.0 011c 0c clock_step +0.148765 s
23 Sep 09:44:07 ntpd[859]: 0.0.0.0 0115 05 clock_sync
23 Sep 09:44:08 ntpd[859]: 0.0.0.0 c118 08 no_sys_peer
23 Sep 09:44:08 ntpd[859]: GPS_NMEA(0) 8014 84 reachable
23 Sep 09:44:08 ntpd[859]: GPS_NMEA(0) 901a 8a sys_peer
23 Sep 09:44:08 ntpd[859]: 0.0.0.0 c413 03 spike_detect -0.145573 s
23 Sep 09:49:12 ntpd[859]: 0.0.0.0 c41c 0c clock_step -0.133409 s
23 Sep 09:49:12 ntpd[859]: 0.0.0.0 c415 05 clock_sync
23 Sep 09:49:13 ntpd[859]: 0.0.0.0 c418 08 no_sys_peer
23 Sep 09:49:14 ntpd[859]: LOCAL(0) 80b4 84 reachable
23 Sep 09:49:28 ntpd[859]: GPS_NMEA(0) 8014 84 reachable
23 Sep 09:49:28 ntpd[859]: GPS_NMEA(0) 901a 8a sys_peer
23 Sep 09:49:29 ntpd[859]: PPS(0) 8014 84 reachable
23 Sep 09:49:29 ntpd[859]: PPS(0) 901a 8a sys_peer
23 Sep 09:49:29 ntpd[859]: 0.0.0.0 0113 03 spike_detect +0.141685 s
23 Sep 09:54:33 ntpd[859]: 0.0.0.0 011c 0c clock_step +0.149252 s
23 Sep 09:54:33 ntpd[859]: 0.0.0.0 0115 05 clock_sync
23 Sep 09:54:33 ntpd[859]: 0.0.0.0 c118 08 no_sys_peer
23 Sep 09:54:37 ntpd[859]: LOCAL(0) 80c4 84 reachable
23 Sep 09:54:49 ntpd[859]: GPS_NMEA(0) 8014 84 reachable
23 Sep 09:54:49 ntpd[859]: GPS_NMEA(0) 901a 8a sys_peer
23 Sep 09:54:49 ntpd[859]: 0.0.0.0 c413 03 spike_detect -0.139208 s
23 Sep 09:59:37 ntpd[859]: 0.0.0.0 c41c 0c clock_step -0.137973 s
23 Sep 09:59:37 ntpd[859]: 0.0.0.0 c415 05 clock_sync
23 Sep 09:59:39 ntpd[859]: 0.0.0.0 c418 08 no_sys_peer
23 Sep 09:59:40 ntpd[859]: LOCAL(0) 80d4 84 reachable
23 Sep 09:59:53 ntpd[859]: GPS_NMEA(0) 8014 84 reachable
23 Sep 09:59:53 ntpd[859]: GPS_NMEA(0) 901a 8a sys_peer
23 Sep 09:59:55 ntpd[859]: PPS(0) 8014 84 reachable
23 Sep 09:59:55 ntpd[859]: PPS(0) 901a 8a sys_peer
23 Sep 09:59:55 ntpd[859]: 0.0.0.0 0113 03 spike_detect +0.146197 s
23 Sep 10:04:59 ntpd[859]: 0.0.0.0 011c 0c clock_step +0.153397 s
23 Sep 10:04:59 ntpd[859]: 0.0.0.0 0115 05 clock_sync
23 Sep 10:05:02 ntpd[859]: 0.0.0.0 c118 08 no_sys_peer
23 Sep 10:05:02 ntpd[859]: GPS_NMEA(0) 8014 84 reachable
23 Sep 10:05:02 ntpd[859]: GPS_NMEA(0) 901a 8a sys_peer
23 Sep 10:05:02 ntpd[859]: 0.0.0.0 c413 03 spike_detect -0.144527 s
23 Sep 10:10:06 ntpd[859]: 0.0.0.0 c41c 0c clock_step -0.138376 s
23 Sep 10:10:06 ntpd[859]: 0.0.0.0 c415 05 clock_sync
23 Sep 10:10:07 ntpd[859]: 0.0.0.0 c418 08 no_sys_peer
23 Sep 10:10:07 ntpd[859]: LOCAL(0) 80e4 84 reachable
23 Sep 10:10:22 ntpd[859]: GPS_NMEA(0) 8014 84 reachable
23 Sep 10:10:22 ntpd[859]: GPS_NMEA(0) 901a 8a sys_peer
23 Sep 10:10:23 ntpd[859]: PPS(0) 8014 84 reachable
23 Sep 10:10:23 ntpd[859]: PPS(0) 901a 8a sys_peer
23 Sep 10:10:23 ntpd[859]: 0.0.0.0 0113 03 spike_detect +0.146600 s
23 Sep 10:15:27 ntpd[859]: 0.0.0.0 011c 0c clock_step +0.154815 s
23 Sep 10:15:27 ntpd[859]: 0.0.0.0 0115 05 clock_sync
23 Sep 10:15:30 ntpd[859]: 0.0.0.0 c118 08 no_sys_peer
23 Sep 10:15:30 ntpd[859]: LOCAL(0) 80f4 84 reachable
23 Sep 10:15:30 ntpd[859]: GPS_NMEA(0) 8014 84 reachable
23 Sep 10:15:30 ntpd[859]: GPS_NMEA(0) 901a 8a sys_peer
23 Sep 10:15:30 ntpd[859]: 0.0.0.0 c413 03 spike_detect -0.145798 s
23 Sep 10:20:34 ntpd[859]: 0.0.0.0 c41c 0c clock_step -0.138779 s
23 Sep 10:20:34 ntpd[859]: 0.0.0.0 c415 05 clock_sync
23 Sep 10:20:35 ntpd[859]: 0.0.0.0 c418 08 no_sys_peer
23 Sep 10:20:50 ntpd[859]: GPS_NMEA(0) 8014 84 reachable
23 Sep 10:20:50 ntpd[859]: GPS_NMEA(0) 901a 8a sys_peer
23 Sep 10:20:51 ntpd[859]: PPS(0) 8014 84 reachable
23 Sep 10:20:51 ntpd[859]: PPS(0) 901a 8a sys_peer
23 Sep 10:20:51 ntpd[859]: 0.0.0.0 0113 03 spike_detect +0.146986 s
23 Sep 10:20:51 ntpd[859]: ntpd exiting on signal 15 (Terminated)
Here we start up the system after a couple of days and and NTPD performs a big step of +519673s. After this we keep detecting spikes and then loosing the PPS signal (seen on the ntpq -p output). After several minutes we get the PPS back and we perform a clock step.
This is the output when I get contant with the PPS. Its offset is huge and always increasing
debian@beaglebone:~$ ntpq -p
remote refid st t when poll reach delay offset jitter
==============================================================================
*GPS_NMEA(0) .GPS-. 0 l 5 16 377 0.000 1.972 5.258
oPPS(0) .PPS. 0 l 3 8 377 0.000 136.903 0.855
LOCAL(0) .LOCL. 10 l 276 64 20 0.000 0.000 0.002
Then at some point I loose contact with the PPS and it seems as the same time the clock is stepped?
debian@beaglebone:~$ ntpq -p
remote refid st t when poll reach delay offset jitter
==============================================================================
*GPS_NMEA(0) .GPS-. 0 l 9 16 377 0.000 -148.66 2.373
PPS(0) .PPS. 0 l 157 8 0 0.000 0.000 0.000
LOCAL(0) .LOCL. 10 l 155 64 4 0.000 0.000 0.002
The strange thing is that if I just restart the ntp service it will typically manage fine and slowely tune the system clock towards PPS. I am not familiar with the underlying control loop of ntpd but it can seem as if an initial big step makes it behave completely different.
My config file is
# Log stuff
statistics loopstats peerstats clockstats sysstats
statistics peerstats
filegen peerstats file peerstats type day enable
filegen loopstats file loopstats type day enable
filegen clockstats file clockstats type day enable
filegen sysstats file sysstats type day enable
#driftfile /var/log/ntp_drift.log
logconfig =syncevents +peerevents +sysevents +allclock
logfile /var/log/ntp.log
statsdir /var/log/ntpstats/
# Guard against DDOS
restrict default kod nomodify notrap nopeer noquery
restrict -6 default kod nomodify notrap nopeer noquery
restrict 10.0.60.0 mask 255.255.255.0 nomodify notrap
restrict -6 ::1
restrict 127.0.0.1 mask 255.255.255.0
tos mindist 0.300
# NMEA refclock driver directly from serial port
server 127.127.20.0 mode 56 minpoll 4 iburst prefer true
fudge 127.127.20.0 flag1 0 flag2 0 flag3 0 flag4 0 time1 0.00 refid GPS-NMEA
# GPS: PPS/ATOM from pps-gpio service
server 127.127.22.0 maxpoll 3 minpoll 5 iburst
fudge 127.127.22.0 refid PPS time1 0.000001
fudge 127.127.22.0 flag3 1
# Add backup based on own system clock
server 127.127.1.0
fudge 127.127.1.0 stratum 10
Can anyone make anything out of this? I am not entirely sure of the configuration of the PPS/ATOM refclock driver. Thanks for all suggestions