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

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

[Fab Stz]

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

Hi,

While upgrading from Debian bullseye (kernel 5.10) to bookworm (6.1) I 
noticed that the newer kernel is at the beginning of the boot stuck for 
more than 60 seconds.

This is apparently related to the clocksource module. If I boot with 
tsc=unstable there is no more delay.

In the kernel logs, I have:

clocksource: Long readout interval, skipping watchdog check: cs_nsec: 
512010551 wd_nsec: 39243763320
clocksource: timekeeping watchdog on CPU0: Marking clocksource 'tsc' as 
unstable because the skew is too large:
clocksource:                       'hpet' wd_nsec: 537773520 wd_now: 
3f0f7632 wd_last: 3e425140 mask: ffffffff
clocksource:                       'tsc' cs_nsec: 511996079 cs_now: 
18b0866e6a cs_last: 185f8d68ba mask: ffffffffffffffff
clocksource:                       'tsc' is current clocksource.
tsc: Marking TSC unstable due to clocksource watchdog
TSC found unstable after boot, most likely due to broken BIOS. Use 
'tsc=unstable'.
sched_clock: Marking unstable (3765559657, 1276001)<-(3775071370, -8235646)
clocksource: Checking clocksource tsc synchronization from CPU 1 to CPUs 0.
clocksource: Switched to clocksource hpet


I already had such a warning with 5.10, but there was no >60sec freeze 
with it like with 6.1

The delay is still present in kernel 6.11.

I attach the output of dmesg. On screen, the last line that is displayed 
before being frozen for >60sec is

[    2.898668] hub 2-0:1.0: 5 ports detected

Because of that, I initially thought that there is a problem with USB, 
but actually not since tsc=unstable "fixes" the delay. The kernel 
mentions clocksource only later in the logs, but the timestamps don't 
reflect the delay. My last measure is a freeze of about 70seconds.

I also noticed that if during that period I do a short press on the 
power button of the system, it stops the freeze and the boot process 
continues immediately.

Regards

==== System information ====

It's an Apple iMac 9.1

