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

From: Fab Stz
Date: Sun Feb 23 2025 - 12:31:55 EST

Next message: Dmitry Osipenko: "[PATCH v8 1/6] MAINTAINERS: Add entry for Synopsys DesignWare HDMI RX Driver"
Previous message: Ard Biesheuvel: "Re: [RFC PATCH 00/11] Add a percpu subsection for hot data"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

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

Next message: Dmitry Osipenko: "[PATCH v8 1/6] MAINTAINERS: Add entry for Synopsys DesignWare HDMI RX Driver"
Previous message: Ard Biesheuvel: "Re: [RFC PATCH 00/11] Add a percpu subsection for hot data"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]