"BUG: using smp_processor_id() in preemptible" on resume from S3

"BUG: using smp_processor_id() in preemptible" on resume from S3

[Marek Marczykowski-Górecki]

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

Hi,

After updating from 5.14.15 dom0 kernel to 5.16.13 I started getting
this on resume from S3:

[   88.082751] ACPI: PM: Low-level resume complete
[   88.087933] ACPI: EC: EC started
[   88.091464] ACPI: PM: Restoring platform NVS memory
[   88.097166] xen_acpi_processor: Uploading Xen processor PM info
[   88.103850] Enabling non-boot CPUs ...
[   88.108128] installing Xen timer for CPU 1
[   88.112763] BUG: using smp_processor_id() in preemptible [00000000] code: systemd-sleep/7138
[   88.122256] caller is is_xen_pmu+0x12/0x30
[   88.126937] CPU: 0 PID: 7138 Comm: systemd-sleep Tainted: G        W         5.16.13-2.fc32.qubes.x86_64 #1
[   88.137939] Hardware name: Star Labs StarBook/StarBook, BIOS 7.97 03/21/2022
[   88.145930] Call Trace:
[   88.148757]  <TASK>
[   88.151193]  dump_stack_lvl+0x48/0x5e
[   88.155381]  check_preemption_disabled+0xde/0xe0
[   88.160641]  is_xen_pmu+0x12/0x30
[   88.164441]  xen_smp_intr_init_pv+0x75/0x100
[   88.169311]  ? xen_read_cr0+0x20/0x20
[   88.173502]  xen_cpu_up_prepare_pv+0x3e/0x90
[   88.178374]  cpuhp_invoke_callback+0x2b8/0x460
[   88.183440]  ? _raw_spin_unlock_irqrestore+0x25/0x40
[   88.189093]  cpuhp_up_callbacks+0x4b/0x170
[   88.193769]  _cpu_up+0xba/0x140
[   88.197374]  thaw_secondary_cpus.cold+0x50/0xaa
[   88.202538]  suspend_enter+0x11e/0x3b0
[   88.206825]  suspend_devices_and_enter+0x165/0x270
[   88.212281]  enter_state+0x125/0x176
[   88.216372]  pm_suspend.cold+0x20/0x6b
[   88.220658]  state_store+0x27/0x50
[   88.224557]  kernfs_fop_write_iter+0x121/0x1b0
[   88.229621]  new_sync_write+0x159/0x1f0
[   88.234006]  vfs_write+0x20d/0x2a0
[   88.237904]  ksys_write+0x67/0xe0
[   88.241703]  do_syscall_64+0x38/0x90
[   88.245797]  entry_SYSCALL_64_after_hwframe+0x44/0xae
[   88.251544] RIP: 0033:0x7eae453da2f7
[   88.255637] Code: 0d 00 f7 d8 64 89 02 48 c7 c0 ff ff ff ff eb b7 0f 1f 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 01 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 51 c3 48 83 ec 28 48 89 54 24 18 48 89 74 24
[   88.276779] RSP: 002b:00007ffcbc7d05e8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[   88.285353] RAX: ffffffffffffffda RBX: 0000000000000004 RCX: 00007eae453da2f7
[   88.293438] RDX: 0000000000000004 RSI: 00007ffcbc7d06d0 RDI: 0000000000000004
[   88.301525] RBP: 00007ffcbc7d06d0 R08: 00005be912db7c00 R09: 000000000000000d
[   88.309613] R10: 00005be912db3e10 R11: 0000000000000246 R12: 0000000000000004
[   88.317699] R13: 00005be912db32d0 R14: 0000000000000004 R15: 00007eae454ac700
[   88.325787]  </TASK>
[   88.328711] cpu 1 spinlock event irq 131
[   88.333188] ACPI: \_SB_.CP01: Found 3 idle states
[   88.338833] CPU1 is up

and so on for all CPUs. 

In recent changes I see e25a8d959992 "x86/Xen: streamline (and fix) PV
CPU enumeration", which was backported to 5.16.11, although that's just
a hunch.

Any ideas? If necessary, I can run bisect to find specific commit, but I
hope the above message gives enough hints.

-- 
Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: "BUG: using smp_processor_id() in preemptible" on resume from S3

[Juergen Gross]

