Re: [REGRESSION] ? system is stuck in clocksource, >60s delay at boot time without tsc=unstable

Fab Stz
2025-02-23T17:31:46Z

[-- Attachment #1: Type: text/plain, Size: 2166 bytes --]

Dear Thomas,

I eventually could proceed with the suggested checks. See below.

Le 15/01/2025 à 17:59, Thomas Gleixner a écrit :
>> Maybe the USB drivers somehow rely on a reliable clock source for
>> proper functioning.
>
> The kernel relies on a reliable clocksource. Loading the USB driver merely
> exposes the problem because it probably causes a long enough delay to
> get the CPUs into a state which exposes the issue.
>
> AFAICT, that iMac 9.1 is Core 2 Duo based and that generation of
> processors definitely had issues with the TSC in deeper idle states.

Indeed, cpuinfo reports:

model name : Intel(R) Core(TM)2 Duo CPU E8135 @ 2.66GHz

>> BTW, I tried the "processor.max_cstate=1" you mentioned but it didn't
>> change anything on the delay and/or warning.
>
> That's weird, but we have no idea what kind of magic the BIOS implements
> there for power management behind the kernels back. I assume that it
> does because this generation of CPUs uses the ACPI processor idle driver
> and that disables TSC when it detects that the system supports
> C-states > 1.
>
> # cat /sys/devices/system/cpu/cpuidle/
>
> tells which idle driver is actually in use.
>
> # ls /sys/devices/system/cpu/cpu0/cpuidle/
>
> tells which states are supported by the driver

> # cat /sys/devices/system/cpu/cpu0/cpuidle/state$N/name
> # cat /sys/devices/system/cpu/cpu0/cpuidle/state$N/disable

> tells the actual C-state name and the disabled state, but I expect that
> there is nothing to see.

Output of these commands can be found in attached file cpuidle.txt

> Can you try 'idle=halt' instead?

When using idle=halt (without tsc=unstable) I haven't encountered the delay.

Extract of the kernel log can be found in attached file
kernel_log_idle=halt.txt I also attach it for when using tsc=unstable &
wihtout any of these two.

So, which parameter is most suitable for this CPU/system?

Can the kernel be patched so that the proper config is used
automatically (ie. without the user having to set any parameter)? I'm
not sure my question actually makes sense.

Thank you, & regards.
Fab

[-- Attachment #2: cpuidle.txt --]
[-- Type: text/plain, Size: 3346 bytes --]

######## When run in kernel with tsc=unstable trace_clock=global ########

+ cat /sys/devices/system/cpu/cpuidle/available_governors
ladder menu
+ cat /sys/devices/system/cpu/cpuidle/current_driver
intel_idle
+ cat /sys/devices/system/cpu/cpuidle/current_governor
menu
+ cat /sys/devices/system/cpu/cpuidle/current_governor_ro
menu
+ ls /sys/devices/system/cpu/cpu0/cpuidle/
state0 state1 state2 state3
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state0/name
POLL
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state0/disable
0
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state1/name
C1_ACPI
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state1/disable
0
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state2/name
C2_ACPI
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state2/disable
0
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state3/name
C3_ACPI
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state3/disable
0

######## When run in kernel with idle=halt ########
+ cat /sys/devices/system/cpu/cpuidle/available_governors
ladder menu
+ cat /sys/devices/system/cpu/cpuidle/current_driver
none
+ cat /sys/devices/system/cpu/cpuidle/current_governor
menu
+ cat /sys/devices/system/cpu/cpuidle/current_governor_ro
menu
+ ls /sys/devices/system/cpu/cpu0/cpuidle/
ls: cannot access '/sys/devices/system/cpu/cpu0/cpuidle/': No such file or directory
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state0/name
cat: /sys/devices/system/cpu/cpu0/cpuidle/state0/name: No such file or directory
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state0/disable
cat: /sys/devices/system/cpu/cpu0/cpuidle/state0/disable: No such file or directory
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state1/name
cat: /sys/devices/system/cpu/cpu0/cpuidle/state1/name: No such file or directory
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state1/disable
cat: /sys/devices/system/cpu/cpu0/cpuidle/state1/disable: No such file or directory
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state2/name
cat: /sys/devices/system/cpu/cpu0/cpuidle/state2/name: No such file or directory
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state2/disable
cat: /sys/devices/system/cpu/cpu0/cpuidle/state2/disable: No such file or directory
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state3/name
cat: /sys/devices/system/cpu/cpu0/cpuidle/state3/name: No such file or directory
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state3/disable
cat: /sys/devices/system/cpu/cpu0/cpuidle/state3/disable: No such file or directory

######## When run in kernel WITHOUT idle=halt & WITHOUT tsc=unstable ########

+ cat /sys/devices/system/cpu/cpuidle/available_governors
ladder menu
+ cat /sys/devices/system/cpu/cpuidle/current_driver
intel_idle
+ cat /sys/devices/system/cpu/cpuidle/current_governor
menu
+ cat /sys/devices/system/cpu/cpuidle/current_governor_ro
menu
+ ls /sys/devices/system/cpu/cpu0/cpuidle/
state0 state1 state2 state3
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state0/name
POLL
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state0/disable
0
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state1/name
C1_ACPI
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state1/disable
0
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state2/name
C2_ACPI
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state2/disable
0
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state3/name
C3_ACPI
+ cat /sys/devices/system/cpu/cpu0/cpuidle/state3/disable
0

[-- Attachment #3: kernel_log_idle=halt.txt --]
[-- Type: text/plain, Size: 1554 bytes --]

Feb 23 17:41:27 debian kernel: Command line: root=UUID=462f57b4-136e-4c18-8c55-e4bc59cfb7aa ro idle=halt swap.enabled=1 mem_sleep_default=deep module_blacklist=nouveau initrd=boot\initrd.img-6.1.0-28-amd64
Feb 23 17:41:27 debian kernel: tsc: Fast TSC calibration using PIT
Feb 23 17:41:27 debian kernel: tsc: Detected 2653.370 MHz processor
Feb 23 17:41:27 debian kernel: clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns
Feb 23 17:41:27 debian kernel: Kernel command line: root=UUID=462f57b4-136e-4c18-8c55-e4bc59cfb7aa ro idle=halt swap.enabled=1 mem_sleep_default=deep module_blacklist=nouveau initrd=boot\initrd.img-6.1.0-28-amd64
Feb 23 17:41:27 debian kernel: clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 76450417870 ns
Feb 23 17:41:27 debian kernel: clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x263f2cb57f4, max_idle_ns: 440795235998 ns
Feb 23 17:41:27 debian kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
Feb 23 17:41:27 debian kernel: clocksource: Switched to clocksource tsc-early
Feb 23 17:41:27 debian kernel: clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
Feb 23 17:41:27 debian kernel: tsc: Refined TSC clocksource calibration: 2653.335 MHz
Feb 23 17:41:27 debian kernel: clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x263f0bda6a8, max_idle_ns: 440795254345 ns
Feb 23 17:41:27 debian kernel: clocksource: Switched to clocksource tsc

[-- Attachment #4: kernel_log_tsc=unstable.txt --]
[-- Type: text/plain, Size: 1262 bytes --]

Feb 23 17:33:21 debian kernel: Command line: root=UUID=462f57b4-136e-4c18-8c55-e4bc59cfb7aa ro tsc=unstable trace_clock=global quiet zswap.enabled=1 mem_sleep_default=deep module_blacklist=nouveau initrd=boot\initrd.img-6.1.0-28-amd64
Feb 23 17:33:21 debian kernel: tsc: Fast TSC calibration using PIT
Feb 23 17:33:21 debian kernel: tsc: Detected 2653.373 MHz processor
Feb 23 17:33:21 debian kernel: clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns
Feb 23 17:33:21 debian kernel: Kernel command line: root=UUID=462f57b4-136e-4c18-8c55-e4bc59cfb7aa ro tsc=unstable trace_clock=global quiet zswap.enabled=1 mem_sleep_default=deep module_blacklist=nouveau initrd=boot\initrd.img-6.1.0-28-amd64
Feb 23 17:33:21 debian kernel: tsc: Marking TSC unstable due to boot parameter
Feb 23 17:33:21 debian kernel: clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 76450417870 ns
Feb 23 17:33:21 debian kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
Feb 23 17:33:21 debian kernel: clocksource: Switched to clocksource hpet
Feb 23 17:33:21 debian kernel: clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns

[-- Attachment #5: kernel_log_noParam.txt --]
[-- Type: text/plain, Size: 2657 bytes --]

Feb 23 17:46:41 debian kernel: Command line: root=UUID=462f57b4-136e-4c18-8c55-e4bc59cfb7aa ro zswap.enabled=1 mem_sleep_default=deep module_blacklist=nouveau initrd=boot\initrd.img-6.1.0-28-amd64
Feb 23 17:46:41 debian kernel: tsc: Fast TSC calibration using PIT
Feb 23 17:46:41 debian kernel: tsc: Detected 2653.319 MHz processor
Feb 23 17:46:41 debian kernel: clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns
Feb 23 17:46:41 debian kernel: Kernel command line: root=UUID=462f57b4-136e-4c18-8c55-e4bc59cfb7aa ro zswap.enabled=1 mem_sleep_default=deep module_blacklist=nouveau initrd=boot\initrd.img-6.1.0-28-amd64
Feb 23 17:46:41 debian kernel: clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 76450417870 ns
Feb 23 17:46:41 debian kernel: clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x263efc7f39c, max_idle_ns: 440795295273 ns
Feb 23 17:46:41 debian kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
Feb 23 17:46:41 debian kernel: clocksource: Switched to clocksource tsc-early
Feb 23 17:46:41 debian kernel: clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
Feb 23 17:46:41 debian kernel: tsc: Refined TSC clocksource calibration: 2653.335 MHz
Feb 23 17:46:41 debian kernel: clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x263f0bda6a8, max_idle_ns: 440795254345 ns
Feb 23 17:46:41 debian kernel: clocksource: Switched to clocksource tsc
Feb 23 17:46:41 debian kernel: clocksource: Long readout interval, skipping watchdog check: cs_nsec: 512005976 wd_nsec: 20666406840
Feb 23 17:46:41 debian kernel: clocksource: timekeeping watchdog on CPU0: Marking clocksource 'tsc' as unstable because the skew is too large:
Feb 23 17:46:41 debian kernel: clocksource: 'hpet' wd_nsec: 790554840 wd_now: 23c18feb wd_last: 2293fd4c mask: ffffffff
Feb 23 17:46:41 debian kernel: clocksource: 'tsc' cs_nsec: 511994526 cs_now: 1b57fd14b2 cs_last: 1b07041f1a mask: ffffffffffffffff
Feb 23 17:46:41 debian kernel: clocksource: 'tsc' is current clocksource.
Feb 23 17:46:41 debian kernel: tsc: Marking TSC unstable due to clocksource watchdog
Feb 23 17:46:41 debian kernel: TSC found unstable after boot, most likely due to broken BIOS. Use 'tsc=unstable'.
Feb 23 17:46:41 debian kernel: clocksource: Checking clocksource tsc synchronization from CPU 0 to CPUs 1.
Feb 23 17:46:41 debian kernel: clocksource: Switched to clocksource hpet