[PATCH] kcsan: Don't flush the consoles while holding report_lock

[PATCH] kcsan: Don't flush the consoles while holding report_lock

[Breno Leitao]

Since commit 59cd94ef8009 ("lockdep: Mark emergency sections in lockdep
splats"), print_irqtrace_events() runs inside an nbcon emergency
section. In an emergency section, every printk() flushes all pending
records to the nbcon consoles from the calling context (instead of the
printk thread).

With CONFIG_KCSAN_VERBOSE, print_report() calls print_irqtrace_events()
while holding the raw report_lock with interrupts disabled, so every
verbose report writes out the whole console backlog under report_lock,
as consoles/UARTs are usually slow, this is not good.

Other CPUs that detect a race in the meantime spin on report_lock with
interrupts disabled, as the lock is taken before rate_limit_report()
gets a chance to drop the report.

On a 72-CPU arm64 machine with a pl011 serial console, a printk flood
from memory offlining left the console about 16 seconds behind. The
next KCSAN report flushed that backlog under report_lock, the rest of
the report never made it to the log, and the buddy watchdog flagged a
CPU waiting for the lock:

  BUG: KCSAN: data-race in mlx5e_poll_tx_cq+0x5d8/0x998
  ...
  irq event stamp: 28975074
  smp: csd: Detected non-responsive CSD lock (#2) on CPU#35, waiting 5000000052 ns for CPU#26 ipi_mb+0x0/0x18(0x0).
  smp: csd: Detected non-responsive CSD lock (#3) on CPU#65, waiting 5000000020 ns for CPU#00 do_nothing+0x0/0x18(0x0).
  watchdog: CPU71: Watchdog detected hard LOCKUP on cpu 0
  Kernel panic - not syncing: Hard LOCKUP

Even without a backlog, each verbose report held report_lock for 0.2 to
0.8 seconds on that machine, the time the console needs to write the
report itself.

Add __print_irqtrace_events(), which prints the same lines without the
emergency section, and use it for verbose reports.
print_irqtrace_events() keeps the emergency section, as the lockup
detectors and the scheduler bug reports rely on it.

Signed-off-by: Breno Leitao <leitao@debian.org>
---
 include/linux/lockdep.h  |  4 ++++
 kernel/kcsan/report.c    |  6 +++++-
 kernel/locking/lockdep.c | 10 +++++++---
 3 files changed, 16 insertions(+), 4 deletions(-)

diff --git a/include/linux/lockdep.h b/include/linux/lockdep.h
index a6451ecbbe9a05..3cf52a4ba9002d 100644
--- a/include/linux/lockdep.h
+++ b/include/linux/lockdep.h
@@ -476,8 +476,12 @@ do {								\
 #endif /* CONFIG_LOCK_STAT */
 
 #ifdef CONFIG_PROVE_LOCKING
+void __print_irqtrace_events(struct task_struct *curr);
 extern void print_irqtrace_events(struct task_struct *curr);
 #else
+static inline void __print_irqtrace_events(struct task_struct *curr)
+{
+}
 static inline void print_irqtrace_events(struct task_struct *curr)
 {
 }
diff --git a/kernel/kcsan/report.c b/kernel/kcsan/report.c
index 11a48b78f8d15b..ab15ed9d642c90 100644
--- a/kernel/kcsan/report.c
+++ b/kernel/kcsan/report.c
@@ -385,7 +385,11 @@ static void print_verbose_info(struct task_struct *task)
 
 	pr_err("\n");
 	debug_show_held_locks(task);
-	print_irqtrace_events(task);
+	/*
+	 * No emergency section: it would flush all pending messages to the
+	 * consoles while report_lock is held with interrupts disabled.
+	 */
+	__print_irqtrace_events(task);
 }
 
 static void print_report(enum kcsan_value_change value_change,
diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
index c3dc84a7cef26f..847157d46e4c2f 100644
--- a/kernel/locking/lockdep.c
+++ b/kernel/locking/lockdep.c
@@ -4241,12 +4241,11 @@ check_usage_backwards(struct task_struct *curr, struct held_lock *this,
 	return 0;
 }
 
-void print_irqtrace_events(struct task_struct *curr)
+/* Like print_irqtrace_events(), but without the emergency console flush. */
+void __print_irqtrace_events(struct task_struct *curr)
 {
 	const struct irqtrace_events *trace = &curr->irqtrace;
 
-	nbcon_cpu_emergency_enter();
-
 	printk("irq event stamp: %u\n", trace->irq_events);
 	printk("hardirqs last  enabled at (%u): [<%px>] %pS\n",
 		trace->hardirq_enable_event, (void *)trace->hardirq_enable_ip,
@@ -4260,7 +4259,12 @@ void print_irqtrace_events(struct task_struct *curr)
 	printk("softirqs last disabled at (%u): [<%px>] %pS\n",
 		trace->softirq_disable_event, (void *)trace->softirq_disable_ip,
 		(void *)trace->softirq_disable_ip);
+}
 
+void print_irqtrace_events(struct task_struct *curr)
+{
+	nbcon_cpu_emergency_enter();
+	__print_irqtrace_events(curr);
 	nbcon_cpu_emergency_exit();
 }
 

---
base-commit: 6628e7d4c6b25c8d18f1345e3a20d21829aae7e4
change-id: 20261103-kcsan-irqtrace-emergency-f11dd338a43c

Best regards,
--  
Breno Leitao <leitao@debian.org>

Re: [PATCH] kcsan: Don't flush the consoles while holding report_lock

[John Ogness]

On 2026-11-03, Breno Leitao <leitao@debian.org> wrote:
> Since commit 59cd94ef8009 ("lockdep: Mark emergency sections in lockdep
> splats"), print_irqtrace_events() runs inside an nbcon emergency
> section. In an emergency section, every printk() flushes all pending
> records to the nbcon consoles from the calling context (instead of the
> printk thread).
>
> With CONFIG_KCSAN_VERBOSE, print_report() calls print_irqtrace_events()
> while holding the raw report_lock with interrupts disabled, so every
> verbose report writes out the whole console backlog under report_lock,
> as consoles/UARTs are usually slow, this is not good.

I am fine with this patch, but am not happy about the motivation. You
are right that it is "not good", but it is "not good" because the CPU is
being put into an emergency state when it is not really an
emergency. Even if the report_lock was not being held, this patch would
be equally valid.

I would even say this patch fixes 59cd94ef8009 because
print_irqtrace_events() is not exclusively used for lockdep splats.

John

Re: [PATCH] kcsan: Don't flush the consoles while holding report_lock

[Breno Leitao]

Hello John,

On Wed, Nov 04, 2026 at 11:57:32AM +0106, John Ogness wrote:
> On 2026-11-03, Breno Leitao <leitao@debian.org> wrote:
> > Since commit 59cd94ef8009 ("lockdep: Mark emergency sections in lockdep
> > splats"), print_irqtrace_events() runs inside an nbcon emergency
> > section. In an emergency section, every printk() flushes all pending
> > records to the nbcon consoles from the calling context (instead of the
> > printk thread).
> >
> > With CONFIG_KCSAN_VERBOSE, print_report() calls print_irqtrace_events()
> > while holding the raw report_lock with interrupts disabled, so every
> > verbose report writes out the whole console backlog under report_lock,
> > as consoles/UARTs are usually slow, this is not good.
> 
> I am fine with this patch, but am not happy about the motivation. You
> are right that it is "not good", but it is "not good" because the CPU is
> being put into an emergency state when it is not really an
> emergency. Even if the report_lock was not being held, this patch would
> be equally valid.

Agreed. A KCSAN report is not an emergency, so it should not enter an
emergency section in the first place. report_lock only made the problem
visible, by turning the console flush into a hard lockup.

I will reword the commit message around that in v2.

> I would even say this patch fixes 59cd94ef8009 because
> print_irqtrace_events() is not exclusively used for lockdep splats.

Makes sense, I will add:

  Fixes: 59cd94ef8009 ("lockdep: Mark emergency sections in lockdep splats")

Thanks for the review,
--breno