Re: [PATCH RFC 3/4] printk: nbcon: move printk_delay to console emiting code

[Petr Mladek <pmladek@suse.com>]

On Mon 2026-06-01 00:17:39, Andrew Murray wrote:
> 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.
> 
> --- a/include/linux/printk.h
> +++ b/include/linux/printk.h

The declaration is needed just inside kernel/printk/ directory.
It should better be done via kernel/printk/internal.h

> @@ -209,6 +209,7 @@ extern bool nbcon_device_try_acquire(struct console *con);
>  extern void nbcon_device_release(struct console *con);
>  void nbcon_atomic_flush_unsafe(void);
>  bool pr_flush(int timeout_ms, bool reset_on_progress);
> +void printk_delay(bool use_atomic);
>  #else
>  static inline __printf(1, 0)
>  int vprintk(const char *s, va_list args)
> @@ -326,6 +327,9 @@ static inline bool pr_flush(int timeout_ms, bool reset_on_progress)
>  {
>  	return true;
>  }
> +static inline void printk_delay(bool use_atomic)
> +{
> +}
>  
>  #endif
>  
> diff --git a/kernel/printk/nbcon.c b/kernel/printk/nbcon.c
> index d7044a7a214bdd4537a5e20d876d99bc3ffe8b3a..a507a2fed5bf4366e24330f763b842a698ecf6f7 100644
> --- a/kernel/printk/nbcon.c
> +++ b/kernel/printk/nbcon.c
> @@ -1267,11 +1267,16 @@ static int nbcon_kthread_func(void *__console)
>  
>  		con_flags = console_srcu_read_flags(con);
>  
> +		wctxt.len = 0;
> +
>  		if (console_is_usable(con, con_flags, false))
>  			backlog = nbcon_emit_one(&wctxt, false);
>  
>  		console_srcu_read_unlock(cookie);
>  
> +		if (backlog && wctxt.len > 0)

Heh, this is tricky. It might probably work but it is not guarantted
by design.

The "backlog" name is a bit misleading. The value is basically
wctxt.ctxt.backlog. The real meaning is that printk_get_next_message()
was able to read a message. It means that there _was_ a backlog.
But it is not clear whether there are still pending messages or not.

Also it is not clear that whether the message was pushed to the
console or not. It might have been supressed in which case
(wctxt.len == 0). But it might also be emitted only partially
when a higher priority context took over the console context
ownership.

I would prefer to explicitely set some flag when
nbcon_emit_next_record() really called con->write*().
See below.

> +			printk_delay(false);
> +
>  		cond_resched();
>  
>  	} while (backlog);
> @@ -1525,6 +1530,8 @@ bool nbcon_legacy_emit_next_record(struct console *con, bool *handover,
>  	}
>  
>  	progress = nbcon_emit_one(&wctxt, use_atomic);
> +	if (progress && wctxt.len > 0)

Same here.

