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