# cat /proc/version
Linux version 6.1.0-28-amd64 (debian-kernel@lists.debian.org) (gcc-12 
(Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40) #1 SMP 
PREEMPT_DYNAMIC Debian 6.1.119-1 (2024-11-22)

# hostnamectl | grep "Operating System"
Operating System: Debian GNU/Linux 12 (bookworm)

# uname -mi
x86_64 unknown

# lspci -nn
00:00.0 Host bridge [0600]: NVIDIA Corporation MCP79 Host Bridge 
[10de:0a82] (rev b1)
00:00.1 RAM memory [0500]: NVIDIA Corporation MCP79 Memory Controller 
[10de:0a88] (rev b1)
00:03.0 ISA bridge [0601]: NVIDIA Corporation MCP79 LPC Bridge 
[10de:0aae] (rev b2)
00:03.1 RAM memory [0500]: NVIDIA Corporation MCP79 Memory Controller 
[10de:0aa4] (rev b1)
00:03.2 SMBus [0c05]: NVIDIA Corporation MCP79 SMBus [10de:0aa2] (rev b1)
00:03.3 RAM memory [0500]: NVIDIA Corporation MCP79 Memory Controller 
[10de:0a89] (rev b1)
00:03.4 RAM memory [0500]: NVIDIA Corporation MCP79 Memory Controller 
[10de:0a98] (rev b1)
00:03.5 Co-processor [0b40]: NVIDIA Corporation MCP79 Co-processor 
[10de:0aa3] (rev b1)
00:04.0 USB controller [0c03]: NVIDIA Corporation MCP79 OHCI USB 1.1 
Controller [10de:0aa5] (rev b1)
00:04.1 USB controller [0c03]: NVIDIA Corporation MCP79 EHCI USB 2.0 
Controller [10de:0aa6] (rev b1)
00:06.0 USB controller [0c03]: NVIDIA Corporation MCP79 OHCI USB 1.1 
Controller [10de:0aa7] (rev b1)
00:06.1 USB controller [0c03]: NVIDIA Corporation MCP79 EHCI USB 2.0 
Controller [10de:0aa9] (rev b1)
00:08.0 Audio device [0403]: NVIDIA Corporation MCP79 High Definition 
Audio [10de:0ac0] (rev b1)
00:09.0 PCI bridge [0604]: NVIDIA Corporation MCP79 PCI Bridge 
[10de:0aab] (rev b1)
00:0a.0 Ethernet controller [0200]: NVIDIA Corporation MCP79 Ethernet 
[10de:0ab0] (rev b1)
00:0b.0 SATA controller [0106]: NVIDIA Corporation MCP79 AHCI Controller 
[10de:0ab9] (rev b1)
00:0c.0 PCI bridge [0604]: NVIDIA Corporation MCP79 PCI Express Bridge 
[10de:0ac4] (rev b1)
00:10.0 PCI bridge [0604]: NVIDIA Corporation MCP79 PCI Express Bridge 
[10de:0aa0] (rev b1)
00:15.0 PCI bridge [0604]: NVIDIA Corporation MCP79 PCI Express Bridge 
[10de:0ac6] (rev b1)
00:16.0 PCI bridge [0604]: NVIDIA Corporation MCP79 PCI Express Bridge 
[10de:0ac7] (rev b1)
03:00.0 VGA compatible controller [0300]: NVIDIA Corporation C79 
[GeForce 9400] [10de:0867] (rev b1)
04:00.0 Network controller [0280]: Broadcom Inc. and subsidiaries 
BCM4322 802.11a/b/g/n Wireless LAN Controller [14e4:432b] (rev 01)
05:00.0 FireWire (IEEE 1394) [0c00]: LSI Corporation FW643 [TrueFire] 
PCIe 1394b Controller [11c1:5901] (rev 07)

[-- Attachment #2: dmesg.noparam.txt.gz --]
[-- Type: application/gzip, Size: 23540 bytes --]

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

[Fab Stz]

Hello,

It's been one month now that I sent this email. Do you have any clue on this?

Regards
Fab


Le mercredi 27 novembre 2024, 08:18:41 CET Fab Stz a écrit :
> Hi,
> 
> While upgrading from Debian bullseye (kernel 5.10) to bookworm (6.1) I
> noticed that the newer kernel is at the beginning of the boot stuck for
> more than 60 seconds.
> 
> This is apparently related to the clocksource module. If I boot with
> tsc=unstable there is no more delay.
> 
> In the kernel logs, I have:
> 
> clocksource: Long readout interval, skipping watchdog check: cs_nsec:
> 512010551 wd_nsec: 39243763320
> clocksource: timekeeping watchdog on CPU0: Marking clocksource 'tsc' as
> unstable because the skew is too large:
> clocksource:                       'hpet' wd_nsec: 537773520 wd_now:
> 3f0f7632 wd_last: 3e425140 mask: ffffffff
> clocksource:                       'tsc' cs_nsec: 511996079 cs_now:
> 18b0866e6a cs_last: 185f8d68ba mask: ffffffffffffffff
> clocksource:                       'tsc' is current clocksource.
> tsc: Marking TSC unstable due to clocksource watchdog
> TSC found unstable after boot, most likely due to broken BIOS. Use
> 'tsc=unstable'.
> sched_clock: Marking unstable (3765559657, 1276001)<-(3775071370, -8235646)
> clocksource: Checking clocksource tsc synchronization from CPU 1 to CPUs 0.
> clocksource: Switched to clocksource hpet
> 
> 
> I already had such a warning with 5.10, but there was no >60sec freeze
> with it like with 6.1
> 
> The delay is still present in kernel 6.11.
> 
> I attach the output of dmesg. On screen, the last line that is displayed
> before being frozen for >60sec is
> 
> [    2.898668] hub 2-0:1.0: 5 ports detected
> 
> Because of that, I initially thought that there is a problem with USB,
> but actually not since tsc=unstable "fixes" the delay. The kernel
> mentions clocksource only later in the logs, but the timestamps don't
> reflect the delay. My last measure is a freeze of about 70seconds.
> 
> I also noticed that if during that period I do a short press on the
> power button of the system, it stops the freeze and the boot process
> continues immediately.
> 
> Regards
> 
> ==== System information ====
> 
> It's an Apple iMac 9.1
> 
> # cat /proc/version
> Linux version 6.1.0-28-amd64 (debian-kernel@lists.debian.org) (gcc-12
> (Debian 12.2.0-14) 12.2.0, GNU ld (GNU Binutils for Debian) 2.40) #1 SMP
> PREEMPT_DYNAMIC Debian 6.1.119-1 (2024-11-22)
> 
> # hostnamectl | grep "Operating System"
> Operating System: Debian GNU/Linux 12 (bookworm)
> 
> # uname -mi
> x86_64 unknown
> 
> # lspci -nn
> 00:00.0 Host bridge [0600]: NVIDIA Corporation MCP79 Host Bridge
> [10de:0a82] (rev b1)
> 00:00.1 RAM memory [0500]: NVIDIA Corporation MCP79 Memory Controller
> [10de:0a88] (rev b1)
> 00:03.0 ISA bridge [0601]: NVIDIA Corporation MCP79 LPC Bridge
> [10de:0aae] (rev b2)
> 00:03.1 RAM memory [0500]: NVIDIA Corporation MCP79 Memory Controller
> [10de:0aa4] (rev b1)
> 00:03.2 SMBus [0c05]: NVIDIA Corporation MCP79 SMBus [10de:0aa2] (rev b1)
> 00:03.3 RAM memory [0500]: NVIDIA Corporation MCP79 Memory Controller
> [10de:0a89] (rev b1)
> 00:03.4 RAM memory [0500]: NVIDIA Corporation MCP79 Memory Controller
> [10de:0a98] (rev b1)
> 00:03.5 Co-processor [0b40]: NVIDIA Corporation MCP79 Co-processor
> [10de:0aa3] (rev b1)
> 00:04.0 USB controller [0c03]: NVIDIA Corporation MCP79 OHCI USB 1.1
> Controller [10de:0aa5] (rev b1)
> 00:04.1 USB controller [0c03]: NVIDIA Corporation MCP79 EHCI USB 2.0
> Controller [10de:0aa6] (rev b1)
> 00:06.0 USB controller [0c03]: NVIDIA Corporation MCP79 OHCI USB 1.1
> Controller [10de:0aa7] (rev b1)
> 00:06.1 USB controller [0c03]: NVIDIA Corporation MCP79 EHCI USB 2.0
> Controller [10de:0aa9] (rev b1)
> 00:08.0 Audio device [0403]: NVIDIA Corporation MCP79 High Definition
> Audio [10de:0ac0] (rev b1)
> 00:09.0 PCI bridge [0604]: NVIDIA Corporation MCP79 PCI Bridge
> [10de:0aab] (rev b1)
> 00:0a.0 Ethernet controller [0200]: NVIDIA Corporation MCP79 Ethernet
> [10de:0ab0] (rev b1)
> 00:0b.0 SATA controller [0106]: NVIDIA Corporation MCP79 AHCI Controller
> [10de:0ab9] (rev b1)
> 00:0c.0 PCI bridge [0604]: NVIDIA Corporation MCP79 PCI Express Bridge
> [10de:0ac4] (rev b1)
> 00:10.0 PCI bridge [0604]: NVIDIA Corporation MCP79 PCI Express Bridge
> [10de:0aa0] (rev b1)
> 00:15.0 PCI bridge [0604]: NVIDIA Corporation MCP79 PCI Express Bridge
> [10de:0ac6] (rev b1)
> 00:16.0 PCI bridge [0604]: NVIDIA Corporation MCP79 PCI Express Bridge
> [10de:0ac7] (rev b1)
> 03:00.0 VGA compatible controller [0300]: NVIDIA Corporation C79
> [GeForce 9400] [10de:0867] (rev b1)
> 04:00.0 Network controller [0280]: Broadcom Inc. and subsidiaries
> BCM4322 802.11a/b/g/n Wireless LAN Controller [14e4:432b] (rev 01)
> 05:00.0 FireWire (IEEE 1394) [0c00]: LSI Corporation FW643 [TrueFire]
> PCIe 1394b Controller [11c1:5901] (rev 07)

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

[John Stultz]

On Fri, Dec 27, 2024 at 4:39 AM Fab Stz <fabstz-it@yahoo.fr> wrote:
>
> Hello,
>
> It's been one month now that I sent this email. Do you have any clue on this?

Apologies you didn't get a quick response, but you didn't really cc
many people on the first one.


> Le mercredi 27 novembre 2024, 08:18:41 CET Fab Stz a écrit :
> > Hi,
> >
> > While upgrading from Debian bullseye (kernel 5.10) to bookworm (6.1) I
> > noticed that the newer kernel is at the beginning of the boot stuck for
> > more than 60 seconds.
> >
> > This is apparently related to the clocksource module. If I boot with
> > tsc=unstable there is no more delay.
> >
> > In the kernel logs, I have:
> >
> > clocksource: Long readout interval, skipping watchdog check: cs_nsec:
> > 512010551 wd_nsec: 39243763320
> > clocksource: timekeeping watchdog on CPU0: Marking clocksource 'tsc' as
> > unstable because the skew is too large:
> > clocksource:                       'hpet' wd_nsec: 537773520 wd_now:
> > 3f0f7632 wd_last: 3e425140 mask: ffffffff
> > clocksource:                       'tsc' cs_nsec: 511996079 cs_now:
> > 18b0866e6a cs_last: 185f8d68ba mask: ffffffffffffffff
> > clocksource:                       'tsc' is current clocksource.
> > tsc: Marking TSC unstable due to clocksource watchdog
> > TSC found unstable after boot, most likely due to broken BIOS. Use
> > 'tsc=unstable'.
> > sched_clock: Marking unstable (3765559657, 1276001)<-(3775071370, -8235646)
> > clocksource: Checking clocksource tsc synchronization from CPU 1 to CPUs 0.
> > clocksource: Switched to clocksource hpet
> >
> >
> > I already had such a warning with 5.10, but there was no >60sec freeze
> > with it like with 6.1

So, it sounds like your TSC stalls in idle (likely missing
X86_FEATURE_NONSTOP_TSC), and probably something between 5.10 and 6.1
added a sleep which causes the stall before the clocksource watchdog
can check and disable the TSC on its own.

The kernel is telling you tsc=unstable is the way to go here, and it
seems that is working for you.  From my first glance, I'd not call
this a regression, as the kernel was warning you about the problematic
hardware before, and it was most likely just luck that it was able to
auto-detect the problem before there were any negative results.

That said, if you're still curious, you might try bisecting kernel
versions between 5.10 and 6.1 to see which commit might have caused
the change in behavior.

thanks
-john

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

[John Stultz]

On Thu, Jan 2, 2025 at 1:49 PM John Stultz <jstultz@google.com> wrote:
>
> On Fri, Dec 27, 2024 at 4:39 AM Fab Stz <fabstz-it@yahoo.fr> wrote:
> >
> > Hello,
> >
> > It's been one month now that I sent this email. Do you have any clue on this?
>
> Apologies you didn't get a quick response, but you didn't really cc
> many people on the first one.
>
>
> > Le mercredi 27 novembre 2024, 08:18:41 CET Fab Stz a écrit :
> > > Hi,
> > >
> > > While upgrading from Debian bullseye (kernel 5.10) to bookworm (6.1) I
> > > noticed that the newer kernel is at the beginning of the boot stuck for
> > > more than 60 seconds.
> > >
> > > This is apparently related to the clocksource module. If I boot with
> > > tsc=unstable there is no more delay.
> > >
> > > In the kernel logs, I have:
> > >
> > > clocksource: Long readout interval, skipping watchdog check: cs_nsec:
> > > 512010551 wd_nsec: 39243763320
> > > clocksource: timekeeping watchdog on CPU0: Marking clocksource 'tsc' as
> > > unstable because the skew is too large:
> > > clocksource:                       'hpet' wd_nsec: 537773520 wd_now:
> > > 3f0f7632 wd_last: 3e425140 mask: ffffffff
> > > clocksource:                       'tsc' cs_nsec: 511996079 cs_now:
> > > 18b0866e6a cs_last: 185f8d68ba mask: ffffffffffffffff
> > > clocksource:                       'tsc' is current clocksource.
> > > tsc: Marking TSC unstable due to clocksource watchdog
> > > TSC found unstable after boot, most likely due to broken BIOS. Use
> > > 'tsc=unstable'.
> > > sched_clock: Marking unstable (3765559657, 1276001)<-(3775071370, -8235646)
> > > clocksource: Checking clocksource tsc synchronization from CPU 1 to CPUs 0.
> > > clocksource: Switched to clocksource hpet
> > >
> > >
> > > I already had such a warning with 5.10, but there was no >60sec freeze
> > > with it like with 6.1
>
> So, it sounds like your TSC stalls in idle (likely missing
> X86_FEATURE_NONSTOP_TSC), and probably something between 5.10 and 6.1
> added a sleep which causes the stall before the clocksource watchdog
> can check and disable the TSC on its own.
>
> The kernel is telling you tsc=unstable is the way to go here, and it
> seems that is working for you.  From my first glance, I'd not call
> this a regression, as the kernel was warning you about the problematic
> hardware before, and it was most likely just luck that it was able to
> auto-detect the problem before there were any negative results.

Debian even suggests this for the iMac9,1 hardware you're using:
https://wiki.debian.org/InstallingDebianOn/Apple/iMac/9-1#Boot_on_installer

And highlights the exact behavior you describe (maybe this is your efforts?):
https://wiki.debian.org/InstallingDebianOn/Apple/iMac/9-1#Kernel_configuration

thanks
-john

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

[Fab Stz]

Hello John,

Le 02/01/2025 à 22:56, John Stultz a écrit :
> On Thu, Jan 2, 2025 at 1:49 PM John Stultz <jstultz@google.com> wrote:
>>
>> On Fri, Dec 27, 2024 at 4:39 AM Fab Stz <fabstz-it@yahoo.fr> wrote:
>>>
>>> Hello,
>>>
>>> It's been one month now that I sent this email. Do you have any clue on this?
>>
>> Apologies you didn't get a quick response, but you didn't really cc
>> many people on the first one.

No problem. I thought it was better not to put too many people in copy 
in the first message given that it was also sent to the mailing list.

>>> Le mercredi 27 novembre 2024, 08:18:41 CET Fab Stz a écrit :
>>>> Hi,
>>>>
>>>> While upgrading from Debian bullseye (kernel 5.10) to bookworm (6.1) I
>>>> noticed that the newer kernel is at the beginning of the boot stuck for
>>>> more than 60 seconds.
>>>>
>>>> This is apparently related to the clocksource module. If I boot with
>>>> tsc=unstable there is no more delay.
>>>>
>>>> In the kernel logs, I have:
>>>>
>>>> clocksource: Long readout interval, skipping watchdog check: cs_nsec:
>>>> 512010551 wd_nsec: 39243763320
>>>> clocksource: timekeeping watchdog on CPU0: Marking clocksource 'tsc' as
>>>> unstable because the skew is too large:
>>>> clocksource:                       'hpet' wd_nsec: 537773520 wd_now:
>>>> 3f0f7632 wd_last: 3e425140 mask: ffffffff
>>>> clocksource:                       'tsc' cs_nsec: 511996079 cs_now:
>>>> 18b0866e6a cs_last: 185f8d68ba mask: ffffffffffffffff
>>>> clocksource:                       'tsc' is current clocksource.
>>>> tsc: Marking TSC unstable due to clocksource watchdog
>>>> TSC found unstable after boot, most likely due to broken BIOS. Use
>>>> 'tsc=unstable'.
>>>> sched_clock: Marking unstable (3765559657, 1276001)<-(3775071370, -8235646)
>>>> clocksource: Checking clocksource tsc synchronization from CPU 1 to CPUs 0.
>>>> clocksource: Switched to clocksource hpet
>>>>
>>>>
>>>> I already had such a warning with 5.10, but there was no >60sec freeze
>>>> with it like with 6.1
>>
>> So, it sounds like your TSC stalls in idle (likely missing
>> X86_FEATURE_NONSTOP_TSC), and probably something between 5.10 and 6.1
>> added a sleep which causes the stall before the clocksource watchdog
>> can check and disable the TSC on its own.
>>
>> The kernel is telling you tsc=unstable is the way to go here, and it
>> seems that is working for you.  From my first glance, I'd not call
>> this a regression, as the kernel was warning you about the problematic
>> hardware before, and it was most likely just luck that it was able to
>> auto-detect the problem before there were any negative results.
> 
> Debian even suggests this for the iMac9,1 hardware you're using:
> https://wiki.debian.org/InstallingDebianOn/Apple/iMac/9-1#Boot_on_installer
> 
> And highlights the exact behavior you describe (maybe this is your efforts?):
> https://wiki.debian.org/InstallingDebianOn/Apple/iMac/9-1#Kernel_configuration


I'm the author of that page on the debian wiki, indeed.


My findings are as follows:

* No delay with the following kernel versions shipped by debian (when 
run on up-to-date bookworm as of today)
5.10.226, 5.19.11, 6.0.10, 6.1.4, 6.1.27, 6.1.38, 6.1.66, 6.1.76, 6.1.82

* Delay with the following kernel versions:
5.15.15, 6.1.85, 6.1.119

So something probably happened between 6.1.82 & 6.1.85 (debian doesn't 
ship packages for versions between them). Why 5.15.15 also has a delay 
is not clear.

For the versions where there is a delay, the warning from clocksource 
mentioning an unstable clock always comes after the first line that 
mentions USB "ACPI: bus type USB registered".

For the versions which don't have a boot delay, the warning from 
clocksource mentioning an unstable clock always comes before the first 
line that mentions USB "ACPI: bus type USB registered".

However, with 6.1.82, sometimes the unstable clocksource message comes 
after the USB line, but when this happens, both messages are very close 
in time (less than 50ms?) so that the subsequent usb messages always 
appear after the clocksource message. So the return from the clocksource 
might be early enough to not encounter the lock.

Actually, the lock is usually bit later than the "ACPI: bus type USB 
registered", and the message at the time of the lock is related to USB.

Moreover, whether there is a boot delay or not:

- the line "ACPI: bus type USB registered" always comes after "Run /init 
as init process"

- the warning from clocksource mentioning an unstable clock may or may 
not be after "Run /init as init process"

Could it be that USB should not be registered/loaded before it was 
determined whether clocksource is unstable or not?

Regards
Fab

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

[John Stultz]

On Fri, Jan 3, 2025 at 7:38 AM Fab Stz <fabstz-it@yahoo.fr> wrote:
> Le 02/01/2025 à 22:56, John Stultz a écrit :
> > On Thu, Jan 2, 2025 at 1:49 PM John Stultz <jstultz@google.com> wrote:
> >> So, it sounds like your TSC stalls in idle (likely missing
> >> X86_FEATURE_NONSTOP_TSC), and probably something between 5.10 and 6.1
> >> added a sleep which causes the stall before the clocksource watchdog
> >> can check and disable the TSC on its own.
> >>
> >> The kernel is telling you tsc=unstable is the way to go here, and it
> >> seems that is working for you.  From my first glance, I'd not call
> >> this a regression, as the kernel was warning you about the problematic
> >> hardware before, and it was most likely just luck that it was able to
> >> auto-detect the problem before there were any negative results.
> >
> > Debian even suggests this for the iMac9,1 hardware you're using:
> > https://wiki.debian.org/InstallingDebianOn/Apple/iMac/9-1#Boot_on_installer
> >
> > And highlights the exact behavior you describe (maybe this is your efforts?):
> > https://wiki.debian.org/InstallingDebianOn/Apple/iMac/9-1#Kernel_configuration
>
>
> I'm the author of that page on the debian wiki, indeed.

Heh. It sounded suspiciously similar :)


> My findings are as follows:
>
> * No delay with the following kernel versions shipped by debian (when
> run on up-to-date bookworm as of today)
> 5.10.226, 5.19.11, 6.0.10, 6.1.4, 6.1.27, 6.1.38, 6.1.66, 6.1.76, 6.1.82
>
> * Delay with the following kernel versions:
> 5.15.15, 6.1.85, 6.1.119
>
> So something probably happened between 6.1.82 & 6.1.85 (debian doesn't
> ship packages for versions between them). Why 5.15.15 also has a delay
> is not clear.

So from a quick scan of the v6.1.82..v6.1.85 delta around timekeeping,
usb and ACPI, I don't see anything obviously sticking out.

I suspect to get a finer sense of it, you'll need to be able to build
and test specific kernel versions so the change in behavior can be
properly bisected.

> For the versions where there is a delay, the warning from clocksource
> mentioning an unstable clock always comes after the first line that
> mentions USB "ACPI: bus type USB registered".
>
> For the versions which don't have a boot delay, the warning from
> clocksource mentioning an unstable clock always comes before the first
> line that mentions USB "ACPI: bus type USB registered".

So for this sort of debugging, it can be helpful to boot with
"initcall_debug loglevel=8" boot arguments.

> However, with 6.1.82, sometimes the unstable clocksource message comes
> after the USB line, but when this happens, both messages are very close
> in time (less than 50ms?) so that the subsequent usb messages always
> appear after the clocksource message. So the return from the clocksource
> might be early enough to not encounter the lock.
>
> Actually, the lock is usually bit later than the "ACPI: bus type USB
> registered", and the message at the time of the lock is related to USB.
>
> Moreover, whether there is a boot delay or not:
>
> - the line "ACPI: bus type USB registered" always comes after "Run /init
> as init process"
>
> - the warning from clocksource mentioning an unstable clock may or may
> not be after "Run /init as init process"

Thanks for the extra details here. Though I don't have much of an idea
right off. There could be other indirect changes that can cause these
things (cpuidle tweaks to how deep the cpu sleeps, etc).
Bisection is probably the most foolproof method of narrowing this down.

> Could it be that USB should not be registered/loaded before it was
> determined whether clocksource is unstable or not?

Ideally, but testing the clocksource takes time, and as we are
optimizing for the case where the hardware works properly, we don't
want to delay booting for everyone. There might be other approaches,
like not selecting the TSC until its proven itself stable, but that
opens a whole different can of worms for systems where the TSC was
fine but the other clocksources (like HPET or ACPI PM) were buggy,
effectively moving your regression to someone else.

Booting with "tsc=unstable" or possibly in your case
"processor.max_cstate=1" (it's been awhile since I tried it, but it
should keep the cpu out of deep idle where the TSC halts) are likely
the best workarounds.

thanks
-john

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

[Fab Stz]

Le 03/01/2025 à 20:02, John Stultz a écrit :
 > On Fri, Jan 3, 2025 at 7:38 AM Fab Stz <fabstz-it@yahoo.fr> wrote:
 >
 >> My findings are as follows:
 >>
 >> * No delay with the following kernel versions shipped by debian (when
 >> run on up-to-date bookworm as of today)
 >> 5.10.226, 5.19.11, 6.0.10, 6.1.4, 6.1.27, 6.1.38, 6.1.66, 6.1.76, 6.1.82
 >>
 >> * Delay with the following kernel versions:
 >> 5.15.15, 6.1.85, 6.1.119
 >>
 >> So something probably happened between 6.1.82 & 6.1.85 (debian doesn't
 >> ship packages for versions between them). Why 5.15.15 also has a delay
 >> is not clear.
 >
 > So from a quick scan of the v6.1.82..v6.1.85 delta around timekeeping,
 > usb and ACPI, I don't see anything obviously sticking out.
 >
 > I suspect to get a finer sense of it, you'll need to be able to build
 > and test specific kernel versions so the change in behavior can be
 > properly bisected.
 >
 >> For the versions where there is a delay, the warning from clocksource
 >> mentioning an unstable clock always comes after the first line that
 >> mentions USB "ACPI: bus type USB registered".
 >>
 >> For the versions which don't have a boot delay, the warning from
 >> clocksource mentioning an unstable clock always comes before the first
 >> line that mentions USB "ACPI: bus type USB registered".
 >
 > So for this sort of debugging, it can be helpful to boot with
 > "initcall_debug loglevel=8" boot arguments.
 >
 >> However, with 6.1.82, sometimes the unstable clocksource message comes
 >> after the USB line, but when this happens, both messages are very close
 >> in time (less than 50ms?) so that the subsequent usb messages always
 >> appear after the clocksource message. So the return from the clocksource
 >> might be early enough to not encounter the lock.
 >>
 >> Actually, the lock is usually bit later than the "ACPI: bus type USB
 >> registered", and the message at the time of the lock is related to USB.
 >>
 >> Moreover, whether there is a boot delay or not:
 >>
 >> - the line "ACPI: bus type USB registered" always comes after "Run /init
 >> as init process"
 >>
 >> - the warning from clocksource mentioning an unstable clock may or may
 >> not be after "Run /init as init process"
 >
 > Thanks for the extra details here. Though I don't have much of an idea
 > right off. There could be other indirect changes that can cause these
 > things (cpuidle tweaks to how deep the cpu sleeps, etc).
 > Bisection is probably the most foolproof method of narrowing this down.
 >
 >> Could it be that USB should not be registered/loaded before it was
 >> determined whether clocksource is unstable or not?
 >
 > Ideally, but testing the clocksource takes time, and as we are
 > optimizing for the case where the hardware works properly, we don't
 > want to delay booting for everyone. There might be other approaches,
 > like not selecting the TSC until its proven itself stable, but that
 > opens a whole different can of worms for systems where the TSC was
 > fine but the other clocksources (like HPET or ACPI PM) were buggy,
 > effectively moving your regression to someone else.
 >
 > Booting with "tsc=unstable" or possibly in your case
 > "processor.max_cstate=1" (it's been awhile since I tried it, but it
 > should keep the cpu out of deep idle where the TSC halts) are likely
 > the best workarounds.
When building the kernel from the sources from the stable repo of the 
kernel to try a git bisect I couldn't reproduce a case where the warning 
is before loading '/init' with the versions I mentioned as working. 
Maybe I was just lucky as you mentioned. If the warning comes before the 
loading of USB modules, there is no delay. If it comes after, there is a 
delay.

If I break/pause at the beginning of the /init script, the warning never 
comes before. I don't really understand what is happening and where the 
problem actually lies (kernel? systemd? udev? somewhere else?). If I add 
a "sleep 5" as 1st command in "/init" it would take ages. So as long as 
the warning from the clocksource is not displayed, the delays seem 
completely wrong. Maybe the USB drivers somehow rely on a reliable clock 
source for proper functioning.

BTW, I tried the "processor.max_cstate=1" you mentioned but it didn't 
change anything on the delay and/or warning.

Regards
Fab

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

[Thomas Gleixner]

On Sat, Jan 04 2025 at 23:02, Fab Stz wrote:
> Le 03/01/2025 à 20:02, John Stultz a écrit :
> When building the kernel from the sources from the stable repo of the 
> kernel to try a git bisect I couldn't reproduce a case where the warning 
> is before loading '/init' with the versions I mentioned as working. 
> Maybe I was just lucky as you mentioned. If the warning comes before the 
> loading of USB modules, there is no delay. If it comes after, there is a 
> delay.

This is a timing problem, which depends on kernel configuration and
run-time differences, but that's just a symptom. It explains why you are
seeing it sometimes and sometimes not. Nothing else.

> If I break/pause at the beginning of the /init script, the warning never 
> comes before. I don't really understand what is happening and where the 
> problem actually lies (kernel? systemd? udev? somewhere else?). If I add 
> a "sleep 5" as 1st command in "/init" it would take ages. So as long as 
> the warning from the clocksource is not displayed, the delays seem 
> completely wrong.

That's an interesting data point because that 'sleep 5' puts the system
into idle and probably into deep idle for the first time during boot.

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

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

Can you try 'idle=halt' instead?

Thanks,

        tglx

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

[Fab Stz]

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

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

[Thomas Gleixner]

Fab!

On Sun, Feb 23 2025 at 18:01, Fab Stz wrote:
> Le 15/01/2025 à 17:59, Thomas Gleixner a écrit :
>> 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

Ok.

>>> 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.
>
> Output of these commands can be found in attached file cpuidle.txt

> + cat /sys/devices/system/cpu/cpuidle/current_driver
> intel_idle

So according to that the intel_idle driver is in use, which does not
have the magic TSC workarounds like the acpi processor driver has, but
it seems to be loaded preferred.

Sigh. Why is the intel_idle driver so agressive in taking over despite
the fact that it does not handle the old CPUs, which are known to
require the TSC workaround? It handles the APIC stops in C2, but not the
TSC oddity while the original ACPI processor_idle driver does the right
thing for more than two decades....

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

Yes, we can. Untested patch below. It just brings the intel idle driver
on par with the original ACPI processor idle driver to deal with that
problem.

Thanks,

        tglx
---
diff --git a/drivers/idle/intel_idle.c b/drivers/idle/intel_idle.c
index 118fe1d37c22..0fdb1d1316c4 100644
--- a/drivers/idle/intel_idle.c
+++ b/drivers/idle/intel_idle.c
@@ -56,6 +56,7 @@
 #include <asm/intel-family.h>
 #include <asm/mwait.h>
 #include <asm/spec-ctrl.h>
+#include <asm/tsc.h>
 #include <asm/fpu/api.h>
 
 #define INTEL_IDLE_VERSION "0.5.1"
@@ -1799,6 +1800,9 @@ static void __init intel_idle_init_cstates_acpi(struct cpuidle_driver *drv)
 		if (intel_idle_state_needs_timer_stop(state))
 			state->flags |= CPUIDLE_FLAG_TIMER_STOP;
 
+		if (cx->type > ACPI_STATE_C1 && !boot_cpu_has(X86_FEATURE_NONSTOP_TSC))
+			mark_tsc_unstable("TSC halts in idle");
+
 		state->enter = intel_idle;
 		state->enter_s2idle = intel_idle_s2idle;
 	}

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

