logging

[Udo van den Heuvel]

On 13-04-19 10:09, Hal Murray via devel wrote:
> Here is a typical batch of the confusing CLOCK printout:
> 
> Apr 12 14:37:35 box.local ntpd[2109]: CLOCK: ts_prev 1555072655 s +
> 712154322 ns, ts_min 1555072655 s + 712153764 ns
> Apr 12 14:37:35 box.local ntpd[2109]: CLOCK: ts 1555072655 s + 712154322 ns
> Apr 12 14:37:35 box.local ntpd[2109]: CLOCK: sys_fuzz 1816 nsec, prior
> fuzz 0.000001594
> Apr 12 14:37:35 box.local ntpd[2109]: CLOCK: this fuzz -0.000001722
> Apr 12 14:37:35 box.local ntpd[2109]: CLOCK: prev get_systime
> 0xe05b050f.b64fb1ce is 0.000000942 later than 0xe05b050f.b64fa201
> 
> It looks like something is screwed up with your system clock.

Hmm... ? :-/

>> Fedora 29 on x86_64 with Garmin gps18x on rs232.
> 
> x86_64 covers a lot of ground.  Anything interesting about that system?

Fedora 29, kernel.org 4.19.30. (my compile)
AMD Ryzen 5 2400G with Radeon Vega Graphics on Gigabyte X470 AORUS ULTRA
GAMING motherboard.
ntpsec from git.


>  Did 
> it work correctly a while ago?  Does it work without any refclocks?  Did you 
> update the kernel recently?  ...

I did not see these messages before.

> What do we know about the system timekeeping?  I'm looking for two things.  
> The first is from ntpd, probably in your syslog, before switching logging to 
> the typical log file.  It should be something like this:
>   Apr 12 22:51:29 hgm ntpd[724]: INIT: precision = 0.157 usec (-23)

Apr 12 14:15:23 bla ntpd[2109]: INIT: precision = 1.816 usec (-19)

> The other comes from the Linux kernel at boot time.  I don't know a simple 
> grep expression to get what I want.  Grep for clocksource is a good start, but 
> poke around to see if there is anything interesting nearby.  Grep for MHz may 
> be interesting.

clocksource is fixed at hpet since the previous situations where clock
sync was weird/gone/etc.

# dmesg|grep clocksource
[    0.000000] Command line: BOOT_IMAGE=/vmlinuz-4.19.30 ro
root=/dev/myvg/rootlv noexec=on noexec32=on vga=0xF06
SYSFONT=latarcyrheb-sun16 LANG=en_US.UTF-8 KEYTABLE=us
acpi_enforce_resources=lax fbcon=font:VGA8x16 radeon.pcie_gen2=1
cgroup_disable=memory threadirqs plymouth.enable=0 rd.plymouth=0
mce=dont_log_ce panic=0 rd.lvm.vg=myvg radeon.dpm=1 zswap.enabled=1
rd.auto=1 audit=0 systemd.log_level=warning  net.ifnames=0 acpi=force
amdgpu.gttsize=8192 clocksource=hpet initrd=/initramfs-4.19.30.img
[    0.000000] clocksource: refined-jiffies: mask: 0xffffffff
max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns
[    0.000000] Kernel command line: BOOT_IMAGE=/vmlinuz-4.19.30 ro
root=/dev/myvg/rootlv noexec=on noexec32=on vga=0xF06
SYSFONT=latarcyrheb-sun16 LANG=en_US.UTF-8 KEYTABLE=us
acpi_enforce_resources=lax fbcon=font:VGA8x16 radeon.pcie_gen2=1
cgroup_disable=memory threadirqs plymouth.enable=0 rd.plymouth=0
mce=dont_log_ce panic=0 rd.lvm.vg=myvg radeon.dpm=1 zswap.enabled=1
rd.auto=1 audit=0 systemd.log_level=warning net.ifnames=0 acpi=force
amdgpu.gttsize=8192 clocksource=hpet initrd=/initramfs-4.19.30.img
[    0.000000] clocksource: hpet: mask: 0xffffffff max_cycles:
0xffffffff, max_idle_ns: 133484873504 ns
[    0.000005] clocksource: tsc-early: mask: 0xffffffffffffffff
max_cycles: 0x33e4791d180, max_idle_ns: 440795290210 ns
[    0.288707] clocksource: jiffies: mask: 0xffffffff max_cycles:
0xffffffff, max_idle_ns: 7645041785100000 ns
[    1.160577] clocksource: Switched to clocksource hpet
[    1.174849] clocksource: acpi_pm: mask: 0xffffff max_cycles:
0xffffff, max_idle_ns: 2085701024 ns
[    2.433537] tsc: Refined TSC clocksource calibration: 3603.134 MHz
[    2.433787] clocksource: tsc: mask: 0xffffffffffffffff max_cycles:
0x33efe3ec317, max_idle_ns: 440795248122 ns

> You need to be careful with the arithmetic.  The ns per tick variable gets 
> adjusted by the clock drift.

I never ever saw these before.

Kind regards,
Udo