| Message ID | 20250514173514.2117832-1-mcobb@thegoodpenguin.co.uk |
|---|---|
| Headers | show |
| Series | printk: Don't flush messages using write_atomic during console registration if kthreads have not been started yet. | expand |
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(); }
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: Using an nbcon console (115200 baud): [ 8.377111] probe of 3f215040.serial returned 0 after 8090191 usecs ... [ 9.316964] Run /sbin/init as init process With this patch applied: [ 0.302173] probe of 3f215040.serial returned 0 after 7479 usecs ... [ 1.096505] Run /sbin/init as init process This patch has been tested on master branch of the printk kernel repository (kernel/git/printk/linux.git), Commit af54a3a151691a969b04396cff15afe70d4da824 ("Merge tag 'printk-for-6.15-2' of git://git.kernel.org/pub/scm/linux/kernel/git/printk/linux") As the 8250 nbcon driver patches [0] have been applied and then reverted upstream [1], this patch requires those driver patches to be reapplied. For completeness, patches 2, 3 in this series reapplies them, but these patches should not be considered as part of this RFC. Kind regards, Michael [0] https://lore.kernel.org/lkml/20250107212702.169493-1-john.ogness@linutronix.de/ [1] https://lore.kernel.org/linux-serial/Z5jn5M5bdV5u21GB@kroah.com/ Signed-Off-By: Michael Cobb <mcobb@thegoodpenguin.co.uk> Michael Cobb (3): printk: Don't flush messages using write_atomic during console registration if kthreads have not been started yet. Reapply "serial: 8250: Switch to nbcon console" Reapply "serial: 8250: Revert "drop lockdep annotation from serial8250_clear_IER()"" drivers/tty/serial/8250/8250_core.c | 35 +++++- drivers/tty/serial/8250/8250_port.c | 183 ++++++++++++++++++++++------ include/linux/serial_8250.h | 13 +- kernel/printk/internal.h | 4 +- kernel/printk/nbcon.c | 2 + kernel/printk/printk.c | 3 + 6 files changed, 198 insertions(+), 42 deletions(-)