[PATCH] x86/irq: Use printk_deferred() on raw_spin_lock() protected sections

[PATCH] x86/irq: Use printk_deferred() on raw_spin_lock() protected sections

[Daniel Bristot de Oliveira]

While testing hotplug I got this BUG:

 =============================
 [ BUG: Invalid wait context ]
 5.9.0-rc5+ #3 Not tainted
 -----------------------------
 migration/2/20 is trying to lock:
 ffffffffb4315778 (&port->lock){-.-.}-{3:3}, at: serial8250_console_write+0x8e/0x380
 other info that might help us debug this:
 context-{5:5}
 4 locks held by migration/2/20:
  #0: ffff91622a3ff4c0 (&irq_desc_lock_class){-.-.}-{2:2}, at: irq_migrate_all_off_this_cpu+0x41/0x2f0
  #1: ffffffffb2c509b8 (vector_lock){-.-.}-{2:2}, at: irq_force_complete_move+0x2a/0x70
  #2: ffffffffb2c7cec0 (console_lock){+.+.}-{0:0}, at: printk+0x48/0x4a
  #3: ffffffffb2c7cbe0 (console_owner){....}-{0:0}, at: console_unlock+0x1af/0x650
 stack backtrace:
 CPU: 2 PID: 20 Comm: migration/2 Not tainted 5.9.0-rc5+ #3
 Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.13.0-2.fc32 04/01/2014
 Call Trace:
  dump_stack+0x8b/0xb8
  __lock_acquire.cold+0x1ce/0x333
  ? stack_trace_save+0x3b/0x50
  ? save_trace+0x3f/0x360
  lock_acquire+0xbf/0x3e0
  ? serial8250_console_write+0x8e/0x380
  _raw_spin_lock_irqsave+0x48/0x60
  ? serial8250_console_write+0x8e/0x380
  serial8250_console_write+0x8e/0x380
  ? console_unlock+0x1e8/0x650
  console_unlock+0x3f3/0x650
  ? printk+0x48/0x4a
  vprintk_emit+0x1b1/0x440
  printk+0x48/0x4a
  irq_force_complete_move.cold+0xf/0x14
  irq_migrate_all_off_this_cpu+0xfa/0x2f0
  fixup_irqs+0x25/0xe8
  cpu_disable_common+0x2b8/0x2d0
  native_cpu_disable+0x18/0x30
  take_cpu_down+0x2f/0xa0
  multi_cpu_stop+0x6d/0x130
  ? stop_machine_yield+0x10/0x10
  cpu_stopper_thread+0x7b/0x110
  ? smpboot_thread_fn+0x26/0x1e0
  smpboot_thread_fn+0x10b/0x1e0
  ? smpboot_register_percpu_thread+0xf0/0xf0
  kthread+0x13a/0x150
  ? kthread_create_worker_on_cpu+0x40/0x40
  ret_from_fork+0x22/0x30
  smpboot: CPU 2 is now offline
 =============================

It was caused by printk() inside a code section protected by a
raw_spin_lock() that ended up calling a serial console that
uses a regular spin_lock().

Use the printk_deferred() to avoid calling the serial console
in a raw_spin_lock() protected section.

Signed-off-by: Daniel Bristot de Oliveira <bristot@redhat.com>
Suggested-by: Thomas Gleixner <tglx@linutronix.de>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Ingo Molnar <mingo@redhat.com>
Cc: Borislav Petkov <bp@alien8.de>
Cc: "H. Peter Anvin" <hpa@zytor.com>
Cc: Marc Zyngier <maz@kernel.org>
Cc: Peter Xu <peterx@redhat.com>
Cc: Andy Lutomirski <luto@kernel.org>
Cc: Bjorn Helgaas <bhelgaas@google.com>
Cc: x86@kernel.org
Cc: linux-kernel@vger.kernel.org
---
 arch/x86/kernel/apic/vector.c | 20 ++++++++++++--------
 1 file changed, 12 insertions(+), 8 deletions(-)

diff --git a/arch/x86/kernel/apic/vector.c b/arch/x86/kernel/apic/vector.c
index f8a56b5dc29f..1a0e5535b8ac 100644
--- a/arch/x86/kernel/apic/vector.c
+++ b/arch/x86/kernel/apic/vector.c
@@ -406,8 +406,9 @@ static int activate_reserved(struct irq_data *irqd)
 	 */
 	if (!cpumask_subset(irq_data_get_effective_affinity_mask(irqd),
 			    irq_data_get_affinity_mask(irqd))) {
-		pr_warn("irq %u: Affinity broken due to vector space exhaustion.\n",
-			irqd->irq);
+		printk_deferred(KERN_WARNING
+				"irq %u: Affinity broken due to vector space exhaustion.\n",
+				irqd->irq);
 	}
 
 	return ret;