> +		printk_delay(use_atomic);
>  
>  	if (use_atomic) {
>  		start_critical_timings();
> @@ -1584,6 +1591,8 @@ static int __nbcon_atomic_flush_pending_con(struct console *con, u64 stop_seq)
>  			if (!nbcon_context_try_acquire(ctxt, false))
>  				return -EPERM;
>  
> +			wctxt.len = 0;
> +
>  			/*
>  			 * nbcon_emit_next_record() returns false when
>  			 * the console was handed over or taken over.
> @@ -1595,7 +1604,9 @@ static int __nbcon_atomic_flush_pending_con(struct console *con, u64 stop_seq)
>  			nbcon_context_release(ctxt);
>  		}
>  
> -		if (!ctxt->backlog) {
> +		if (ctxt->backlog && wctxt.len > 0) {
> +			printk_delay(true);
> +		} else {

This changes the semantic. The original code call this when
no message was read. The new code would call this path also
when the output was suppressed. It would probably work.
But still.

>  			/* Are there reserved but not yet finalized records? */
>  			if (nbcon_seq_read(con) < stop_seq)
>  				err = -ENOENT;


As mentioned above, I would add a flag which would be set when
con->write*() was called.

It modifies the type of unsafe_takeover in struct nbcon_write_context.
But it actually makes it more compatible with struct nbcon_state.

My proposal (on top of this patch):

diff --git a/include/linux/console.h b/include/linux/console.h
index 5520e4477ad7..5a86942e55ef 100644
--- a/include/linux/console.h
+++ b/include/linux/console.h
@@ -290,6 +290,7 @@ struct nbcon_context {
  * @outbuf:		Pointer to the text buffer for output
  * @len:		Length to write
  * @unsafe_takeover:	If a hostile takeover in an unsafe state has occurred
+ * @emitted:		The write context tried to emit the message. Might be incomplete.
  * @cpu:		CPU on which the message was generated
  * @pid:		PID of the task that generated the message
  * @comm:		Name of the task that generated the message
@@ -298,7 +299,8 @@ struct nbcon_write_context {
 	struct nbcon_context	__private ctxt;
 	char			*outbuf;
 	unsigned int		len;
-	bool			unsafe_takeover;
+	unsigned char		unsafe_takeover	:  1;
+	unsigned char		emitted : 1
 #ifdef CONFIG_PRINTK_EXECUTION_CTX
 	int			cpu;
 	pid_t			pid;
diff --git a/kernel/printk/nbcon.c b/kernel/printk/nbcon.c
index a507a2fed5bf..060534becefc 100644
--- a/kernel/printk/nbcon.c
+++ b/kernel/printk/nbcon.c
@@ -1069,6 +1069,9 @@ static bool nbcon_emit_next_record(struct nbcon_write_context *wctxt, bool use_a
 	else
 		con->write_thread(con, wctxt);
 
+	/* Tried to emit something. Might be incomplete. */
+	wctxt.emitted = 1;
+
 	if (!wctxt->outbuf) {
 		/*
 		 * Ownership was lost and reacquired by the driver. Handle it
@@ -1267,14 +1270,14 @@ static int nbcon_kthread_func(void *__console)
 
 		con_flags = console_srcu_read_flags(con);
 
-		wctxt.len = 0;
+		wctxt.emitted = 0;
 
 		if (console_is_usable(con, con_flags, false))
 			backlog = nbcon_emit_one(&wctxt, false);
 
 		console_srcu_read_unlock(cookie);
 
-		if (backlog && wctxt.len > 0)
+		if (wctxt.emitted)
 			printk_delay(false);
 
 		cond_resched();
@@ -1530,7 +1533,7 @@ bool nbcon_legacy_emit_next_record(struct console *con, bool *handover,
 	}
 
 	progress = nbcon_emit_one(&wctxt, use_atomic);
-	if (progress && wctxt.len > 0)
+	if (wctxt.emitted)
 		printk_delay(use_atomic);
 
 	if (use_atomic) {
@@ -1591,7 +1594,7 @@ static int __nbcon_atomic_flush_pending_con(struct console *con, u64 stop_seq)
 			if (!nbcon_context_try_acquire(ctxt, false))
 				return -EPERM;
 
-			wctxt.len = 0;
+			wctxt.emitted = 0;
 
 			/*
 			 * nbcon_emit_next_record() returns false when
@@ -1604,9 +1607,10 @@ static int __nbcon_atomic_flush_pending_con(struct console *con, u64 stop_seq)
 			nbcon_context_release(ctxt);
 		}
 
-		if (ctxt->backlog && wctxt.len > 0) {
+		if (wctxt.emitted)
 			printk_delay(true);
-		} else {
+
+		if (!ctxt->backlog) {
 			/* Are there reserved but not yet finalized records? */
 			if (nbcon_seq_read(con) < stop_seq)
 				err = -ENOENT;