An odd example of the Pine64+ 2GB time jump? Or an interesting one?

Sun Aug 19 18:56:11 UTC 2018

[No examples during a 44 hr monitoring during
a poudriere-devel run.]

On 2018-Aug-17, at 9:41 AM, Mark Millard <marklmi at yahoo.com> wrote:

> The oddity is the timing of that 1st no_sys_peer reported
> at 17 Aug 07:24:09 (before the time is adjusted) in what
> is later reported below: timing relative to other things
> going on that had not been going on just before.
> 
> The sequence establishing context follows . . .
> 
> Henri Hennebert <hlh at restart.be> asked me to
> do some time monitoring during the long running
> poudriere-devel involving, for example, building
> lang/gcc8 with a full bootstrap.
> 
> This was started during that lang/gcc8 build the
> 2nd /var/log/ntp.log content below was discovered
> during the package stage of what turned out to be
> a 12:32:45 or so for lang/gcc8 overall. Earlier
> was during the build stage.
> 
> Notes: The laptop has 2 ssh sessions in to the
> Pine64+ 2GB, including the one with material
> below and the one running poudriere-devel. The
> laptop is also what is monitoring the serial
> console.  I've not applied any patches for the
> time issue.
> 
> 
> (Note: there were prior instances of the date ; more
> command sequence that are not shown.)
> 
> # date ; more /var/log/ntp.log
> Fri Aug 17 03:04:12 PDT 2018
> 17 Aug 01:02:20 ntpd[49765]: Listen and drop on 0 v6wildcard [::]:123
> 17 Aug 01:02:20 ntpd[49765]: Listen and drop on 1 v4wildcard 0.0.0.0:123
> 17 Aug 01:02:20 ntpd[49765]: Listen normally on 2 awg0 192.168.0.100:123
> 17 Aug 01:02:20 ntpd[49765]: Listen normally on 3 lo0 [::1]:123
> 17 Aug 01:02:20 ntpd[49765]: Listen normally on 4 lo0 [fe80::1%2]:123
> 17 Aug 01:02:20 ntpd[49765]: Listen normally on 5 lo0 127.0.0.1:123
> 17 Aug 01:02:20 ntpd[49765]: Listening on routing socket on fd #26 for interface updates
> 17 Aug 01:02:20 ntpd[49765]: 0.0.0.0 c01d 0d kern kernel time sync enabled
> 17 Aug 01:02:20 ntpd[49765]: 0.0.0.0 c012 02 freq_set kernel 0.000 PPM
> 17 Aug 01:02:20 ntpd[49765]: 0.0.0.0 c011 01 freq_not_set
> 17 Aug 01:02:20 ntpd[49765]: 0.0.0.0 c016 06 restart
> 17 Aug 01:02:21 ntpd[49765]: Soliciting pool server 103.105.51.156
> 17 Aug 01:02:22 ntpd[49765]: Soliciting pool server 45.77.78.241
> 17 Aug 01:02:23 ntpd[49765]: Soliciting pool server 198.98.57.16
> 17 Aug 01:02:24 ntpd[49765]: Soliciting pool server 173.230.152.251
> 17 Aug 01:02:30 ntpd[49765]: 0.0.0.0 c614 04 freq_mode
> 17 Aug 01:05:46 ntpd[49765]: Soliciting pool server 74.207.240.206
> 17 Aug 01:07:58 ntpd[49765]: 0.0.0.0 0612 02 freq_set kernel 36.141 PPM
> 17 Aug 01:07:58 ntpd[49765]: 0.0.0.0 0615 05 clock_sync
> pine64# fg
> top -CawSores
> . . . (I go to bed during this time; the laptop screen locks) . . .
> . . . (when I get back in I read an Email from Henri H. before the below) . . .
> [1] + Suspended               top -CawSores
> # date ; more /var/log/ntp.log
> Fri Aug 17 07:23:04 PDT 2018
> 17 Aug 01:02:20 ntpd[49765]: Listen and drop on 0 v6wildcard [::]:123
> 17 Aug 01:02:20 ntpd[49765]: Listen and drop on 1 v4wildcard 0.0.0.0:123
> 17 Aug 01:02:20 ntpd[49765]: Listen normally on 2 awg0 192.168.0.100:123
> 17 Aug 01:02:20 ntpd[49765]: Listen normally on 3 lo0 [::1]:123
> 17 Aug 01:02:20 ntpd[49765]: Listen normally on 4 lo0 [fe80::1%2]:123
> 17 Aug 01:02:20 ntpd[49765]: Listen normally on 5 lo0 127.0.0.1:123
> 17 Aug 01:02:20 ntpd[49765]: Listening on routing socket on fd #26 for interface updates
> 17 Aug 01:02:20 ntpd[49765]: 0.0.0.0 c01d 0d kern kernel time sync enabled
> 17 Aug 01:02:20 ntpd[49765]: 0.0.0.0 c012 02 freq_set kernel 0.000 PPM
> 17 Aug 01:02:20 ntpd[49765]: 0.0.0.0 c011 01 freq_not_set
> 17 Aug 01:02:20 ntpd[49765]: 0.0.0.0 c016 06 restart
> 17 Aug 01:02:21 ntpd[49765]: Soliciting pool server 103.105.51.156
> 17 Aug 01:02:22 ntpd[49765]: Soliciting pool server 45.77.78.241
> 17 Aug 01:02:23 ntpd[49765]: Soliciting pool server 198.98.57.16
> 17 Aug 01:02:24 ntpd[49765]: Soliciting pool server 173.230.152.251
> 17 Aug 01:02:30 ntpd[49765]: 0.0.0.0 c614 04 freq_mode
> 17 Aug 01:05:46 ntpd[49765]: Soliciting pool server 74.207.240.206
> 17 Aug 01:07:58 ntpd[49765]: 0.0.0.0 0612 02 freq_set kernel 36.141 PPM
> 17 Aug 01:07:58 ntpd[49765]: 0.0.0.0 0615 05 clock_sync
> 17 Aug 07:24:09 ntpd[49765]: 0.0.0.0 0618 08 no_sys_peer
> 17 Aug 07:24:42 ntpd[49765]: Soliciting pool server 162.254.66.243
> 17 Aug 07:24:43 ntpd[49765]: Soliciting pool server 129.250.35.251
> 17 Aug 07:24:44 ntpd[49765]: Soliciting pool server 173.255.206.154
> 17 Aug 07:24:45 ntpd[49765]: Soliciting pool server 74.6.168.72
> 17 Aug 07:24:46 ntpd[49765]: Soliciting pool server 45.79.111.114
> 17 Aug 07:24:47 ntpd[49765]: Soliciting pool server 69.195.159.158
> 17 Aug 07:24:48 ntpd[49765]: Soliciting pool server 199.223.248.98
> 17 Aug 07:25:53 ntpd[49765]: 0.0.0.0 0613 03 spike_detect -178.954593 s
> 17 Aug 07:25:56 ntpd[49765]: 0.0.0.0 061c 0c clock_step -178.956586 s
> 17 Aug 07:22:57 ntpd[49765]: 0.0.0.0 0615 05 clock_sync
> 17 Aug 07:22:58 ntpd[49765]: 0.0.0.0 c618 08 no_sys_peer
> 17 Aug 07:22:58 ntpd[49765]: 198.98.57.16 local addr 192.168.0.100 -> <null>
> 
> The oddity is the timing of that 1st no_sys_peer reported
> at 17 Aug 07:24:09 (before the time is adjusted): it appears
> to be very closely timed with activity near my logging in
> on the laptop and starting to do things before the 2nd
> "date" above.
> 
> It is almost like my new activity "kicked" the Pine64+
> 2GB and ended up with the 1st no_sys_peer as a result.
> 
> 
> Looking around about no_sys_peer:
> 
> "Indicates that there is no server that satisfies ntpd’s stability criteria"
> 
> So it might be tied ntpd noticing the time being odd and the
> later activity is ntpd gaining independent evidence of the
> from a set of servers and finally accepting the error is
> likely real and adjusting for it.
> 
> [This suggests that the "no_sys_peer" is the best indicator
> of when the time difference was noted.]
> 
> The second no_sys_peer could fit with this based on its
> having adjusted the clock and needing to re-certify.
> 
> 
> It appears that either I was very lucky in the
> timing of waking up and taking a look at the status
> or that activity somehow contributed to the timing
> of the no_sys_peer and related activity.
> 
> 
> I wonder if these notes should be referenced in:
> 
> https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=229644
> 
> (The "Affects Only Me" status there could be updated
> as well, not that I could do that.)
> 
> 
> For reference:
> 
> head -r337400 is in use on the Pine64+ 2GB.
> 
> I've not applied any patches for the time issue.
> 
> The Pine64+ 2GB has a case, heat sinks, and a fan.
> UFS, not ZFS is in use.
> 
> Ethernet is in use.
> 
> Other than the serial console connection, nothing
> else is connected.
> 
> As stands I'm using an e.MMC for the root file
> system and swap partition. But it is on a microsd
> adapter, plugged into a USB 3.0 capable reader, that
> in turn is plugged in to the bottom USB port on the
> Pine64+ 2GB. (I've used other USB media before.
> (Most types are more reliable with a powered hub
> but the e.MMC/USB combination has never shown evidence
> of needing such.)
> 
> (It used to be the Pine64+ 2GB would boot from the
> e.MMC on the microsd adpater. But that is not true
> now based on what FreeBSD tries to do with the e.MCC
> that the Pine64+ 2GB can not actually do: a voltage
> change. Thus the USB involvement these days.)

I disabled the laptop from doing a blank-screen/partial-sleep
and used a different root file system device (more capacity)
that involved using a powered hub. I then did a poudriere-devel
run that lasted 47 hours, including building devel/gcc8 (a
little under 12.5 hours and late in the overall time).

I was interrupted before starting the ntp.log file and so
the tracking spans the last 44 or so hrs instead of the full
47 hours:

# date ; more /var/log/ntp.log
Sun Aug 19 10:50:48 PDT 2018
17 Aug 14:28:51 ntpd[20620]: Listen and drop on 0 v6wildcard [::]:123
17 Aug 14:28:51 ntpd[20620]: Listen and drop on 1 v4wildcard 0.0.0.0:123
17 Aug 14:28:51 ntpd[20620]: Listen normally on 2 awg0 192.168.0.100:123
17 Aug 14:28:51 ntpd[20620]: Listen normally on 3 lo0 [::1]:123
17 Aug 14:28:51 ntpd[20620]: Listen normally on 4 lo0 [fe80::1%2]:123
17 Aug 14:28:51 ntpd[20620]: Listen normally on 5 lo0 127.0.0.1:123
17 Aug 14:28:51 ntpd[20620]: Listening on routing socket on fd #26 for interface updates
17 Aug 14:28:51 ntpd[20620]: 0.0.0.0 c01d 0d kern kernel time sync enabled
17 Aug 14:28:51 ntpd[20620]: 0.0.0.0 c012 02 freq_set kernel 0.000 PPM
17 Aug 14:28:51 ntpd[20620]: 0.0.0.0 c011 01 freq_not_set
17 Aug 14:28:51 ntpd[20620]: 0.0.0.0 c016 06 restart
17 Aug 14:28:52 ntpd[20620]: Soliciting pool server 199.223.248.99
17 Aug 14:28:53 ntpd[20620]: Soliciting pool server 204.9.54.119
17 Aug 14:28:54 ntpd[20620]: Soliciting pool server 128.2.1.22
17 Aug 14:28:55 ntpd[20620]: Soliciting pool server 74.6.168.73
17 Aug 14:28:59 ntpd[20620]: 0.0.0.0 c614 04 freq_mode
17 Aug 14:32:19 ntpd[20620]: Soliciting pool server 72.30.35.88
17 Aug 14:34:39 ntpd[20620]: 0.0.0.0 0612 02 freq_set kernel 59.409 PPM
17 Aug 14:34:39 ntpd[20620]: 0.0.0.0 0615 05 clock_sync

(This also spans the pkg update and pkg upgrade and a few
package installs after the poudriere-devel run.)

This makes the one observed "spike_detect -178.954593 s" example
and its timing relative to my activity seemingly somewhat more
special.

===
Mark Millard
marklmi at yahoo.com
( dsl-only.net went
away in early 2018-Mar)