Date: Fri, 17 Aug 2018 09:41:05 -0700 From: Mark Millard <marklmi@yahoo.com> To: freebsd-arm <freebsd-arm@freebsd.org> Subject: An odd example of the Pine64+ 2GB time jump? Or an interesting one? Message-ID: <FC6484D4-94E1-4F12-9BDB-0A81646ED47C@yahoo.com>
next in thread | raw e-mail | index | archive | help
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=E2=80=99s = 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=3D229644 (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.) =3D=3D=3D Mark Millard marklmi at yahoo.com ( dsl-only.net went away in early 2018-Mar)
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?FC6484D4-94E1-4F12-9BDB-0A81646ED47C>