[Fab Stz]

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

Hello Thomas,

Thank you for the patch! I built the 6.1 kernel with it applied and it 
apparently works as expected (no delay). Please find logs below & 
attached dmesg log. Maybe the interesting line is:

Feb 25 08:53:51 debian kernel: tsc: Marking TSC unstable due to TSC 
halts in idle

Comparison shows that it is "Marking TSC unstable due to boot parameter" 
with a non patched kernel + 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


Will the patch also enter the longterm releases like 6.1?

Regards
Fab


Le 24/02/2025 à 09:13, Thomas Gleixner a écrit :
>>>> 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.
>>
>> Output of these commands can be found in attached file cpuidle.txt
> 
>> + cat /sys/devices/system/cpu/cpuidle/current_driver
>> intel_idle
> 
> So according to that the intel_idle driver is in use, which does not
> have the magic TSC workarounds like the acpi processor driver has, but
> it seems to be loaded preferred.
> 
> Sigh. Why is the intel_idle driver so agressive in taking over despite
> the fact that it does not handle the old CPUs, which are known to
> require the TSC workaround? It handles the APIC stops in C2, but not the
> TSC oddity while the original ACPI processor_idle driver does the right
> thing for more than two decades....
> 
>> 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.
> 
> Yes, we can. Untested patch below. It just brings the intel idle driver
> on par with the original ACPI processor idle driver to deal with that
> problem.
> 
> Thanks,
> 
>          tglx
> ---
> diff --git a/drivers/idle/intel_idle.c b/drivers/idle/intel_idle.c
> index 118fe1d37c22..0fdb1d1316c4 100644
> --- a/drivers/idle/intel_idle.c
> +++ b/drivers/idle/intel_idle.c
> @@ -56,6 +56,7 @@
>   #include <asm/intel-family.h>
>   #include <asm/mwait.h>
>   #include <asm/spec-ctrl.h>
> +#include <asm/tsc.h>
>   #include <asm/fpu/api.h>
>   
>   #define INTEL_IDLE_VERSION "0.5.1"
> @@ -1799,6 +1800,9 @@ static void __init intel_idle_init_cstates_acpi(struct cpuidle_driver *drv)
>   		if (intel_idle_state_needs_timer_stop(state))
>   			state->flags |= CPUIDLE_FLAG_TIMER_STOP;
>   
> +		if (cx->type > ACPI_STATE_C1 && !boot_cpu_has(X86_FEATURE_NONSTOP_TSC))
> +			mark_tsc_unstable("TSC halts in idle");
> +
>   		state->enter = intel_idle;
>   		state->enter_s2idle = intel_idle_s2idle;
>   	}


