Re: Weird clock behaviour with current (amd64) kernel

[Masanobu SAITOH <msaitoh%execsw.org@localhost>]

Hi,

On 2022/07/15 21:38, Robert Elz wrote:
>     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.

Yes, it should be related to the problem.

> 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 ...

Another possibility is that the LAPIC_ICR_TIMER register is
not set correctly in lapic_calibrate_timer(). The function is called
twice and it refers "lapic_per_second" global variable. The code is
little tricky.

> 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).

It worked. "TSC freq CPUID" is printed in cpu_tsc_freq_cpuid().

                aprint_verbose_dev(ci->ci_dev, "TSC freq CPUID %" PRIu64
                    " Hz\n", freq);

aprint_verbose*() is printed when -v is set.

> 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,

I'd like to see the debug(-x) output, too.
I'll mail to you privately.


> or you supply a different grep pattern (if I can find one
> line, I can easily extract any relevant looking surrounding lines).
> 
> kre
> 

-- 
-----------------------------------------------
                SAITOH Masanobu (msaitoh%execsw.org@localhost
                                 msaitoh%netbsd.org@localhost)