Re: [PATCH] x86/tsc: Require a deviating refined calibration to be reproduced

[NvD Ss]

Hi,

I appear to be seeing essentially the same TSC issue on another Raven
Ridge / ASUS A320 system.

Hardware:

- CPU: AMD Ryzen 5 2400G with Radeon Vega Graphics (Raven Ridge)
- Motherboard: ASUS PRIME A320M-C R2.0
- BIOS: 6254
- RAM: 16 GiB DDR4-2400
- GPU: NVIDIA GeForce RTX 4060

Kernel used for the tests below:

- 6.18.52-1-cachyos-lts and 7.2.8-2-cachyos

The CPU reports both constant_tsc and nonstop_tsc.

I originally discovered this because a timing-heavy Wine/Proton game
was performing extremely poorly. perf showed a surprising amount of
CPU time in read_hpet, which led me to check the clocksource.

With a normal warm boot, the kernel switches from TSC to HPET. One
representative boot with BIOS 6254 produced:

tsc: Fast TSC calibration using PIT
tsc: Detected 3593.185 MHz processor
clocksource: Switched to clocksource tsc-early
tsc: Refined TSC clocksource calibration: 3596.250 MHz
clocksource: Switched to clocksource tsc
clocksource: Marking clocksource tsc unstable due to frequency skew
clocksource: Watchdog                    hpet interval:        504269467ns
clocksource: Clocksource                  tsc interval:        503848443ns
tsc: Marking TSC unstable due to clocksource watchdog
TSC found unstable after boot, most likely due to broken BIOS. Use
'tsc=unstable'.
clocksource: Switched to clocksource hpet

The difference is about 421 us over ~504 ms, or roughly 835 ppm.

I also tested with "nohpet" to determine whether HPET itself was
responsible. The same problem occurred using the ACPI PM timer as the
watchdog/reference:

Command line: ... nohpet
tsc: Fast TSC calibration using PIT
tsc: Detected 3593.621 MHz processor
clocksource: Switched to clocksource tsc-early
clocksource: acpi_pm: ...
tsc: Refined TSC clocksource calibration: 3596.253 MHz
clocksource: Switched to clocksource tsc
clocksource: Marking clocksource tsc unstable due to frequency skew
clocksource: Watchdog                 acpi_pm interval:        496412812ns
clocksource: Clocksource                  tsc interval:        495998342ns
tsc: Marking TSC unstable due to clocksource watchdog
TSC found unstable after boot, most likely due to broken BIOS.
clocksource: Switched to clocksource acpi_pm

Again the discrepancy is about 414 us over ~496 ms, approximately the
same ~835 ppm.

The particularly interesting result is a full cold boot.

I removed all experimental clocksource parameters, ran with the normal
kernel command line, shut the machine completely down, waited for
power-off, and then powered it back on.

On that boot I got:

tsc: Fast TSC calibration using PIT
tsc: Detected 3593.621 MHz processor
clocksource: Switched to clocksource tsc-early
tsc: Refined TSC clocksource calibration: 3593.248 MHz
clocksource: Switched to clocksource tsc

TSC remained the active clocksource:

$ cat /sys/devices/system/clocksource/clocksource0/current_clocksource
tsc

$ cat /sys/devices/system/clocksource/clocksource0/available_clocksource
tsc hpet acpi_pm

There was one:

clocksource: Watchdog remote CPU 6 read timed out

message during this cold boot, but TSC was not subsequently marked unstable.

This appears very similar to the warm-reset + first deep-idle/C-state
behavior described in your patch. The bad refinement on my machine is
about 3596.25 MHz, while a cold boot gives about 3593.25 MHz.

For an additional test, I temporarily booted a warm-booted system with:

tsc=reliable clocksource=tsc

This prevented the fallback and dramatically improved the affected
workload, but I have removed this workaround because it also prevents
the normal clocksource validation. systemd-timesyncd initially reached
the +500 ppm frequency correction limit during that test.

With a normal cold boot and no TSC-related kernel parameters, TSC
stays selected and NTP later reported:

Frequency: -9.956ppm

I do not consider the NTP measurement precise evidence by itself,
since it was still relatively early after boot, but it is consistent
with the cold-boot TSC behaving much better than the forced warm-boot
case.

The application-level effect is very large on this machine. Under
HPET, Deadlock running through Proton was approximately 15-25 FPS. A
perf recording showed, among other samples:

 9.99%  MainThrd         [kernel.kallsyms]  [k] read_hpet
 8.58%  swapper          [kernel.kallsyms]  [k] read_hpet
 2.08%  wineserver       [kernel.kallsyms]  [k] read_hpet

Keeping TSC as the clocksource increased performance dramatically.
After resolving some separate memory/indexing issues as well, the same
game now runs around 90-115 FPS with TSC active.

I also updated the motherboard BIOS specifically while investigating this.

The board was previously running:

ASUS PRIME A320M-C R2.0
BIOS 5007
2019-06-18

I updated it to:

BIOS 6254

The warm-reboot TSC behavior remained present after the update.

This seems noteworthy because your reported machine is a Ryzen 3 PRO
2200GE / PRIME A320M-K / BIOS 6254, while mine is a Ryzen 5 2400G /
PRIME A320M-C R2.0 / BIOS 6254. Both are Raven Ridge systems from the
same ASUS A320 motherboard generation.

P.S most of the wording for the above report has been produced and
written by ai after days of me trying to diagnose such a massive fps
difference in my game between windows and linux, logging and
troubleshooting was done by me with assistance from the ai. This is my
first time reporting like this but I would be happy to provide any
help I can.