Hi, everyone,
I don't know if this has been reported before, but from a cursory
search it doesn't seem to be the case.
I have a x86-64 Pentium (4) D machine which always worked perfectly
with Linux 5.2 using the TSC as the clock source. With Linux 5.3-rc1 I
can't, for the life of me, boot it with anything other than
clocksource=jiffies, it completely hangs without even a backtrace.
At the moment I'm at work and, for obvious reasons, I'm not able to
bisect this remotely. In any case, if anyone has any idea about the
cause, I'll be glad to help debugging and testing any patches.
Thanks in advance,
Rui
Rui,
On Wed, 24 Jul 2019, Rui Salvaterra wrote:
> I don't know if this has been reported before, but from a cursory
> search it doesn't seem to be the case.
> I have a x86-64 Pentium (4) D machine which always worked perfectly
> with Linux 5.2 using the TSC as the clock source. With Linux 5.3-rc1 I
> can't, for the life of me, boot it with anything other than
> clocksource=jiffies, it completely hangs without even a backtrace.
The obvious candidate for this is the following section:
c8c4076723da ("x86/timer: Skip PIT initialization on modern chipsets")
dde3626f815e ("x86/apic: Use non-atomic operations when possible")
748b170ca19a ("x86/apic: Make apic_bsp_setup() static")
2420a0b1798d ("x86/tsc: Set LAPIC timer period to crystal clock frequency")
52ae346bd26c ("x86/apic: Rename 'lapic_timer_frequency' to 'lapic_timer_period'")
604dc9170f24 ("x86/tsc: Use CPUID.0x16 to calculate missing crystal frequency")
Thanks,
tglx
On Wed, 24 Jul 2019 at 12:02, Thomas Gleixner <[email protected]> wrote:
>
> Rui,
>
> On Wed, 24 Jul 2019, Rui Salvaterra wrote:
> > I don't know if this has been reported before, but from a cursory
> > search it doesn't seem to be the case.
> > I have a x86-64 Pentium (4) D machine which always worked perfectly
> > with Linux 5.2 using the TSC as the clock source. With Linux 5.3-rc1 I
> > can't, for the life of me, boot it with anything other than
> > clocksource=jiffies, it completely hangs without even a backtrace.
>
> The obvious candidate for this is the following section:
>
> c8c4076723da ("x86/timer: Skip PIT initialization on modern chipsets")
> dde3626f815e ("x86/apic: Use non-atomic operations when possible")
> 748b170ca19a ("x86/apic: Make apic_bsp_setup() static")
> 2420a0b1798d ("x86/tsc: Set LAPIC timer period to crystal clock frequency")
> 52ae346bd26c ("x86/apic: Rename 'lapic_timer_frequency' to 'lapic_timer_period'")
> 604dc9170f24 ("x86/tsc: Use CPUID.0x16 to calculate missing crystal frequency")
Hi again, everyone,
Looks like we have a winner. Actually, I did a full bisection between
5.2 and 5.3-rc1. Full log follows:
git bisect start
# good: [0ecfebd2b52404ae0c54a878c872bb93363ada36] Linux 5.2
git bisect good 0ecfebd2b52404ae0c54a878c872bb93363ada36
# bad: [5f9e832c137075045d15cd6899ab0505cfb2ca4b] Linus 5.3-rc1
git bisect bad 5f9e832c137075045d15cd6899ab0505cfb2ca4b
# bad: [e786741ff1b52769b044b7f4407f39cd13ee5d2d] Merge tag
'staging-5.3-rc1' of
git://git.kernel.org/pub/scm/linux/kernel/git/gregkh/staging
git bisect bad e786741ff1b52769b044b7f4407f39cd13ee5d2d
# bad: [8f6ccf6159aed1f04c6d179f61f6fb2691261e84] Merge tag
'clone3-v5.3' of
git://git.kernel.org/pub/scm/linux/kernel/git/brauner/linux
git bisect bad 8f6ccf6159aed1f04c6d179f61f6fb2691261e84
# bad: [ed63b9c873601ca113da5c7b1745e3946493e9f3] Merge tag
'media/v5.3-1' of
git://git.kernel.org/pub/scm/linux/kernel/git/mchehab/linux-media
git bisect bad ed63b9c873601ca113da5c7b1745e3946493e9f3
# bad: [4d2fa8b44b891f0da5ceda3e5a1402ccf0ab6f26] Merge branch 'linus'
of git://git.kernel.org/pub/scm/linux/kernel/git/herbert/crypto-2.6
git bisect bad 4d2fa8b44b891f0da5ceda3e5a1402ccf0ab6f26
# bad: [46f1ec23a46940846f86a91c46f7119d8a8b5de1] Merge branch
'core-rcu-for-linus' of
git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
git bisect bad 46f1ec23a46940846f86a91c46f7119d8a8b5de1
# good: [2a1ccd31420a7b1acd6ca37b2bec2d723aa093e4] Merge branch
'irq-core-for-linus' of
git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
git bisect good 2a1ccd31420a7b1acd6ca37b2bec2d723aa093e4
# good: [ab2486a9ee3243c8342549f58a13cdfa9abb497a] Merge branch
'x86-fpu-for-linus' of
git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
git bisect good ab2486a9ee3243c8342549f58a13cdfa9abb497a
# bad: [2f0f6503e37551eb8d8d5e4d27c78d28a30fed5a] Merge branch
'x86-timers-for-linus' of
git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
git bisect bad 2f0f6503e37551eb8d8d5e4d27c78d28a30fed5a
# good: [fd329f276ecaad7a371d6f91b9bbea031d0c3440] x86/mtrr: Skip
cache flushes on CPUs with cache self-snooping
git bisect good fd329f276ecaad7a371d6f91b9bbea031d0c3440
# bad: [e37f0881e9d9ec8b12f242cc2b78d93259aa7f0f] x86/hpet: Introduce
struct hpet_base and struct hpet_channel
git bisect bad e37f0881e9d9ec8b12f242cc2b78d93259aa7f0f
# good: [8c273f2c81f0756f65b24771196c0eff7ac90e7b] x86/hpet: Move
static and global variables to one place
git bisect good 8c273f2c81f0756f65b24771196c0eff7ac90e7b
# bad: [3535aa12f7f26fc755514b13aee8fac15741267e] x86/hpet:
Decapitalize and rename EVT_TO_HPET_DEV
git bisect bad 3535aa12f7f26fc755514b13aee8fac15741267e
# bad: [3222daf970f30133cc4c639cbecdc29c4ae91b2b] x86/hpet: Separate
counter check out of clocksource register code
git bisect bad 3222daf970f30133cc4c639cbecdc29c4ae91b2b
# good: [6bdec41a0cbcbda35c9044915fc8f45503a595a0] x86/hpet: Shuffle
code around for readability sake
git bisect good 6bdec41a0cbcbda35c9044915fc8f45503a595a0
# first bad commit: [3222daf970f30133cc4c639cbecdc29c4ae91b2b]
x86/hpet: Separate counter check out of clocksource register code
I haven't tried reverting this commit and recompiling (it's already
past 1:00 here, need to sleep), but I'll try it tomorrow, if required.
Note that on this machine (i945G) the HPET is disabled at boot and is
forcefully enabled by the kernel…
[ 0.147527] pci 0000:00:1f.0: Force enabled HPET at 0xfed00000
… and the commit message reads…
"The init code checks whether the HPET counter works late in the init
function when the clocksource is registered. That should happen right
with the other sanity checks."
… maybe now the check is happening a bit too early…?
Thanks,
Rui
Rui,
On Thu, 25 Jul 2019, Rui Salvaterra wrote:
> Looks like we have a winner. Actually, I did a full bisection between
> 5.2 and 5.3-rc1. Full log follows:
>
> git bisect start
> # good: [0ecfebd2b52404ae0c54a878c872bb93363ada36] Linux 5.2
> git bisect good 0ecfebd2b52404ae0c54a878c872bb93363ada36
>
> # first bad commit: [3222daf970f30133cc4c639cbecdc29c4ae91b2b]
> x86/hpet: Separate counter check out of clocksource register code
>
> I haven't tried reverting this commit and recompiling (it's already
'Revert' on top of Linus tree below.
> past 1:00 here, need to sleep), but I'll try it tomorrow, if required.
> Note that on this machine (i945G) the HPET is disabled at boot and is
> forcefully enabled by the kernel…
> [ 0.147527] pci 0000:00:1f.0: Force enabled HPET at 0xfed00000
Ok.
> … and the commit message reads…
>
> "The init code checks whether the HPET counter works late in the init
> function when the clocksource is registered. That should happen right
> with the other sanity checks."
>
> … maybe now the check is happening a bit too early…?
The only reason I can think of is that the HPET on that machine has a weird
register state (it's not advertised by the BIOS ... )
But that does not explain the boot failure completely. If the HPET is not
available then the kernel should automatically do the right thing and fall
back to something else.
Can you please provide the output of:
cat /sys/devices/system/clocksource/clocksource0/available_clocksource
and
cat /sys/devices/system/clocksource/clocksource0/current_clocksource
from a successful boot with 5.2 and 5.3 head with the 'fix' applied?
Then boot these kernels with 'hpet=disable' on the command line and see
whether they come up. If so please provide the same output.
The dmesg output of each boot would be useful as well.
Thanks,
tglx
8<--------------------
--- a/arch/x86/kernel/hpet.c
+++ b/arch/x86/kernel/hpet.c
@@ -827,10 +827,6 @@ int __init hpet_enable(void)
if (!hpet_cfg_working())
goto out_nohpet;
- /* Validate that the counter is counting */
- if (!hpet_counting())
- goto out_nohpet;
-
/*
* Read the period and check for a sane value:
*/
@@ -896,6 +892,14 @@ int __init hpet_enable(void)
}
hpet_print_config();
+ /*
+ * Validate that the counter is counting. This needs to be done
+ * after sanitizing the config registers to properly deal with
+ * force enabled HPETs.
+ */
+ if (!hpet_counting())
+ goto out_nohpet;
+
clocksource_register_hz(&clocksource_hpet, (u32)hpet_freq);
if (id & HPET_ID_LEGSUP) {
Hi again, Thomas,
On Thu, 25 Jul 2019 at 07:28, Thomas Gleixner <[email protected]> wrote:
>
> The only reason I can think of is that the HPET on that machine has a weird
> register state (it's not advertised by the BIOS ... )
>
> But that does not explain the boot failure completely. If the HPET is not
> available then the kernel should automatically do the right thing and fall
> back to something else.
This may be a useful data point, the relevant part of the dmesg on a
pristine 5.3-rc1 with clocksource=jiffies:
[ 0.028964] clocksource: refined-jiffies: mask: 0xffffffff
max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[ 0.113537] clocksource: tsc-early: mask: 0xffffffffffffffff
max_cycles: 0x30e24b1e83d, max_idle_ns: 440795362670 ns
[ 0.127048] clocksource: jiffies: mask: 0xffffffff max_cycles:
0xffffffff, max_idle_ns: 19112604462750000 ns
[ 0.175604] clocksource: hpet: mask: 0xffffffff max_cycles:
0xffffffff, max_idle_ns: 133484882848 ns
[ 0.185029] clocksource: acpi_pm: mask: 0xffffff max_cycles:
0xffffff, max_idle_ns: 2085701024 ns
[ 1.123548] clocksource: timekeeping watchdog on CPU1: Marking
clocksource 'tsc-early' as unstable because the skew is too large:
[ 1.123552] clocksource: 'hpet' wd_now: 33
wd_last: 33 mask: ffffffff
[ 1.123554] clocksource: 'tsc-early' cs_now:
922361204 cs_last: 8bc8d8390 mask: ffffffffffffffff
[ 1.123556] tsc: Marking TSC unstable due to clocksource watchdog
available_clocksource: hpet acpi_pm refined-jiffies jiffies
current_clocksource: jiffies
> Can you please provide the output of:
>
> cat /sys/devices/system/clocksource/clocksource0/available_clocksource
> and
> cat /sys/devices/system/clocksource/clocksource0/current_clocksource
>
> from a successful boot with 5.2 and 5.3 head with the 'fix' applied?
Here we go…
Linux 5.2:
available_clocksource: tsc hpet acpi_pm
current_clocksource: tsc
Linux 5.3-rc1 patched:
available_clocksource: tsc hpet acpi_pm
current_clocksource: tsc
> Then boot these kernels with 'hpet=disable' on the command line and see
> whether they come up. If so please provide the same output.
Fortunately (as I'm doing this remotely) they did come up.
With hpet=disabled…
Linux 5.2:
available_clocksource: tsc acpi_pm
current_clocksource: tsc
Linux 5.3-rc1 patched:
available_clocksource: tsc acpi_pm
current_clocksource: tsc
> The dmesg output of each boot would be useful as well.
Attached is the dmesg output of each case.
Thanks,
Rui
Commit-ID: 643d83f0a3518d6fbcf88f970de0340a5aa6b5a2
Gitweb: https://git.kernel.org/tip/643d83f0a3518d6fbcf88f970de0340a5aa6b5a2
Author: Thomas Gleixner <[email protected]>
AuthorDate: Thu, 25 Jul 2019 08:28:45 +0200
Committer: Thomas Gleixner <[email protected]>
CommitDate: Thu, 25 Jul 2019 12:21:32 +0200
x86/hpet: Undo the early counter is counting check
Rui reported that on a Pentium D machine which has HPET forced enabled
because it is not advertised by ACPI, the early counter is counting check
leads to a silent boot hang.
The reason is that the ordering of checking the counter first and then
reconfiguring the HPET fails to work on that machine. As the HPET is not
advertised and presumably not initialized by the BIOS the early enable and
the following reconfiguration seems to bring it into a broken state. Adding
clocksource=jiffies to the command line results in the following
clocksource watchdog warning:
clocksource: timekeeping watchdog on CPU1:
Marking clocksource 'tsc-early' as unstable because the skew is too large:
clocksource: 'hpet' wd_now: 33 wd_last: 33 mask: ffffffff
That clearly shows that the HPET is not counting after it got reconfigured
and reenabled. If the counter is not working then the HPET timer is not
expiring either, which explains the boot hang.
Move the counter is counting check after the full configuration again to
unbreak these systems.
Reported-by: Rui Salvaterra <[email protected]>
Fixes: 3222daf970f3 ("x86/hpet: Separate counter check out of clocksource register code")
Signed-off-by: Thomas Gleixner <[email protected]>
Tested-by: Rui Salvaterra <[email protected]>
Link: https://lkml.kernel.org/r/[email protected]
---
arch/x86/kernel/hpet.c | 12 ++++++++----
1 file changed, 8 insertions(+), 4 deletions(-)
diff --git a/arch/x86/kernel/hpet.c b/arch/x86/kernel/hpet.c
index c43e96a938d0..c6f791bc481e 100644
--- a/arch/x86/kernel/hpet.c
+++ b/arch/x86/kernel/hpet.c
@@ -827,10 +827,6 @@ int __init hpet_enable(void)
if (!hpet_cfg_working())
goto out_nohpet;
- /* Validate that the counter is counting */
- if (!hpet_counting())
- goto out_nohpet;
-
/*
* Read the period and check for a sane value:
*/
@@ -896,6 +892,14 @@ int __init hpet_enable(void)
}
hpet_print_config();
+ /*
+ * Validate that the counter is counting. This needs to be done
+ * after sanitizing the config registers to properly deal with
+ * force enabled HPETs.
+ */
+ if (!hpet_counting())
+ goto out_nohpet;
+
clocksource_register_hz(&clocksource_hpet, (u32)hpet_freq);
if (id & HPET_ID_LEGSUP) {
Rui,
On Thu, 25 Jul 2019, Rui Salvaterra wrote:
> On Thu, 25 Jul 2019 at 07:28, Thomas Gleixner <[email protected]> wrote:
> >
> > The only reason I can think of is that the HPET on that machine has a weird
> > register state (it's not advertised by the BIOS ... )
> >
> > But that does not explain the boot failure completely. If the HPET is not
> > available then the kernel should automatically do the right thing and fall
> > back to something else.
>
> This may be a useful data point, the relevant part of the dmesg on a
> pristine 5.3-rc1 with clocksource=jiffies:
Duh. Yes, this explains it nicely.
> [ 1.123548] clocksource: timekeeping watchdog on CPU1: Marking
> clocksource 'tsc-early' as unstable because the skew is too large:
> [ 1.123552] clocksource: 'hpet' wd_now: 33
> wd_last: 33 mask: ffffffff
The HPET counter check succeeded, but the early enable and the following
reconfiguration confused it completely. So the HPET is not counting:
'hpet' wd_now: 33 wd_last: 33 mask: ffffffff
Which is a full explanation for the boot fail because if the counter is not
working then the HPET timer is not expiring and the early boot is waiting
for HPET to fire forever.
> > Then boot these kernels with 'hpet=disable' on the command line and see
> > whether they come up. If so please provide the same output.
>
> Fortunately (as I'm doing this remotely) they did come up.
> With hpet=disabled…
>
> Linux 5.2:
> available_clocksource: tsc acpi_pm
> current_clocksource: tsc
>
> Linux 5.3-rc1 patched:
> available_clocksource: tsc acpi_pm
> current_clocksource: tsc
That's consistent with the above. 5.3-rc1 unpatched would of course boot as
well with hpet=disable now that we know the root cause.
I'll write a changelog and route it to Linus for -rc2.
Thanks a lot for debugging this and providing all the information!
tglx
Hi, Thomas,
On Thu, 25 Jul 2019 at 10:37, Thomas Gleixner <[email protected]> wrote:
>
> Duh. Yes, this explains it nicely.
>
> > [ 1.123548] clocksource: timekeeping watchdog on CPU1: Marking
> > clocksource 'tsc-early' as unstable because the skew is too large:
> > [ 1.123552] clocksource: 'hpet' wd_now: 33
> > wd_last: 33 mask: ffffffff
>
> The HPET counter check succeeded, but the early enable and the following
> reconfiguration confused it completely. So the HPET is not counting:
>
> 'hpet' wd_now: 33 wd_last: 33 mask: ffffffff
>
> Which is a full explanation for the boot fail because if the counter is not
> working then the HPET timer is not expiring and the early boot is waiting
> for HPET to fire forever.
Interesting. Thanks for the detailed explanation!
> That's consistent with the above. 5.3-rc1 unpatched would of course boot as
> well with hpet=disable now that we know the root cause.
I guess that's the only thing I hadn't tried, hindsight is 20/20. :)
> I'll write a changelog and route it to Linus for -rc2.
>
> Thanks a lot for debugging this and providing all the information!
My pleasure! I'm glad to have this old workhorse chugging along again.
Thanks,
Rui