Re: [PATCH clocksource 1/3] clocksource: Reject bogus watchdog clocksource measurements
From: Paul E. McKenney
Date: Fri Dec 02 2022 - 17:24:24 EST
On Fri, Dec 02, 2022 at 10:02:59AM +0800, Feng Tang wrote:
> On Thu, Dec 01, 2022 at 05:44:28PM -0800, Paul E. McKenney wrote:
> > On Fri, Dec 02, 2022 at 09:10:12AM +0800, Feng Tang wrote:
> > > On Thu, Dec 01, 2022 at 09:24:05AM -0800, Paul E. McKenney wrote:
> > > > On Wed, Nov 30, 2022 at 02:00:04PM +0800, Feng Tang wrote:
> > > > > On Tue, Nov 29, 2022 at 09:50:24PM -0800, Paul E. McKenney wrote:
> > > > > [...]
> > > > > > >
> > > > > > > Great! As both HPET and PM_TIMER get the same calibration 1975.000 MHz,
> > > > > > > and it matches the 40ms drift per second you mentioned earlier, this
> > > > > > > seems like the CPUID(0x15) gave the wrong frequence number.
> > > > > > >
> > > > > > > Or unlikely, HPET and PM_TIMER are driven by the same circuit source,
> > > > > > > which has deviation.
> > > > > > >
> > > > > > > Either way, I think the HW/FW could have some problem.
> > > > > >
> > > > > > And this time with your printk()s:
> > > > > >
> > > > > > [ 0.000000] tsc: using CPUID[0x15] crystal_khz= 24000 kHz ebx=158 eax=2
> > > > > > [ 0.000000] tsc: Detected 1900.000 MHz processor
> > > > > > [ 0.000000] tsc: Detected 1896.000 MHz TSC
> > > > > > [ 5.268858] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
> > > > > > [ 25.706231] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x36a8d32ce31, max_idle_ns: 881590731004 ns
> > > > > > [ 32.223011] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
> > > > > > [ 57.823933] clocksource: Switched to clocksource tsc-early
> > > > > > [ 58.144840] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
> > > > > > [ 63.613713] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x36a8d32ce31, max_idle_ns: 881590731004 ns
> > > > > > [ 63.637323] clocksource: Switched to clocksource tsc
> > > > > > [ 64.673579] tsc: Warning: TSC freq calibrated by CPUID/MSR differs from what is calibrated by HW timer, please check with vendor!!
> > > > > > [ 64.703719] tsc: Previous calibrated TSC freq: 1896.000 MHz
> > > > > > [ 64.716816] tsc: TSC freq recalibrated by [PM_TIMER]: 1974.999 MHz
> > > > >
> > > > > This confirms the tsc frequency is calculated from CPUID(0x15).
> > > > >
> > > > > > What would be good next steps to check up on the hardware and firmware?
> > > > >
> > > > > Maybe raise it to vendor? I have no idea how to check thos black boxes :)
> > > >
> > > > Done, but no high hopes here. (What, me cynical? Better believe it!!!)
> > > >
> > > > > > (My next step involves a pillow, but will follow up tomorrow morning
> > > > > > Pacific Time.)
> > > > >
> > > > > Really thanks for checking this through late night!
> > > >
> > > > No problem, and I guess it is instead the day after tomorrow, but
> > > > I thought you might be interested in chronyd's opinion:
> > > >
> > > > [root@rtptest1029.snc8 ~]# cat /var/lib/chrony/drift
> > > > 40001.074911 0.002098
> > > >
> > > > In contrast, on my Fedora laptop:
> > > >
> > > > $ sudo cat /var/lib/chrony/drift
> > > > 2.074313 0.186606
> > > >
> > > > I am (perhaps incorrectly) taking this to indicate that TSC is in fact
> > > > drifting with respect to standard time.
> > >
> > > This info is very useful! It further confirms the CPUID(0x15) gave
> > > the wrong frequency info.
> >
> > So the TSC is just doing what it is told. ;-)
> >
> > This indicates a firmware problem?
> >
> > > Also I don't think TSC itself is drifting, and the drift some from
> > > the wrong match calculation(1896 MHz), if we give it the correct
> > > number (likely 1975 MHz here), there shouldn't be big chrony drift
> > > like your Fedora laptop.
> >
> > Resetting so that the clocksource watchdog once again gets rid of TSC,
> > but leaving nohpet:
> >
> > [ 0.000000] tsc: using CPUID[0x15] crystal_khz= 24000 kHz ebx=158 eax=2
> > [ 0.000000] tsc: Detected 1900.000 MHz processor
> > [ 0.000000] tsc: Detected 1896.000 MHz TSC
> > [ 5.287750] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
> > [ 17.963947] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x36a8d32ce31, max_idle_ns: 881590731004 ns
> > [ 19.996287] clocksource: timekeeping watchdog on CPU3: Marking clocksource 'tsc-early' as unstable because the skew is too large:
> > [ 20.040287] clocksource: 'refined-jiffies' wd_nsec: 503923392 wd_now: fffb73f8 wd_last: fffb7200 mask: ffffffff
> > [ 20.067286] clocksource: 'tsc-early' cs_nsec: 588021368 cs_now: 581c1eb378 cs_last: 57d9aad9e8 mask: ffffffffffffffff
> > [ 20.096286] clocksource: No current clocksource.
> > [ 20.111286] tsc: Marking TSC unstable due to clocksource watchdog
> > [ 24.582541] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
> > [ 49.739301] clocksource: Switched to clocksource refined-jiffies
> > [ 50.046356] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
> > [ 50.066475] clocksource: Switched to clocksource acpi_pm
> >
> > # cat /var/lib/chrony/drift
> > 1.372570 0.020049
> >
> > I interpret this to mean that acpi_pm (and thus from prior observations,
> > HPET as well) are counting at the correct rate.
>
> Correct. And this is a good news! that 1975 MHz seems to be the right
> number.
>
> Could you try below patch, it should override the CPUID calculation
> and forced to use HW timer calibrated number:
>
> ---
> diff --git a/arch/x86/kernel/tsc.c b/arch/x86/kernel/tsc.c
> index a78e73da4a74..68a2fea4961d 100644
> --- a/arch/x86/kernel/tsc.c
> +++ b/arch/x86/kernel/tsc.c
> @@ -1417,7 +1417,8 @@ static int __init init_tsc_clocksource(void)
> * When TSC frequency is known (retrieved via MSR or CPUID), we skip
> * the refined calibration and directly register it as a clocksource.
> */
> - if (boot_cpu_has(X86_FEATURE_TSC_KNOWN_FREQ)) {
> +// if (boot_cpu_has(X86_FEATURE_TSC_KNOWN_FREQ)) {
> + if (false) {
> if (boot_cpu_has(X86_FEATURE_ART))
> art_related_clocksource = &clocksource_tsc;
> clocksource_register_khz(&clocksource_tsc, tsc_khz);
> ---
>
> And together with b50db7095fe0 "x86/tsc: Disable clocksource watchdog
> for TSC on qualified platorms". I assume this will tell TSC to use
> 1975 MHZ as its frequency.
This did not change things, but when I hardcoded tsc_khz to 1975, the
clocksource watchdog no longer disables TSC and chrony shows drifts of
less than 2.0. (As opposed to about 40,000 without the hardcoding.)
So yes, forcing 1975 makes TSC work nicely. Yay! ;-)
Thanx, Paul