Date: Sun, 19 Aug 2018 11:56:01 -0700 From: Mark Millard <marklmi@yahoo.com> To: freebsd-arm <freebsd-arm@freebsd.org> Subject: Re: An odd example of the Pine64+ 2GB time jump? Or an interesting one? Message-ID: <16742A08-A315-422E-9869-E484D47AD8EB@yahoo.com> In-Reply-To: <FC6484D4-94E1-4F12-9BDB-0A81646ED47C@yahoo.com> References: <FC6484D4-94E1-4F12-9BDB-0A81646ED47C@yahoo.com>
next in thread | previous in thread | raw e-mail | index | archive | help
[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. >=20 > The sequence establishing context follows . . . >=20 > 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. >=20 > 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. >=20 > 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. >=20 >=20 > (Note: there were prior instances of the date ; more > command sequence that are not shown.) >=20 > # 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> >=20 > 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. >=20 > It is almost like my new activity "kicked" the Pine64+ > 2GB and ended up with the 1st no_sys_peer as a result. >=20 >=20 > Looking around about no_sys_peer: >=20 > "Indicates that there is no server that satisfies ntpd=E2=80=99s = stability criteria" >=20 > 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. >=20 > [This suggests that the "no_sys_peer" is the best indicator > of when the time difference was noted.] >=20 > The second no_sys_peer could fit with this based on its > having adjusted the clock and needing to re-certify. >=20 >=20 > 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. >=20 >=20 > I wonder if these notes should be referenced in: >=20 > https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=3D229644 >=20 > (The "Affects Only Me" status there could be updated > as well, not that I could do that.) >=20 >=20 > For reference: >=20 > head -r337400 is in use on the Pine64+ 2GB. >=20 > I've not applied any patches for the time issue. >=20 > The Pine64+ 2GB has a case, heat sinks, and a fan. > UFS, not ZFS is in use. >=20 > Ethernet is in use. >=20 > Other than the serial console connection, nothing > else is connected. >=20 > 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.) >=20 > (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. =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?16742A08-A315-422E-9869-E484D47AD8EB>