[PATCH v2] kcsan: Don't enter an nbcon emergency section for verbose reports

[PATCH v2] kcsan: Don't enter an nbcon emergency section for verbose reports

[Breno Leitao]

Since commit 59cd94ef8009 ("lockdep: Mark emergency sections in lockdep
splats"), print_irqtrace_events() runs inside an nbcon emergency
section. It is not only used by lockdep splats, though: verbose KCSAN
reports call it too, and a data race report is not an emergency. Yet in
an emergency section, every printk() flushes all pending records to the
nbcon consoles from the calling context, instead of leaving them to the
printk threads.

KCSAN makes this worse, as print_report() runs with the raw report_lock
held and interrupts disabled, so every verbose report writes out the
whole console backlog under report_lock. 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.

Fixes: 59cd94ef8009 ("lockdep: Mark emergency sections in lockdep splats")
Signed-off-by: Breno Leitao <leitao@debian.org>
---
Changes in v2:
- Retitled and reworded the commit message: a KCSAN report is not an
  emergency, report_lock only makes it worse (John Ogness)
- Add Fixes: tag (John Ogness)
- Link to v1: https://patch.msgid.link/20261103-kcsan-irqtrace-emergency-v1-1-162288205435@debian.org
---
 include/linux/lockdep.h  |  4 ++++
 kernel/kcsan/report.c    |  3 ++-
 kernel/locking/lockdep.c | 10 +++++++---
 3 files changed, 13 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..d2b1af47ee78d5 100644
--- a/kernel/kcsan/report.c
+++ b/kernel/kcsan/report.c
@@ -385,7 +385,8 @@ static void print_verbose_info(struct task_struct *task)
 
 	pr_err("\n");
 	debug_show_held_locks(task);
-	print_irqtrace_events(task);
+	/* Not an emergency: don't force console flushing from this context. */
+	__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 v2] kcsan: Don't enter an nbcon emergency section for verbose reports

[John Ogness]

On 2026-11-04, 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. It is not only used by lockdep splats, though: verbose KCSAN
> reports call it too, and a data race report is not an emergency. Yet in
> an emergency section, every printk() flushes all pending records to the
> nbcon consoles from the calling context, instead of leaving them to the
> printk threads.

Wouldn't the below diff be the proper fix?

John

diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
index c3dc84a7cef26..71f1b4b8f06d5 100644
--- a/kernel/locking/lockdep.c
+++ b/kernel/locking/lockdep.c
@@ -4245,8 +4245,6 @@ 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,8 +4258,6 @@ 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);
-
-	nbcon_cpu_emergency_exit();
 }
 
 static int HARDIRQ_verbose(struct lock_class *class)
@@ -5797,8 +5793,11 @@ static noinstr void check_flags(unsigned long flags)
 	}
 #endif
 
-	if (!debug_locks)
+	if (!debug_locks) {
+		nbcon_cpu_emergency_enter();
 		print_irqtrace_events(current);
+		nbcon_cpu_emergency_exit();
+	}
 
 	instrumentation_end();
 #endif

Re: [PATCH v2] kcsan: Don't enter an nbcon emergency section for verbose reports

[Breno Leitao]

On Wed, Nov 04, 2026 at 01:52:41PM +0106, John Ogness wrote:
> On 2026-11-04, 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. It is not only used by lockdep splats, though: verbose KCSAN
> > reports call it too, and a data race report is not an emergency. Yet in
> > an emergency section, every printk() flushes all pending records to the
> > nbcon consoles from the calling context, instead of leaving them to the
> > printk threads.
> 
> Wouldn't the below diff be the proper fix?
> 
> John
> 
> diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
> index c3dc84a7cef26..71f1b4b8f06d5 100644
> --- a/kernel/locking/lockdep.c
> +++ b/kernel/locking/lockdep.c
> @@ -4245,8 +4245,6 @@ 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,8 +4258,6 @@ 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);
> -
> -	nbcon_cpu_emergency_exit();
>  }
>  
>  static int HARDIRQ_verbose(struct lock_class *class)
> @@ -5797,8 +5793,11 @@ static noinstr void check_flags(unsigned long flags)
>  	}
>  #endif
>  
> -	if (!debug_locks)
> +	if (!debug_locks) {
> +		nbcon_cpu_emergency_enter();
>  		print_irqtrace_events(current);
> +		nbcon_cpu_emergency_exit();
> +	}
>  
>  	instrumentation_end();
>  #endif

Yes, but it was unclear to me what were the invocations of
print_irqtrace_events() that needed the emergency turned on.

how did you decided that only check_flags() needed it?

Thanks for the review,
--breno

Re: [PATCH v2] kcsan: Don't enter an nbcon emergency section for verbose reports

[John Ogness]

On 2026-11-04, Breno Leitao <leitao@debian.org> wrote:
>> Wouldn't the below diff be the proper fix?
>> 
>> John
>> 
>> diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
>> index c3dc84a7cef26..71f1b4b8f06d5 100644
>> --- a/kernel/locking/lockdep.c
>> +++ b/kernel/locking/lockdep.c
>> @@ -4245,8 +4245,6 @@ 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,8 +4258,6 @@ 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);
>> -
>> -	nbcon_cpu_emergency_exit();
>>  }
>>  
>>  static int HARDIRQ_verbose(struct lock_class *class)
>> @@ -5797,8 +5793,11 @@ static noinstr void check_flags(unsigned long flags)
>>  	}
>>  #endif
>>  
>> -	if (!debug_locks)
>> +	if (!debug_locks) {
>> +		nbcon_cpu_emergency_enter();
>>  		print_irqtrace_events(current);
>> +		nbcon_cpu_emergency_exit();
>> +	}
>>  
>>  	instrumentation_end();
>>  #endif
>
> Yes, but it was unclear to me what were the invocations of
> print_irqtrace_events() that needed the emergency turned on.
>
> how did you decided that only check_flags() needed it?

The emergency enter/exit's are intended for lockdep splats. AFAICT
check_flags() was the only call to print_irqtrace_events() that was not
already in emergency state for lockdep splats.

KCSAN is not the only non-lockdep caller of print_irqtrace_events(). So
my suggested fix applies to the other non-lockdep users as well. Commit
59cd94ef8009 ("lockdep: Mark emergency sections in lockdep splats") was
only intended for lockdep splats.

John