[-- Attachment #2: patched.log --]
[-- Type: text/x-log, Size: 2020 bytes --]

Feb 25 08:53:50 debian kernel: Command line: root=UUID=462f57b4-136e-4c18-8c55-e4bc59cfb7aa ro  zswap.enabled=1 mem_sleep_default=deep single initrd=\boot\initrd.img-6.1.0-0.a.test-amd64                                     
Feb 25 08:53:50 debian kernel: tsc: Fast TSC calibration using PIT
Feb 25 08:53:50 debian kernel: tsc: Detected 2653.363 MHz processor
Feb 25 08:53:50 debian kernel: clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645519600211568 ns
Feb 25 08:53:50 debian kernel: Kernel command line: root=UUID=462f57b4-136e-4c18-8c55-e4bc59cfb7aa ro  zswap.enabled=1 mem_sleep_default=deep single initrd=\boot\initrd.img-6.1.0-0.a.test-amd64                                     
Feb 25 08:53:50 debian kernel: Unknown kernel command line parameters "single", will be passed to user space.
Feb 25 08:53:50 debian kernel: clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 76450417870 ns
Feb 25 08:53:50 debian kernel: clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x263f25ec687, max_idle_ns: 440795217651 ns
Feb 25 08:53:50 debian kernel: clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
Feb 25 08:53:51 debian kernel: clocksource: Switched to clocksource tsc-early
Feb 25 08:53:51 debian kernel: clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
Feb 25 08:53:51 debian kernel: tsc: Refined TSC clocksource calibration: 2653.335 MHz
Feb 25 08:53:51 debian kernel: clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x263f0bda6a8, max_idle_ns: 440795254345 ns
Feb 25 08:53:51 debian kernel: clocksource: Switched to clocksource tsc
Feb 25 08:53:51 debian kernel: tsc: Marking TSC unstable due to TSC halts in idle
Feb 25 08:53:51 debian kernel: clocksource: Checking clocksource tsc synchronization from CPU 1 to CPUs 0.
Feb 25 08:53:51 debian kernel: clocksource: Switched to clocksource hpet
                               on the kernel command line

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

[Thomas Gleixner]

On Tue, Feb 25 2025 at 09:11, Fab Stz wrote:
> Thank you for the patch! I built the 6.1 kernel with it applied and it 
> apparently works as expected (no delay). Please find logs below & 
> attached dmesg log. Maybe the interesting line is:
>
> Feb 25 08:53:51 debian kernel: tsc: Marking TSC unstable due to TSC 
> halts in idle

Correct. That's the missing piece.

> Will the patch also enter the longterm releases like 6.1?

Let me write a proper change log with a Fixes tag and cc stable, so it
will be automatically picked up.

Thanks,

        tglx

[PATCH] intel_idle: Handle older CPUs, which stop the TSC in deeper C states, correctly

[Thomas Gleixner]

The Intel idle driver is preferred over the ACPI processor idle driver,
but fails to implement the work around for Core2 generation CPUs, where
the TSC stops in C2 and deeper C-states. This causes stalls and boot
delays, when the clocksource watchdog does not catch the unstable TSC
before the CPU goes deep idle for the first time.

The ACPI driver marks the TSC unstable when it detects that the CPU
supports C2 or deeper and the CPU does not have a non-stop TSC.

Add the equivivalent work around to the Intel idle driver to cure that.

Fixes: 18734958e9bf ("intel_idle: Use ACPI _CST for processor models without C-state tables")
Reported-by: Fab Stz <fabstz-it@yahoo.fr>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
Tested-by: Fab Stz <fabstz-it@yahoo.fr>
Cc: stable@vger.kernel.org
Closes: https://lore.kernel.org/all/10cf96aa-1276-4bd4-8966-c890377030c3@yahoo.fr
---
 drivers/idle/intel_idle.c |    4 ++++
 1 file changed, 4 insertions(+)

--- a/drivers/idle/intel_idle.c
+++ b/drivers/idle/intel_idle.c
@@ -56,6 +56,7 @@
 #include <asm/intel-family.h>
 #include <asm/mwait.h>
 #include <asm/spec-ctrl.h>
+#include <asm/tsc.h>
 #include <asm/fpu/api.h>
 
 #define INTEL_IDLE_VERSION "0.5.1"
@@ -1799,6 +1800,9 @@ static void __init intel_idle_init_cstat
 		if (intel_idle_state_needs_timer_stop(state))
 			state->flags |= CPUIDLE_FLAG_TIMER_STOP;
 
+		if (cx->type > ACPI_STATE_C1 && !boot_cpu_has(X86_FEATURE_NONSTOP_TSC))
+			mark_tsc_unstable("TSC halts in idle");
+
 		state->enter = intel_idle;
 		state->enter_s2idle = intel_idle_s2idle;
 	}

