Date:   Fri, 21 May 2021 16:11:22 -0600
From:   James Feeney <james@...ealm.net>
To:     Borislav Petkov <bp@...e.de>
Cc:     linux-smp@...r.kernel.org, Jens Axboe <axboe@...nel.dk>,
        lkml <linux-kernel@...r.kernel.org>
Subject: Re: linux 5.12 - fails to boot - soft lockup - CPU#0 stuck for 23s! -
 RIP smp_call_function_single

On 5/20/21 3:21 AM, Borislav Petkov wrote:
> On Wed, May 19, 2021 at 09:12:04PM -0600, James Feeney wrote:
> 
>> $ diff .config .config.old
>> 4983c4983,4984
>> < # CONFIG_X86_THERMAL_VECTOR is not set
>> ---
>>> CONFIG_X86_THERMAL_VECTOR=y
>>> CONFIG_X86_PKG_TEMP_THERMAL=m
>>
>> No joy. Still have the same soft lockups and full boots - the full
>> boots interrupted by some mystery delay.
> 
> Which means, even with therm_throt disabled, it still locks up. Which
> can't be caused by my patch.
> 
>> I don't know about these patches, modifying and moving the location of
>> therm_throt.c, so I'm not in a position to draw any conclusion from
>> these results.
> 
> They're just moving the thermal interrupt functionality from the
> MCE code where they don't belong to the thermal code where they do.
> Otherwise there should be no change.
> 
>> build 5.11? There are lots of 5.11 kernels from the Arch distribution
>> that I have run. Are you looking for a dmesg log from 5.11?
> 
> Take the .config you're normally using, make sure it has
> 
> CONFIG_X86_THERMAL_VECTOR=y
> 
> and build with it plain 5.11 kernel. No patches ontop, no nothing.
> 
> Then add
> 
> debug ignore_loglevel log_buf_len=16M no_console_suspend systemd.log_target=null console=ttyS0,115200 console=tty0
> 
> to its kernel command line and send me full dmesg again pls.
> 

Hmm - for comparison, I'm attaching the full dmesg log for the 7bb39313cd62 build, the one in the git bisect immediately prior to your patch.

dmesglog.7bb39313cd62.full


> Looking how it sometimes boots and sometimes it locks up, try that a
> couple of times.
> 

There are *no* 5.11 builds that lock-up.

>> So far, something looks quirky - somewhere. Timing related failures
>> can be a pain. Is there no useful information being provided by the
>> Call Trace in the dmesg log?
> 
> What I'm seeing is that *sometimes* - not always - your CPU0 is not
> responding to the TLB flush IPI. Which is really weird. Have you had
> those always or did they start appearing with 5.12?
> 

This all started with the 5.12 kernels, on this machine - never before.

> That's why I'm still scratching my head over how my patch would cause
> CPU0 not responding to IPIs.
> 
> Well, *maybe* there's a little difference which my patch did: it does
> that APIC_LVTTHMR only on the BSP. And *maybe* there's a problem there,
> who knows with those old CPUs.
> 
> So here's two more things to try:
> 
> 1. On plain 5.12, with the same kernel cmdline params add also
> 
> "idle=nomwait"
> 
> to the kernel command line and boot with it a couple of times to see
> whether it still locks up.
> 

On the Arch 5.12.0 kernel with "CONFIG_X86_THERMAL_VECTOR is not set", on the first boot, as before, it just hangs at "Trying to unpack rootfs image as initramfs...".

On the Arch 5.12.0 kernel with "CONFIG_X86_THERMAL_VECTOR=y", I got a couple of full boots, and then repeating "soft lockup", same as before.  All in all, "idle=nomwait" makes no difference.

It seems significant that, *if* the system boots normally, then, from then on, it seems to run normally.  Maybe the issue is something at-play only during the early boot process.  Certainly, the issue seems to be at-play even before unpacking the rootfs, or maybe just after unpacking the rootfs.  This happens before whatever is able to generate the "watchdog: BUG: soft lockup - CPU#0 stuck for 23s! [systemd-udevd:242]".