@@ -1012,8 +1013,9 @@ void irq_force_complete_move(struct irq_desc *desc)
 		 * so we have the necessary information when a problem in that
 		 * area arises.
 		 */
-		pr_warn("IRQ fixup: irq %d move in progress, old vector %d\n",
-			irqd->irq, vector);
+		printk_deferred(KERN_WARNING
+				"IRQ fixup: irq %d move in progress, old vector %d\n",
+				irqd->irq, vector);
 	}
 	free_moved_vector(apicd);
 unlock:
@@ -1034,15 +1036,17 @@ int lapic_can_unplug_cpu(void)
 	tomove = irq_matrix_allocated(vector_matrix);
 	avl = irq_matrix_available(vector_matrix, true);
 	if (avl < tomove) {
-		pr_warn("CPU %u has %u vectors, %u available. Cannot disable CPU\n",
-			cpu, tomove, avl);
+		printk_deferred(KERN_WARNING
+				"CPU %u has %u vectors, %u available. Cannot disable CPU\n",
+				cpu, tomove, avl);
 		ret = -ENOSPC;
 		goto out;
 	}
 	rsvd = irq_matrix_reserved(vector_matrix);
 	if (avl < rsvd) {
-		pr_warn("Reserved vectors %u > available %u. IRQ request may fail\n",
-			rsvd, avl);
+		printk_deferred(KERN_WARNING
+				"Reserved vectors %u > available %u. IRQ request may fail\n",
+				rsvd, avl);
 	}
 out:
 	raw_spin_unlock(&vector_lock);
-- 
2.26.2

Re: [PATCH] x86/irq: Use printk_deferred() on raw_spin_lock() protected sections

[Peter Zijlstra]

On Mon, Sep 21, 2020 at 06:22:12PM +0200, Daniel Bristot de Oliveira wrote:
> While testing hotplug I got this BUG:

> 
> It was caused by printk() inside a code section protected by a
> raw_spin_lock() that ended up calling a serial console that
> uses a regular spin_lock().
> 
> Use the printk_deferred() to avoid calling the serial console
> in a raw_spin_lock() protected section.

I consider printk_deferred() to be a bug, can't we just wait for the new
printk implementation to land so we don't need all this nonsense?

Re: [PATCH] x86/irq: Use printk_deferred() on raw_spin_lock() protected sections

[Joe Perches]

On Thu, 2020-09-24 at 12:28 +0200, Peter Zijlstra wrote:
> On Mon, Sep 21, 2020 at 06:22:12PM +0200, Daniel Bristot de Oliveira wrote:
> > While testing hotplug I got this BUG:
> > It was caused by printk() inside a code section protected by a
> > raw_spin_lock() that ended up calling a serial console that
> > uses a regular spin_lock().
> > 
> > Use the printk_deferred() to avoid calling the serial console
> > in a raw_spin_lock() protected section.
> 
> I consider printk_deferred() to be a bug, can't we just wait for the new
> printk implementation to land so we don't need all this nonsense?

It will be good to do a sed fixup for all these
printk_deferred uses soon,  but in the meantime
isn't it useful to avoid BUGs?

Re: [PATCH] x86/irq: Use printk_deferred() on raw_spin_lock() protected sections

[Peter Zijlstra]

On Thu, Sep 24, 2020 at 09:08:57AM -0700, Joe Perches wrote:
> On Thu, 2020-09-24 at 12:28 +0200, Peter Zijlstra wrote:
> > On Mon, Sep 21, 2020 at 06:22:12PM +0200, Daniel Bristot de Oliveira wrote:
> > > While testing hotplug I got this BUG:
> > > It was caused by printk() inside a code section protected by a
> > > raw_spin_lock() that ended up calling a serial console that
> > > uses a regular spin_lock().
> > > 
> > > Use the printk_deferred() to avoid calling the serial console
> > > in a raw_spin_lock() protected section.
> > 
> > I consider printk_deferred() to be a bug, can't we just wait for the new
> > printk implementation to land so we don't need all this nonsense?
> 
> It will be good to do a sed fixup for all these
> printk_deferred uses soon,  but in the meantime
> isn't it useful to avoid BUGs?

The kernel isn't PROVE_RAW_LOCK_NESTING clean anyway. Printk is one of
the biggest offenders there anyway, iirc.