Re: [PATCH RFC 0/3] printk: Don't flush messages using write_atomic during console registration if kthreads have not been started yet.

[John Ogness <john.ogness@linutronix.de>]

Hi Michael,

On 2025-05-14, Michael Cobb <mcobb@thegoodpenguin.co.uk> wrote:
> Hello all,
>
> When using a legacy console, there is a large amount of time during boot
> that is spent printing boot messages to the serial port. I have spent time
> looking at nbcon and the potential effects the new interface should have on
> boot times. We should expect a significant reduction in boot times as this
> work is now offloaded to a dedicated kthread.
>
> With some slight tweaks to the behaviour of nbcon during console
> registration, it is possible to reduce boot times significantly.
>
> During initial console registration, we mainly rely on two flags,
> `have_nbcon_console` and `printk_kthreads_running`, to handle the glboal
> state of nbcon and to determine the appropriate method to handle flushing
> messages.
>
> In the case of nbcon, when calling `printk()`, messages are either flushed
> by the caller using `write_atomic`, or this work is offloaded to the
> console's printk kthread. As can be seen in
> `printk_get_console_flush_type()`, under normal (i.e. non-emergency or
> panic) priority, we check the value of `printk_kthreads_running` to
> determine if nbcon consoles should be flushed via `write_atomic` or not.
>
> When `register_console()` is called to register the first nbcon console
> during boot, we know that `printk_kthreads_running` will be false as:
> - before the `printk_set_kthreads_ready` initcall, no kthreads have been
>   started since `printk_kthreads_ready` will be false.
> - after the `printk_set_kthreads_ready` initcall, `printk_kthreads_running`
>   will be false since we have not yet registered any nbcon consoles. As we
>   are registering an nbcon console, `register_console()` will set
>   `have_nbcon_console = true`. At this point, we are now in an intermediate
>   state - we have registered an nbcon console but a kthread for it has not
>   yet been started.
>
> In effect, this means that any calls made to `printk()` after
> `have_nbcon_console` has been set but before
> `printk_kthreads_check_locked()` has set `printk_kthreads_running` will use
> `write_atomic` on nbcon consoles. As `vprintk_emit()` calls
> `nbcon_atomic_flush_pending()` in this situation, we see that the newly
> registered console has all boot messages flushed in this manner.
>
> This RFC patch introduces a new flag, `printk_kthreads_pending_start`, to
> handle this intermediate state. This flag is set when an nbcon console is
> registered and cleared once `printk_kthreads_running` is set to true. We
> then check this flag under `printk_get_console_flush_type()`, so that
> printk's are deferred in this state, relying on the fact that a kthread is
> about to be started. This does not affect behaviour under panic and
> emergency priorities which are flushed via `write_atomic`.
>
> With this change applied, the flushing of printk messages on a newly
> registered nbcon console is now fully handled by the console's kthread. On
> my test hardware (Raspberry Pi 3B+), I have seen a reduction in the time
> taken to boot into userspace when using nbcon consoles from ~9s to ~1s:

If I understand the problem correctly, it is really due to the "console
enabled" message that is printed upon registration. For the first
console, it would perform a full atomic flush, even though it is about
to create the kthread printer.

What if we create the kthread _before_ printing the message. Something
like the below (untested) changes. Does this also address the issue?

John Ogness

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 1eea80d0648ed..ecc0f393cacf0 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -4122,7 +4122,6 @@ void register_console(struct console *newcon)
 	 * users know there might be something in the kernel's log buffer that
 	 * went to the bootconsole (that they do not see on the real console)
 	 */
-	con_printk(KERN_INFO, newcon, "enabled\n");
 	if (bootcon_registered &&
 	    ((newcon->flags & (CON_CONSDEV | CON_BOOT)) == CON_CONSDEV) &&
 	    !keep_bootcon) {
@@ -4136,6 +4135,7 @@ void register_console(struct console *newcon)
 
 	/* Changed console list, may require printer threads to start/stop. */
 	printk_kthreads_check_locked();
+	con_printk(KERN_INFO, newcon, "enabled\n");
 unlock:
 	console_list_unlock();
 }