Re: Weird clock behaviour with current (amd64) kernel

[Robert Elz <kre%munnari.OZ.AU@localhost>]

    Date:        Fri, 15 Jul 2022 13:32:55 +0900
    From:        Masanobu SAITOH <msaitoh%execsw.org@localhost>
    Message-ID:  <87553319-950b-7dad-ac64-29d2c25d112d%execsw.org@localhost>

  | Could you show me the full dmesg with verbose output?

I could, but it turns out to be about a megabyte, so unless you need
to see all that noise, perhaps just this will help:

jacaranda$ grep -i TSC ~/dmesg*cold
[     1.000003] cpu0: Use lfence to serialize rdtsc
[     1.000003] cpu0: TSC freq CPUID 3417600000 Hz
[     1.031552] cpu0: TSC freq CPUID 3417600000 Hz
[     1.031552] cpu0: TSC freq calibrated 10483939000 Hz
[     1.457151] timecounter: Timecounter "TSC" frequency 10483939000 Hz quality 3000

When that was running, I did a
	while sleep 1; do date; done
loop, and watched it compared with time from my phone.
The date lines showed nicely incrementing seconds, but each
"sleep 1" lasted for (about) 3 seconds.

I switched from TSC to hpet0 and repeated the loop, the sleeps
still slept for 3 seconds, but now time went up in steps of 3.
(ie: time of day keeping became accurate, internal relative times
remained broken).

It is difficult to believe that the ratio 10483939000/3417600000 (== 3.067)
is not related here.

A different boot produced this instead

[     1.000003] cpu0: TSC freq CPUID 3417600000 Hz
[     1.031706] cpu0: TSC freq CPUID 3417600000 Hz
[     1.031706] cpu0: TSC freq calibrated 10491257000 Hz
[     1.345506] timecounter: Timecounter "TSC" frequency 10491257000 Hz quality 3000

A similar calibrated value, but not identical.   That kind of looks like
the PCI_CONFIG_DUMP output/scrolling/something related is interfering with
the calibration ... all the messages with dmesg timestamps of 1.03xxx are
being produced while all of that is happening.   The 1.000 message is before
the config dump starts, the 1.3455 or 1.457... messages appear after the
config dump has ended.

  | i.e. add -v option to the boot command in /boot.cfg.

I can't do exactly that, as I cannot find a boot.cfg file anywhere that
gets used (this is another issue I'm having, which I was going to ask
about sometime) - I have been modifying the banner= strings on every one
I can find (turns out I have a lot of them... none being used) so I know
when one is picked.   None of the boot.cfg files I can find has the ascii
art flag in the banner - the menu printed by efiboot does have that.

So, instead I simply hand typed a boot command, with -v at the end.   I'm
not sure that worked (that is, the system certainly booted, but I don't
know that the -v flag worked).

If you'd like to see the complete dmesg I can make that available (either
one from a cold boot, or the subsequent one, from a reboot, where the
previous boot's dmesg is still in the buffer - that file is about 2MB).

For comparison, when I boot generic (built from the same kernel sources,
but no pci config dump of course) what I see is:

[     1.000003] cpu0: Use lfence to serialize rdtsc
[     1.000003] cpu0: TSC freq CPUID 3417600000 Hz
[     1.059545] cpu0: TSC freq CPUID 3417600000 Hz
[     1.059545] cpu0: TSC freq calibrated 3417601000 Hz
[     2.106529] timecounter: Timecounter "TSC" frequency 3417601000 Hz quality 3000

That there is no info not there which is included above, is why I
suspect the -v might not have worked .. of course, this is all from a
simple grep (using -i, which is why that rdtsc line is included).
Of course, if the additional info you are looking for doesn't contain "tsc"
(or TSC) then I wouldn't have found it, in which case either I give you
the whole dmesg, or you supply a different grep pattern (if I can find one
line, I can easily extract any relevant looking surrounding lines).

kre