> 2. On plain 5.12, with the same kernel cmdline params apply this hunk
> ontop:
> 
> ---
> diff --git a/drivers/thermal/intel/therm_throt.c b/drivers/thermal/intel/therm_throt.c
> index f8e882592ba5..42db48cd4666 100644
> --- a/drivers/thermal/intel/therm_throt.c
> +++ b/drivers/thermal/intel/therm_throt.c
> @@ -630,9 +630,8 @@ void intel_init_thermal(struct cpuinfo_x86 *c)
>  	if (!intel_thermal_supported(c))
>  		return;
>  
> -	/* On the BSP? */
> -	if (c == &boot_cpu_data)
> -		lvtthmr_init = apic_read(APIC_LVTTHMR);
> +	lvtthmr_init = apic_read(APIC_LVTTHMR);
> +	pr_info("%s: CPU%d, lvtthmr_init: 0x%x\n", __func__, cpu, lvtthmr_init);
>  
>  	/*
>  	 * First check if its enabled already, in which case there might
> ---
> 
> That'll tell us the thermal sensor LVT on both CPUs.
> 
> Also do that a couple of times - it'll be interesting to see what those
> values are *when* the box locks up.
> 
> As always, catch full dmesg each time pls.
> 
> Thx.
> 

$ diff .config .config.old
4983,4984c4983
< CONFIG_X86_THERMAL_VECTOR=y
< CONFIG_X86_PKG_TEMP_THERMAL=m
---
> # CONFIG_X86_THERMAL_VECTOR is not set

It seems odd, that making one small change to the .config, results in the entire kernel being recompiled.  Is there a way to avoid that?

Hmm - this version may be interesting.  There are inconsistencies, in the sense of various different boot results, in 10 sequential boot events.  The dmesg logs are attached.


$ tail -n3 dmesglog.5.12.lvtthmr.*       
==> dmesglog.5.12.lvtthmr.1 <==
[    3.755697] pci 0000:01:00.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff]
[    3.764074] PCI: CLS 64 bytes, default 64
[    3.768186] Trying to unpack rootfs image as initramfs...

==> dmesglog.5.12.lvtthmr.10 <==
[  147.270555] ACPI: Preparing to enter system sleep state S5
[  147.278663] reboot: Power down
[  147.284389] acpi_power_off called

==> dmesglog.5.12.lvtthmr.2 <==
[    3.758020] pci 0000:01:00.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff]
[    3.766394] PCI: CLS 64 bytes, default 64
[    3.770507] Trying to unpack rootfs image as initramfs...

==> dmesglog.5.12.lvtthmr.3 <==
[    1.622582] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
[    1.629249] ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics)
[    1.645854] ACPI: 6 ACPI AML tables successfully acquired and loaded

==> dmesglog.5.12.lvtthmr.4 <==
[  501.491752] ACPI: Preparing to enter system sleep state S5
[  501.499967] reboot: Power down
[  501.505786] acpi_power_off called

==> dmesglog.5.12.lvtthmr.5 <==
[  225.055556] ACPI: Preparing to enter system sleep state S5
[  225.063645] reboot: Power down
[  225.069318] acpi_power_off called

==> dmesglog.5.12.lvtthmr.6 <==
[  150.364732] ACPI: Preparing to enter system sleep state S5
[  150.373028] reboot: Power down
[  150.378965] acpi_power_off called

==> dmesglog.5.12.lvtthmr.7 <==
[  140.049778] ACPI: Preparing to enter system sleep state S5
[  140.057886] reboot: Power down
[  140.063536] acpi_power_off called

==> dmesglog.5.12.lvtthmr.8 <==
[    1.623091] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
[    1.629757] ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics)
[    1.646421] ACPI: 6 ACPI AML tables successfully acquired and loaded

==> dmesglog.5.12.lvtthmr.9 <==
[  124.813366] ACPI: Preparing to enter system sleep state S5
[  124.821411] reboot: Power down
[  124.827059] acpi_power_off called

6 of the 10 are full boot, ending with acpi_power_off called.  2 of 10 end at "Trying to unpack rootfs image as initramfs...", and - this is new - boot 3 and 8 do not make it that far, ending after "ACPI: 6 ACPI AML tables successfully acquired and loaded".  "ACPI: Dynamic OEM Table Load:" would have been next, after "ACPI: 6 ACPI AML tables successfully acquired and loaded".

Of note, *none* of these 10 boot events generated the "soft lockup" Stack Trace events.  Also of note, even though boot number 4 is a full boot, there is a 73 second mystery delay.  The delay occurs right after adding swap, and just before "Bluetooth: BNEP".  Boot 4 has other unique characteristics, mentioned below.


$ grep lvtth dmesglog.5.12.lvtthmr.*
dmesglog.5.12.lvtthmr.1:[    1.246282] intel_init_thermal: CPU0, lvtthmr_init: 0x10200
dmesglog.5.12.lvtthmr.1:[    0.933178] intel_init_thermal: CPU1, lvtthmr_init: 0x10000
dmesglog.5.12.lvtthmr.10:[    1.245288] intel_init_thermal: CPU0, lvtthmr_init: 0x10200
dmesglog.5.12.lvtthmr.10:[    0.933148] intel_init_thermal: CPU1, lvtthmr_init: 0x10000
dmesglog.5.12.lvtthmr.2:[    1.245260] intel_init_thermal: CPU0, lvtthmr_init: 0x10200
dmesglog.5.12.lvtthmr.2:[    0.933118] intel_init_thermal: CPU1, lvtthmr_init: 0x10000
dmesglog.5.12.lvtthmr.3:[    1.245958] intel_init_thermal: CPU0, lvtthmr_init: 0x10200
dmesglog.5.12.lvtthmr.3:[    0.933159] intel_init_thermal: CPU1, lvtthmr_init: 0x10000
dmesglog.5.12.lvtthmr.4:[    1.247200] intel_init_thermal: CPU0, lvtthmr_init: 0x10200
dmesglog.5.12.lvtthmr.5:[    1.246849] intel_init_thermal: CPU0, lvtthmr_init: 0x10200
dmesglog.5.12.lvtthmr.5:[    0.933187] intel_init_thermal: CPU1, lvtthmr_init: 0x10000
dmesglog.5.12.lvtthmr.6:[    1.246143] intel_init_thermal: CPU0, lvtthmr_init: 0x10200
dmesglog.5.12.lvtthmr.6:[    0.933146] intel_init_thermal: CPU1, lvtthmr_init: 0x10000
dmesglog.5.12.lvtthmr.7:[    1.246826] intel_init_thermal: CPU0, lvtthmr_init: 0x10200
dmesglog.5.12.lvtthmr.7:[    0.932840] intel_init_thermal: CPU1, lvtthmr_init: 0x10000
dmesglog.5.12.lvtthmr.8:[    1.246467] intel_init_thermal: CPU0, lvtthmr_init: 0x10200
dmesglog.5.12.lvtthmr.8:[    0.933189] intel_init_thermal: CPU1, lvtthmr_init: 0x10000
dmesglog.5.12.lvtthmr.9:[    1.246288] intel_init_thermal: CPU0, lvtthmr_init: 0x10200
dmesglog.5.12.lvtthmr.9:[    0.933210] intel_init_thermal: CPU1, lvtthmr_init: 0x10000

Note that boot number 4 is unique, in that "intel_init_thermal: CPU1, lvtthmr_init: 0x10000" is never seen.


$ grep -i monitor dmesglog.5.12.lvtthmr.*
dmesglog.5.12.lvtthmr.1:[    0.933178] CPU0: Thermal monitoring enabled (TM2)
dmesglog.5.12.lvtthmr.10:[    0.933148] CPU0: Thermal monitoring enabled (TM2)
dmesglog.5.12.lvtthmr.10:[    4.152122] Monitor-Mwait will be used to enter C-1 state
dmesglog.5.12.lvtthmr.10:[    4.158004] Monitor-Mwait will be used to enter C-2 state
dmesglog.5.12.lvtthmr.10:[    8.106471] drop_monitor: Initializing network drop monitor service
dmesglog.5.12.lvtthmr.2:[    0.933118] CPU0: Thermal monitoring enabled (TM2)
dmesglog.5.12.lvtthmr.3:[    0.933159] CPU0: Thermal monitoring enabled (TM2)
dmesglog.5.12.lvtthmr.4:[   13.613968] Monitor-Mwait will be used to enter C-1 state
dmesglog.5.12.lvtthmr.4:[   13.619845] Monitor-Mwait will be used to enter C-2 state
dmesglog.5.12.lvtthmr.4:[   17.456124] drop_monitor: Initializing network drop monitor service
dmesglog.5.12.lvtthmr.5:[    0.933187] CPU0: Thermal monitoring enabled (TM2)
dmesglog.5.12.lvtthmr.5:[    4.157058] Monitor-Mwait will be used to enter C-1 state
dmesglog.5.12.lvtthmr.5:[    4.162940] Monitor-Mwait will be used to enter C-2 state
dmesglog.5.12.lvtthmr.5:[    8.170316] drop_monitor: Initializing network drop monitor service
dmesglog.5.12.lvtthmr.6:[    0.933146] CPU0: Thermal monitoring enabled (TM2)
dmesglog.5.12.lvtthmr.6:[    4.159566] Monitor-Mwait will be used to enter C-1 state
dmesglog.5.12.lvtthmr.6:[    4.165450] Monitor-Mwait will be used to enter C-2 state
dmesglog.5.12.lvtthmr.6:[    8.222319] drop_monitor: Initializing network drop monitor service
dmesglog.5.12.lvtthmr.7:[    0.932840] CPU0: Thermal monitoring enabled (TM2)
dmesglog.5.12.lvtthmr.7:[    4.158158] Monitor-Mwait will be used to enter C-1 state
dmesglog.5.12.lvtthmr.7:[    4.164046] Monitor-Mwait will be used to enter C-2 state
dmesglog.5.12.lvtthmr.7:[    8.263059] drop_monitor: Initializing network drop monitor service
dmesglog.5.12.lvtthmr.8:[    0.933189] CPU0: Thermal monitoring enabled (TM2)
dmesglog.5.12.lvtthmr.9:[    0.933210] CPU0: Thermal monitoring enabled (TM2)
dmesglog.5.12.lvtthmr.9:[    4.159696] Monitor-Mwait will be used to enter C-1 state
dmesglog.5.12.lvtthmr.9:[    4.165581] Monitor-Mwait will be used to enter C-2 state
dmesglog.5.12.lvtthmr.9:[    8.203103] drop_monitor: Initializing network drop monitor service

Again, boot number 4 is unique, in that "CPU0: Thermal monitoring enabled (TM2)" is never seen. On the abbreviated boot 3 and 8, "CPU0: Thermal monitoring enabled (TM2)" is still seen.

These varying results may indicate that some initialization step is being missed, resulting in random variation in the initial state.

James

View attachment "dmesglog.7bb39313cd62.full" of type "text/plain" (69108 bytes)

Download attachment "dmesglog.5.12.lvtthmr.1" of type "application/x-troff-man" (37903 bytes)

Download attachment "dmesglog.5.12.lvtthmr.2" of type "application/x-troff-man" (37903 bytes)

Download attachment "dmesglog.5.12.lvtthmr.3" of type "application/x-troff-man" (15316 bytes)

Download attachment "dmesglog.5.12.lvtthmr.4" of type "application/x-troff-man" (69282 bytes)

Download attachment "dmesglog.5.12.lvtthmr.5" of type "application/x-troff-man" (69806 bytes)

Download attachment "dmesglog.5.12.lvtthmr.6" of type "application/x-troff-man" (69778 bytes)

Download attachment "dmesglog.5.12.lvtthmr.7" of type "application/x-troff-man" (69732 bytes)

Download attachment "dmesglog.5.12.lvtthmr.8" of type "application/x-troff-man" (15316 bytes)

View attachment "dmesglog.5.12.lvtthmr.9" of type "text/plain" (69670 bytes)

View attachment "dmesglog.5.12.lvtthmr.10" of type "text/plain" (69699 bytes)

Powered by blists - more mailing lists