Re: Weird clock behaviour with current (amd64) kernel

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

    Date:        Sat, 13 Aug 2022 17:41:05 +0200
    From:        Michael van Elst <mlelstv%serpens.de@localhost>
    Message-ID:  <YvfGEXBuss872Fwl%serpens.de@localhost>

  | If you boot the kernel in debug mode (netbsd -x),

I did.

  | you may see output like:

which was:

[     1.000003] cpu0: TSC freq CPUID 3417600000 Hz
[     1.000003] cpu0: TSC freq from CPUID 3417600000 Hz
[     1.064451] xhci0: hcc2=0x1fd<ETC_TSC,ETC,CIC,LEC,CTC,FSC,U3C>
[     1.064451] xhci3: hcc2=0xfd<ETC_TSC,ETC,CIC,LEC,CTC,FSC,U3C>
[     1.064451] cpu0: TSC freq from HPET 9007294000 Hz
[     1.064451] cpu0: TSC freq CPUID 3417600000 Hz
[     1.064451] cpu0: TSC freq calibrated 9007294000 Hz
[     1.972808] cpu1: TSC skew=4 drift=0
[     1.993656] cpu2: TSC skew=0 drift=0
[     2.060514] cpu3: TSC skew=81 drift=-16
[     2.187906] cpu4: TSC skew=-61 drift=4
[     2.213693] cpu5: TSC skew=0 drift=0
[     2.289145] cpu6: TSC skew=0 drift=0
[     2.415347] cpu7: TSC skew=0 drift=0
[     2.441701] cpu8: TSC skew=-65 drift=4
[     2.557519] cpu9: TSC skew=0 drift=0
[     2.583039] cpu10: TSC skew=-2 drift=-2
[     2.705257] cpu11: TSC skew=68 drift=-127
[     2.731613] cpu12: TSC skew=0 drift=0
[     2.799767] cpu13: TSC skew=0 drift=0
[     2.875167] cpu14: TSC skew=0 drift=0
[     2.944878] cpu15: TSC skew=-51 drift=49
[     3.074237] cpu16: TSC skew=-28 drift=2
[     3.100594] cpu17: TSC skew=-27 drift=-2
[     3.219004] cpu18: TSC skew=-27 drift=-1
[     3.244362] cpu19: TSC skew=-31 drift=6
[     3.365815] cpu20: TSC skew=-9 drift=0
[     3.391221] cpu21: TSC skew=-5 drift=0
[     3.512663] cpu22: TSC skew=-33 drift=4
[     3.538003] cpu23: TSC skew=-3 drift=-1
[     3.654063] timecounter: Timecounter "TSC" frequency 9007294000 Hz quality 3000

(ignore the xhci lines, they just matched the grep pattern "TSC").

A normal boot (no PCIDUMP) ends with:

[     1.678054] timecounter: Timecounter "TSC" frequency 3417601000 Hz quality 3000

jacaranda$ bc
scale=3
9007294000/3417600000
2.635

which is almost exactly the slowdown I was seeing in user mode once
it booted.   Note that aside from time running slowly, everything else
seems to work fine.   After switching to hpet0 (after having booted
as above) time advances at the proper rate again, but internal delays
(as in that needed for "sleep 1" to sleep for a second) keep running
at the slow rate.

In the dmesg, everything that happens at timestamp 1.064451 is while
the PCI CONFIG DUMP code is running - that lasts about 6 minutes, maybe a
bit more with -x (I didn't time it this time), during which the timestamps
don't advance.   The timestamps that happen after that are running on
slow time (a 1 second increment is really about 2.6 seconds).

  | "from delay" is the first calibration against the i8254 timer.

I don't have any "from delay" output.

  | The patch should improve the accuracy of the "from delay" value.

In that case it is no surprise that nothing changed much.  I am
guessing that that line would appear without -x as well, the other
ones do - I don't see a "from delay" line in any dmesg output I have
saved (unless that was something new you just added, and does only
appear with -x - in which case it simply wasn't invoked on my system).

  | It's also the only place that could have been influenced by e.g. console
  | output.

Clearly there's some other place, the only difference between the kernel
that has this problem, and one that doesn't, is the PCIDUMP option being
enabled:

jacaranda$ (command cd ~/src/sys-conf; diff JACARANDA JACARANDA_PCI_DUMP)
207c207
< #options      PCI_CONFIG_DUMP # verbosely dump PCI config space
---
> options       PCI_CONFIG_DUMP # verbosely dump PCI config space
jacaranda$ 


  | If you have a working HPET,

I do, that one works fine in general.

  | the second calibration should be better.
  | Here it always returns exactly the same number.

See above.

To avoid delays in a message turnaround, this is what sysctl says is
available (this output is from a normal boot, not the PCIDUMP one).

kern.timecounter.choice = TSC(q=3000, f=3417601000 Hz) clockinterrupt(q=0, f=100 Hz) lapic(q=-100, f=38400000 Hz) hpet0(q=2000, f=19200000 Hz) ACPI-Fast(q=1000, f=3579545 Hz) i8254(q=100, f=1193182 Hz) dummy(q=-1000000, f=1000000 Hz)


As I have said before, this is most probably an exceedingly unimportant
issue, not worth spending a lot of time on.   That is, unless perhaps it
is exposing some other bug that may possibly reveal itself in some other
situations.

kre