Re: [PATCH v3 5/6] printk: nbcon: move printk_delay to console emiting code

[Petr Mladek <pmladek@suse.com>]

On Sun 2026-07-12 11:20:36, 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.
> 
> 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.
> 
> --- 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;

We should be consistent. Note that there is one more
"allow_unsafe_takeover" bit defined above.

Maybe, the "unsigned int" was a waste of space. I do not see any
technical reason to keep it. But we should switch the existing
members in a separate patch. It might help bisecting eventual
problems, ...

>  	/* 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;

Makes perfect sense. But it should be done in a separate patch. We
should not hide this in complex patches. It will most likely
just work. But there is always a tiny risk that such changes
might cause regression or unveil an existing problem which was
hidded before.

>  #ifdef CONFIG_PRINTK_EXECUTION_CTX
>  	int			cpu;
>  	pid_t			pid;
> --- a/kernel/printk/nbcon.c
> +++ b/kernel/printk/nbcon.c
> @@ -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);

This should be:

		/*
		 * This is a compromise between reliability and	effectiveness.
		 * A less intrusive sleeping wait might be used	here. But
		 * the released nbcon context allows to print one more message
		 * in an emergency or panic context immediately. But
		 * next	messages in these contexts will have its own delay.
		 */
		if (ctxt->emitted)
			printk_delay(false);

We need to check only ctxt->emitted. Otherwise, the delay would be
skipped for the last message. It would be bad when messages are added
slow-enough so that the kthread can emit them immediately and
the delay is always skipped. But it still might be too fast for a
human reader.

> +
>  		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);

Same here:

	if (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);

Similar here. We need something like:

		if (ctxt->emitted) {
			printk_delay(true);

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

>  	}
>  
> 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
> @@ -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();
>  

The rest looks good to me.

Well, the bool parameters are always hard to follow. I would prefer to
create two wrappers. They might be defined in kernel/printk/internal.h

static inline void printk_delay_atomic(void)
{
	printk_delay(true);
}

static inline void printk_delay_thread(void)
{
	printk_delay(false);
}

Or maybe rename the original printk_delay() to __printk_delay().
And use:

static inline void printk_delay_atomic(void)
{
	printk_delay(true);
}

static inline void printk_delay(void)
{
	printk_delay(false);
}


Finally, Sashiko AI pointed out that the delay is newly done while
holding console_sem and might trigger lockup detector warning, see
https://sashiko.dev/#/patchset/20260712-printkcleanup-v3-0-574547b8f71b%40thegoodpenguin.co.uk
I would ignore it until we see real-life problems.

Best Regards,
Petr