[PATCH v3 5/6] printk: nbcon: move printk_delay to console emiting code
From: Andrew Murray
Date: Sun Jul 12 2026 - 06:23:34 EST
The printk_delay and boot_delay features are helpful for debugging
as kernel output can be slowed down during boot allowing messages to
be seen before scrolling off the screen, or to correlate timing between
some physical event and console output.
However, since the introduction of nbcon and the legacy printer thread
for PREEMPT_RT kernels, printk records are now emited to the console
asynchronously to the caller of printk. Thus, any printk delay added by
boot_delay/printk_delay continues to slow down the calling process but
may not have any impact to the rate in which records are emited to the
console.
Let's address this by moving the printk delay from the calling code
to the console emiting code instead. Whilst this ensures that delays
are still observed (especially for slower consoles), it doesn't improve
the use-case of using boot_delay/printk_delay to correlate timings
between physical events and console output.
Behavior change:
Please note that printk delays now occur after messages are emitted
rather than before.
Please also note that the printk delays occur within the printk_safe
(irqs off) context.
Signed-off-by: Andrew Murray <amurray@xxxxxxxxxxxxxxxxxxxx>
---
include/linux/console.h | 5 ++++-
include/linux/printk.h | 1 -
kernel/printk/internal.h | 6 ++++++
kernel/printk/nbcon.c | 13 +++++++++++++
kernel/printk/printk.c | 17 +++++++++--------
5 files changed, 32 insertions(+), 10 deletions(-)
diff --git a/include/linux/console.h b/include/linux/console.h
index d624200cfc1708bf73925892a466efe0c95c5586..0f7a69bd1a42af38208fdb28971114f76f99a968 100644
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -266,6 +266,8 @@ struct printk_buffers;
* might cause a system freeze when the console
* is used later.
* @backlog: Ringbuffer has pending records
+ * @emitted: The context attempted to emit the message. Might
+ * be incomplete.
* @pbufs: Pointer to the text buffer for this context
* @seq: The sequence number to print for this context
*/
@@ -278,6 +280,7 @@ struct nbcon_context {
/* members set by emit */
unsigned int backlog : 1;
+ unsigned char emitted : 1;
/* members set by acquire */
struct printk_buffers *pbufs;
@@ -298,7 +301,7 @@ struct nbcon_write_context {
struct nbcon_context __private ctxt;
char *outbuf;
unsigned int len;
- bool unsafe_takeover;
+ unsigned char unsafe_takeover : 1;
#ifdef CONFIG_PRINTK_EXECUTION_CTX
int cpu;
pid_t pid;
diff --git a/include/linux/printk.h b/include/linux/printk.h
index ea52dc72b73b64898f82a0319b01c27323b18dee..8885e11367d50ea1cd7642249852d011e589adb4 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -188,7 +188,6 @@ extern int __printk_ratelimit(const char *func);
extern bool printk_timed_ratelimit(unsigned long *caller_jiffies,
unsigned int interval_msec);
-extern unsigned int printk_delay_msec;
extern int dmesg_restrict;
extern void wake_up_klogd(void);
diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index 85fbf1801cbe070ad96d253bccdf775a11bf945a..c3586f8b8360208902bbbd4607413997bcbd5fb9 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -33,6 +33,8 @@ int devkmsg_sysctl_set_loglvl(const struct ctl_table *table, int write,
# define force_legacy_kthread() (false)
#endif
+extern unsigned int printk_delay_msec;
+
#ifdef CONFIG_PRINTK
#ifdef CONFIG_PRINTK_CALLER
@@ -131,6 +133,8 @@ static inline void nbcon_kthread_wake(struct console *con)
rcuwait_wake_up(&con->rcuwait); /* LMM(nbcon_kthread_wake:A) */
}
+void printk_delay(bool use_atomic);
+
#else
#define PRINTK_PREFIX_MAX 0
@@ -162,6 +166,8 @@ static inline bool nbcon_legacy_emit_next_record(struct console *con, bool *hand
static inline void nbcon_kthread_wake(struct console *con) { }
static inline void nbcon_kthreads_wake(void) { }
+static inline void printk_delay(bool use_atomic) { }
+
#endif /* CONFIG_PRINTK */
extern bool have_boot_console;
diff --git a/kernel/printk/nbcon.c b/kernel/printk/nbcon.c
index 4b03b019cd5ee25d68e9ace84392045e91241a7f..c8427906b1c54fb00d005ef87f7280e89fae2579 100644
--- a/kernel/printk/nbcon.c
+++ b/kernel/printk/nbcon.c
@@ -1069,6 +1069,8 @@ static bool nbcon_emit_next_record(struct nbcon_write_context *wctxt, bool use_a
else
con->write_thread(con, wctxt);
+ ctxt->emitted = 1;
+
if (!wctxt->outbuf) {
/*
* Ownership was lost and reacquired by the driver. Handle it
@@ -1267,11 +1269,16 @@ static int nbcon_kthread_func(void *__console)
con_flags = console_srcu_read_flags(con);
+ ctxt->emitted = 0;
+
if (console_is_usable(con, con_flags, false))
backlog = nbcon_emit_one(&wctxt, false);
console_srcu_read_unlock(cookie);
+ if (backlog && ctxt->emitted)
+ printk_delay(false);
+
cond_resched();
} while (backlog);
@@ -1525,6 +1532,8 @@ bool nbcon_legacy_emit_next_record(struct console *con, bool *handover,
}
progress = nbcon_emit_one(&wctxt, use_atomic);
+ if (progress && ctxt->emitted)
+ printk_delay(use_atomic);
if (use_atomic) {
start_critical_timings();
@@ -1584,6 +1593,8 @@ static int __nbcon_atomic_flush_pending_con(struct console *con, u64 stop_seq)
if (!nbcon_context_try_acquire(ctxt, false))
return -EPERM;
+ ctxt->emitted = 0;
+
/*
* nbcon_emit_next_record() returns false when
* the console was handed over or taken over.
@@ -1600,6 +1611,8 @@ static int __nbcon_atomic_flush_pending_con(struct console *con, u64 stop_seq)
if (nbcon_seq_read(con) < stop_seq)
err = -ENOENT;
break;
+ } else if (ctxt->emitted) {
+ printk_delay(true);
}
}
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 4517266e9ca112e0dcb0163a99dd0e8d50931848..5df09e56cf8abc2d0555b6950eed4e483ba56d4b 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2143,18 +2143,17 @@ static inline void late_boot_delay_msec(void)
}
}
-static inline void printk_delay(int level)
+void printk_delay(bool use_atomic)
{
- bool suppress = !is_printk_force_console() &&
- suppress_message_printing(level);
-
- if (likely(!printk_delay_msec) || suppress)
+ if (likely(!printk_delay_msec))
return;
if (system_state < SYSTEM_RUNNING)
early_boot_delay_msec();
- else
+ else if (use_atomic)
late_boot_delay_msec();
+ else
+ msleep(printk_delay_msec);
}
#define CALLER_ID_MASK 0x80000000
@@ -2474,8 +2473,6 @@ asmlinkage int vprintk_emit(int facility, int level,
ft.legacy_direct = false;
}
- printk_delay(level);
-
printed_len = vprintk_store(facility, level, dev_info, fmt, args);
if (ft.nbcon_atomic)
@@ -3185,6 +3182,8 @@ static bool console_emit_next_record(struct console *con, bool *handover, int co
*/
con->write(con, outbuf, pmsg.outbuf_len);
+ printk_delay(true);
+
con->seq = pmsg.seq + 1;
} else {
/*
@@ -3206,6 +3205,7 @@ static bool console_emit_next_record(struct console *con, bool *handover, int co
printk_legacy_allow_spinlock_enter();
con->write(con, outbuf, pmsg.outbuf_len);
printk_legacy_allow_spinlock_exit();
+ printk_delay(true);
start_critical_timings();
@@ -3214,6 +3214,7 @@ static bool console_emit_next_record(struct console *con, bool *handover, int co
*handover = console_lock_spinning_disable_and_check(cookie);
printk_safe_exit_irqrestore(flags);
}
+
skip:
return true;
}
--
2.34.1