Received-SPF: pass (google.com: domain of linux-kernel+bounces-75923-linux.lists.archive=gmail.com@vger.kernel.org designates 147.75.199.223 as permitted sender) client-ip=147.75.199.223;
Date: Wed, 21 Feb 2024 21:12:37 -0800
Precedence: bulk
Mime-Version: 1.0
Message-ID: <20240222051253.1361002-1-jstultz@google.com>
Subject: [RFC][PATCH] hrtimer: Use printk_deferred_once for hrtimer_interrupt message
From: John Stultz <jstultz@google.com>
To: LKML <linux-kernel@vger.kernel.org>
Cc: John Stultz <jstultz@google.com>, Thomas Gleixner <tglx@linutronix.de>, 
	Frederic Weisbecker <frederic@kernel.org>, Steven Rostedt <rostedt@goodmis.org>, kernel-team@android.com
Content-Type: text/plain; charset="UTF-8"

With qemu, I constantly see lockdep warnings after the
hrimter_interrupt message is printed:

[   43.434557] hrtimer: interrupt took 6517564 ns
[   43.435000]
[   43.435000] =============================
[   43.435000] [ BUG: Invalid wait context ]
[   43.435000] 6.8.0-rc5-00002-g28763ef29a5b #3743 Not tainted
[   43.435000] -----------------------------
[   43.435000] lock_torture_wr/605 is trying to lock:
[   43.435000] ffffffffbdcdc6f8 (&port_lock_key){-...}-{3:3}, at: serial8250_console_write+0xdd/0x710
[   43.435000] other info that might help us debug this:
[   43.435000] context-{2:2}
[   43.435000] 4 locks held by lock_torture_wr/605:
[   43.435000]  #0: ffffffffbd6f1de8 (torture_mutex_init#4){+.+.}-{4:4}, at: torture_mutex_nested_lock+0x4b/0x70
[   43.435000]  #1: ffffffffbb557260 (console_lock){+.+.}-{0:0}, at: vprintk_emit+0xd3/0x330
[   43.435000]  #2: ffffffffbb5572d0 (console_srcu){....}-{0:0}, at: console_flush_all+0xd6/0x6b0
[   43.435000]  #3: ffffffffbb396e20 (console_owner){-...}-{0:0}, at: console_flush_all+0x2a0/0x6b0
[   43.435000] stack backtrace:
[   43.435000] CPU: 36 PID: 605 Comm: lock_torture_wr Not tainted 6.8.0-rc5-00002-g28763ef29a5b #3743
[   43.435000] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.3-debian-1.16.3-2 04/01/2014
[   43.435000] Call Trace:
[   43.435000]  <IRQ>
[   43.435000]  dump_stack_lvl+0x57/0x90
[   43.435000]  __lock_acquire+0xd07/0x3260
[   43.435000]  ? __pfx___lock_acquire+0x10/0x10
[   43.435000]  ? memchr+0x1e/0x50
[   43.435000]  lock_acquire+0x159/0x3b0
[   43.435000]  ? serial8250_console_write+0xdd/0x710
[   43.435000]  ? __pfx_lock_acquire+0x10/0x10
[   43.435000]  ? __pfx___lock_acquire+0x10/0x10
[   43.435000]  _raw_spin_lock_irqsave+0x42/0x60
[   43.435000]  ? serial8250_console_write+0xdd/0x710
[   43.435000]  serial8250_console_write+0xdd/0x710
[   43.435000]  ? __pfx_serial8250_console_write+0x10/0x10
[   43.435000]  ? __pfx_lock_release+0x10/0x10
[   43.435000]  ? do_raw_spin_lock+0x104/0x180
[   43.435000]  ? __pfx_do_raw_spin_lock+0x10/0x10
[   43.435000]  ? console_flush_all+0x2a0/0x6b0
[   43.435000]  console_flush_all+0x2ea/0x6b0
[   43.435000]  ? console_flush_all+0x2a0/0x6b0
[   43.435000]  ? __pfx_console_flush_all+0x10/0x10
[   43.435000]  ? __pfx_lock_acquire+0x10/0x10
[   43.435000]  console_unlock+0x9d/0x150
[   43.435000]  ? __pfx_console_unlock+0x10/0x10
[   43.435000]  ? vprintk_emit+0xd3/0x330
[   43.435000]  ? __down_trylock_console_sem+0x62/0xa0
[   43.435000]  ? vprintk_emit+0xd3/0x330
[   43.435000]  vprintk_emit+0xdc/0x330
[   43.435000]  _printk+0x92/0xb0
[   43.435000]  ? __pfx__printk+0x10/0x10
[   43.435000]  ? hrtimer_interrupt+0x2f0/0x360
[   43.439262]  __sysvec_apic_timer_interrupt+0xb8/0x290
[   43.439345]  sysvec_apic_timer_interrupt+0x8a/0xb0
[   43.439345]  </IRQ>
[   43.439345]  <TASK>
[   43.439345]  asm_sysvec_apic_timer_interrupt+0x16/0x20

I thought the new printk work was going to resolve this, but
apparently not, so to avoid trying to printk in this problematic
context, lets use prink_deferred_once() instead.

Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Frederic Weisbecker <frederic@kernel.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: kernel-team@android.com
Signed-off-by: John Stultz <jstultz@google.com>
---
 kernel/time/hrtimer.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/kernel/time/hrtimer.c b/kernel/time/hrtimer.c
index edb0f821dcea..e6b060403384 100644
--- a/kernel/time/hrtimer.c
+++ b/kernel/time/hrtimer.c
@@ -1870,7 +1870,8 @@ void hrtimer_interrupt(struct clock_event_device *dev)
 	else
 		expires_next = ktime_add(now, delta);
 	tick_program_event(expires_next, 1);
-	pr_warn_once("hrtimer: interrupt took %llu ns\n", ktime_to_ns(delta));
+	printk_deferred_once(KERN_WARNING "hrtimer: interrupt took %llu ns\n",
+			     ktime_to_ns(delta));
 }
 
 /* called with interrupts disabled */
-- 
2.44.0.rc0.258.g7320e95886-goog