Re: [PATCH] intel_idle: Handle older CPUs, which stop the TSC in deeper C states, correctly

[Rafael J. Wysocki]

On Tue, Feb 25, 2025 at 11:37 PM Thomas Gleixner <tglx@linutronix.de> wrote:
>
> The Intel idle driver is preferred over the ACPI processor idle driver,
> but fails to implement the work around for Core2 generation CPUs, where
> the TSC stops in C2 and deeper C-states. This causes stalls and boot
> delays, when the clocksource watchdog does not catch the unstable TSC
> before the CPU goes deep idle for the first time.
>
> The ACPI driver marks the TSC unstable when it detects that the CPU
> supports C2 or deeper and the CPU does not have a non-stop TSC.
>
> Add the equivivalent work around to the Intel idle driver to cure that.
>
> Fixes: 18734958e9bf ("intel_idle: Use ACPI _CST for processor models without C-state tables")
> Reported-by: Fab Stz <fabstz-it@yahoo.fr>
> Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
> Tested-by: Fab Stz <fabstz-it@yahoo.fr>
> Cc: stable@vger.kernel.org
> Closes: https://lore.kernel.org/all/10cf96aa-1276-4bd4-8966-c890377030c3@yahoo.fr
> ---
>  drivers/idle/intel_idle.c |    4 ++++
>  1 file changed, 4 insertions(+)
>
> --- a/drivers/idle/intel_idle.c
> +++ b/drivers/idle/intel_idle.c
> @@ -56,6 +56,7 @@
>  #include <asm/intel-family.h>
>  #include <asm/mwait.h>
>  #include <asm/spec-ctrl.h>
> +#include <asm/tsc.h>
>  #include <asm/fpu/api.h>
>
>  #define INTEL_IDLE_VERSION "0.5.1"
> @@ -1799,6 +1800,9 @@ static void __init intel_idle_init_cstat
>                 if (intel_idle_state_needs_timer_stop(state))
>                         state->flags |= CPUIDLE_FLAG_TIMER_STOP;
>
> +               if (cx->type > ACPI_STATE_C1 && !boot_cpu_has(X86_FEATURE_NONSTOP_TSC))
> +                       mark_tsc_unstable("TSC halts in idle");
> +
>                 state->enter = intel_idle;
>                 state->enter_s2idle = intel_idle_s2idle;
>         }

Applied as a fix for 6.14-rc5, thank you!