[-- Attachment #1.1.1: Type: text/plain, Size: 1286 bytes --]

Hi Marek,

On 21.03.22 23:26, Marek Marczykowski-Górecki wrote:
> Hi,
> 
> After updating from 5.14.15 dom0 kernel to 5.16.13 I started getting
> this on resume from S3:
> 
> [   88.082751] ACPI: PM: Low-level resume complete
> [   88.087933] ACPI: EC: EC started
> [   88.091464] ACPI: PM: Restoring platform NVS memory
> [   88.097166] xen_acpi_processor: Uploading Xen processor PM info
> [   88.103850] Enabling non-boot CPUs ...
> [   88.108128] installing Xen timer for CPU 1
> [   88.112763] BUG: using smp_processor_id() in preemptible [00000000] code: systemd-sleep/7138
> [   88.122256] caller is is_xen_pmu+0x12/0x30
> [   88.126937] CPU: 0 PID: 7138 Comm: systemd-sleep Tainted: G        W         5.16.13-2.fc32.qubes.x86_64 #1
> [   88.137939] Hardware name: Star Labs StarBook/StarBook, BIOS 7.97 03/21/2022
> [   88.145930] Call Trace:
> [   88.148757]  <TASK>
> [   88.151193]  dump_stack_lvl+0x48/0x5e
> [   88.155381]  check_preemption_disabled+0xde/0xe0
> [   88.160641]  is_xen_pmu+0x12/0x30
> [   88.164441]  xen_smp_intr_init_pv+0x75/0x100
> [   88.169311]  ? xen_read_cr0+0x20/0x20
> [   88.173502]  xen_cpu_up_prepare_pv+0x3e/0x90

Thanks for the report.

Could you please test whether the attached patch is helping?


Juergen

[-- Attachment #1.1.2: 0001-xen-fix-is_xen_pmu.patch --]
[-- Type: text/x-patch, Size: 4754 bytes --]

From 52d3e1a690e4eff152b8aeb8df4c99e3f40f296c Mon Sep 17 00:00:00 2001
From: Juergen Gross <jgross@suse.com>
To: x86@kernel.org
To: linux-kernel@vger.kernel.org
Cc: Boris Ostrovsky <boris.ostrovsky@oracle.com>
Cc: Juergen Gross <jgross@suse.com>
Cc: Stefano Stabellini <sstabellini@kernel.org>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Borislav Petkov <bp@alien8.de>
Cc: Dave Hansen <dave.hansen@linux.intel.com>
Cc: "H. Peter Anvin" <hpa@zytor.com>
Cc: xen-devel@lists.xenproject.org
Date: Tue, 22 Mar 2022 07:35:14 +0100
Subject: [PATCH] xen: fix is_xen_pmu()
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

is_xen_pmu() is taking the cpu number as parameter, but it is not using
it. Instead it just tests whether the Xen PMU initialization on the
current cpu did succeed. As this test is done by checking a percpu
pointer, preemption needs to be disabled in order to avoid switching
the cpu while doing the test. While resuming from suspend() this seems
not to be the case:

[   88.082751] ACPI: PM: Low-level resume complete
[   88.087933] ACPI: EC: EC started
[   88.091464] ACPI: PM: Restoring platform NVS memory
[   88.097166] xen_acpi_processor: Uploading Xen processor PM info
[   88.103850] Enabling non-boot CPUs ...
[   88.108128] installing Xen timer for CPU 1
[   88.112763] BUG: using smp_processor_id() in preemptible [00000000] code: systemd-sleep/7138
[   88.122256] caller is is_xen_pmu+0x12/0x30
[   88.126937] CPU: 0 PID: 7138 Comm: systemd-sleep Tainted: G        W         5.16.13-2.fc32.qubes.x86_64 #1
[   88.137939] Hardware name: Star Labs StarBook/StarBook, BIOS 7.97 03/21/2022
[   88.145930] Call Trace:
[   88.148757]  <TASK>
[   88.151193]  dump_stack_lvl+0x48/0x5e
[   88.155381]  check_preemption_disabled+0xde/0xe0
[   88.160641]  is_xen_pmu+0x12/0x30
[   88.164441]  xen_smp_intr_init_pv+0x75/0x100

Fix that by replacing is_xen_pmu() by a simple boolean variable which
reflects the Xen PMU initialization state on cpu 0.

Modify xen_pmu_init() to return early in case it is being called for a
cpu other than cpu 0 and the boolean variable not being set.

Fixes: bf6dfb154d93 ("xen/PMU: PMU emulation code")
Reported-by: Marek Marczykowski-Górecki <marmarek@invisiblethingslab.com>
Signed-off-by: Juergen Gross <jgross@suse.com>
---
 arch/x86/xen/pmu.c    | 11 ++++++-----
 arch/x86/xen/pmu.h    |  3 ++-
 arch/x86/xen/smp_pv.c |  2 +-
 3 files changed, 9 insertions(+), 7 deletions(-)

diff --git a/arch/x86/xen/pmu.c b/arch/x86/xen/pmu.c
index 89dd6b1708b0..0efe452eb13e 100644
--- a/arch/x86/xen/pmu.c
+++ b/arch/x86/xen/pmu.c
@@ -506,10 +506,7 @@ irqreturn_t xen_pmu_irq_handler(int irq, void *dev_id)
 	return ret;
 }
 
-bool is_xen_pmu(int cpu)
-{
-	return (get_xenpmu_data() != NULL);
-}
+bool is_xen_pmu;
 
 void xen_pmu_init(int cpu)
 {
@@ -520,7 +517,7 @@ void xen_pmu_init(int cpu)
 
 	BUILD_BUG_ON(sizeof(struct xen_pmu_data) > PAGE_SIZE);
 
-	if (xen_hvm_domain())
+	if (xen_hvm_domain() || (cpu != 0 && !is_xen_pmu))
 		return;
 
 	xenpmu_data = (struct xen_pmu_data *)get_zeroed_page(GFP_KERNEL);
@@ -542,6 +539,7 @@ void xen_pmu_init(int cpu)
 	per_cpu(xenpmu_shared, cpu).flags = 0;
 
 	if (cpu == 0) {
+		is_xen_pmu = true;
 		perf_register_guest_info_callbacks(&xen_guest_cbs);
 		xen_pmu_arch_init();
 	}
@@ -572,4 +570,7 @@ void xen_pmu_finish(int cpu)
 
 	free_pages((unsigned long)per_cpu(xenpmu_shared, cpu).xenpmu_data, 0);
 	per_cpu(xenpmu_shared, cpu).xenpmu_data = NULL;
+
+	if (cpu == 0)
+		is_xen_pmu = false;
 }
diff --git a/arch/x86/xen/pmu.h b/arch/x86/xen/pmu.h
index 0e83a160589b..65c58894fc79 100644
--- a/arch/x86/xen/pmu.h
+++ b/arch/x86/xen/pmu.h
@@ -4,6 +4,8 @@
 
 #include <xen/interface/xenpmu.h>
 
+extern bool is_xen_pmu;
+
 irqreturn_t xen_pmu_irq_handler(int irq, void *dev_id);
 #ifdef CONFIG_XEN_HAVE_VPMU
 void xen_pmu_init(int cpu);
@@ -12,7 +14,6 @@ void xen_pmu_finish(int cpu);
 static inline void xen_pmu_init(int cpu) {}
 static inline void xen_pmu_finish(int cpu) {}
 #endif
-bool is_xen_pmu(int cpu);
 bool pmu_msr_read(unsigned int msr, uint64_t *val, int *err);
 bool pmu_msr_write(unsigned int msr, uint32_t low, uint32_t high, int *err);
 int pmu_apic_update(uint32_t reg);
diff --git a/arch/x86/xen/smp_pv.c b/arch/x86/xen/smp_pv.c
index 4a6019238ee7..688aa8b6ae29 100644
--- a/arch/x86/xen/smp_pv.c
+++ b/arch/x86/xen/smp_pv.c
@@ -129,7 +129,7 @@ int xen_smp_intr_init_pv(unsigned int cpu)
 	per_cpu(xen_irq_work, cpu).irq = rc;
 	per_cpu(xen_irq_work, cpu).name = callfunc_name;
 
-	if (is_xen_pmu(cpu)) {
+	if (is_xen_pmu) {
 		pmu_name = kasprintf(GFP_KERNEL, "pmu%d", cpu);
 		rc = bind_virq_to_irqhandler(VIRQ_XENPMU, cpu,
 					     xen_pmu_irq_handler,
-- 
2.34.1


[-- Attachment #1.1.3: OpenPGP public key --]
[-- Type: application/pgp-keys, Size: 3149 bytes --]

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 495 bytes --]

Re: "BUG: using smp_processor_id() in preemptible" on resume from S3

[Marek Marczykowski-Górecki]

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

On Tue, Mar 22, 2022 at 08:12:53AM +0100, Juergen Gross wrote:
> Hi Marek,
> 
> On 21.03.22 23:26, Marek Marczykowski-Górecki wrote:
> > Hi,
> > 
> > After updating from 5.14.15 dom0 kernel to 5.16.13 I started getting
> > this on resume from S3:
> > 
> > [   88.082751] ACPI: PM: Low-level resume complete
> > [   88.087933] ACPI: EC: EC started
> > [   88.091464] ACPI: PM: Restoring platform NVS memory
> > [   88.097166] xen_acpi_processor: Uploading Xen processor PM info
> > [   88.103850] Enabling non-boot CPUs ...
> > [   88.108128] installing Xen timer for CPU 1
> > [   88.112763] BUG: using smp_processor_id() in preemptible [00000000] code: systemd-sleep/7138
> > [   88.122256] caller is is_xen_pmu+0x12/0x30
> > [   88.126937] CPU: 0 PID: 7138 Comm: systemd-sleep Tainted: G        W         5.16.13-2.fc32.qubes.x86_64 #1
> > [   88.137939] Hardware name: Star Labs StarBook/StarBook, BIOS 7.97 03/21/2022
> > [   88.145930] Call Trace:
> > [   88.148757]  <TASK>
> > [   88.151193]  dump_stack_lvl+0x48/0x5e
> > [   88.155381]  check_preemption_disabled+0xde/0xe0
> > [   88.160641]  is_xen_pmu+0x12/0x30
> > [   88.164441]  xen_smp_intr_init_pv+0x75/0x100
> > [   88.169311]  ? xen_read_cr0+0x20/0x20
> > [   88.173502]  xen_cpu_up_prepare_pv+0x3e/0x90
> 
> Thanks for the report.
> 
> Could you please test whether the attached patch is helping?

Yes, that helps, thanks!

-- 
Best Regards,
Marek Marczykowski-Górecki
Invisible Things Lab

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]