The legacy printer kthread uses console_lock and
__console_flush_and_unlock to flush records to the console. This
approach results in the console_lock being held for the entire
duration of a flush. This can result in large waiting times for
those waiting for console_lock especially where there is a large
volume of records or where the console is slow (e.g. serial). This
contention is observed during boot, as the call to filp_open in
console_on_rootfs will delay progression to userspace until any
in-flight flush is completed.
Let's instead use console_flush_one_record and release/reacquire
the console_lock between records.
On a PocketBeagle 2, with the following boot args:
"console=ttyS2,9600 initcall_debug=1 loglevel=10"
Without this patch:
[ 5.613166] +console_on_rootfs/filp_open
[ 5.643473] mmc1: SDHCI controller on fa00000.mmc [fa00000.mmc] using ADMA 64-bit
[ 5.643823] probe of fa00000.mmc returned 0 after 258244 usecs
[ 5.710520] mmc1: new UHS-I speed SDR104 SDHC card at address 5048
[ 5.721976] mmcblk1: mmc1:5048 SD32G 29.7 GiB
[ 5.747258] mmcblk1: p1 p2
[ 5.753324] probe of mmc1:5048 returned 0 after 40002 usecs
[ 15.595240] ti_sci_pm_domains 44043000.system-controller:power-controller: sync_state() pending due to 30040000.pruss
[ 15.595282] ti_sci_pm_domains 44043000.system-controller:power-controller: sync_state() pending due to e010000.watchdog
[ 15.595297] ti_sci_pm_domains 44043000.system-controller:power-controller: sync_state() pending due to e000000.watchdog
[ 15.595437] ti_sci_pm_domains 44043000.system-controller:power-controller: sync_state() pending due to 30300000.crc
[ 146.275961] -console_on_rootfs/filp_open ...
and with:
[ 5.477122] +console_on_rootfs/filp_open
[ 5.595814] mmc1: SDHCI controller on fa00000.mmc [fa00000.mmc] using ADMA 64-bit
[ 5.596181] probe of fa00000.mmc returned 0 after 312757 usecs
[ 5.662813] mmc1: new UHS-I speed SDR104 SDHC card at address 5048
[ 5.674367] mmcblk1: mmc1:5048 SD32G 29.7 GiB
[ 5.699320] mmcblk1: p1 p2
[ 5.705494] probe of mmc1:5048 returned 0 after 39987 usecs
[ 6.418682] -console_on_rootfs/filp_open ...
...
[ 15.593509] ti_sci_pm_domains 44043000.system-controller:power-controller: sync_state() pending due to 30040000.pruss
[ 15.593551] ti_sci_pm_domains 44043000.system-controller:power-controller: sync_state() pending due to e010000.watchdog
[ 15.593566] ti_sci_pm_domains 44043000.system-controller:power-controller: sync_state() pending due to e000000.watchdog
[ 15.593704] ti_sci_pm_domains 44043000.system-controller:power-controller: sync_state() pending due to 30300000.crc
Where I've added a printk surrounding the call in console_on_rootfs to filp_open.
Suggested-by: Petr Mladek <pmladek@suse.com>
Signed-off-by: Andrew Murray <amurray@thegoodpenguin.co.uk>
---
kernel/printk/printk.c | 24 ++++++++++++++++++------
1 file changed, 18 insertions(+), 6 deletions(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index e2c1cacdb4164489c60fe38f1e2837eb838107d6..2c9b9383df76de956a05211537264fd6e06366da 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -3668,17 +3668,29 @@ static bool legacy_kthread_should_wakeup(void)
static int legacy_kthread_func(void *unused)
{
- for (;;) {
- wait_event_interruptible(legacy_wait, legacy_kthread_should_wakeup());
+ bool any_progress;
+
+wait_for_event:
+ wait_event_interruptible(legacy_wait,
+ legacy_kthread_should_wakeup());
+
+ do {
+ bool any_usable;
+ bool handover = false;
+ u64 next_seq;
if (kthread_should_stop())
- break;
+ return 0;
console_lock();
- __console_flush_and_unlock();
- }
+ any_progress = console_flush_one_record(true, &next_seq,
+ &handover, &any_usable);
+ if (!handover)
+ __console_unlock();
- return 0;
+ } while (any_progress);
+
+ goto wait_for_event;
}
static bool legacy_kthread_create(void)
--
2.34.1Here is the same patch with the alternative semantic of
console_flush_one_record() as proposed at
https://lore.kernel.org/all/aN_3id2CF7ivC42R@pathway.suse.cz/
The return value from console_flush_all() can be ignored.
It is enough to check whether @try_again is true.
I hope that this semantic is more straightforward.
Here to go:
From 51667c506c13f662d222c7907e6a055ae77639a0 Mon Sep 17 00:00:00 2001
From: Andrew Murray <amurray@thegoodpenguin.co.uk>
Date: Sat, 27 Sep 2025 23:05:37 +0100
Subject: [PATCH 3/3] printk: Use console_flush_one_record for legacy printer
kthread
The legacy printer kthread uses console_lock and
__console_flush_and_unlock to flush records to the console. This
approach results in the console_lock being held for the entire
duration of a flush. This can result in large waiting times for
those waiting for console_lock especially where there is a large
volume of records or where the console is slow (e.g. serial). This
contention is observed during boot, as the call to filp_open in
console_on_rootfs will delay progression to userspace until any
in-flight flush is completed.
Let's instead use console_flush_one_record and release/reacquire
the console_lock between records.
On a PocketBeagle 2, with the following boot args:
"console=ttyS2,9600 initcall_debug=1 loglevel=10"
Without this patch:
[ 5.613166] +console_on_rootfs/filp_open
[ 5.643473] mmc1: SDHCI controller on fa00000.mmc [fa00000.mmc] using ADMA 64-bit
[ 5.643823] probe of fa00000.mmc returned 0 after 258244 usecs
[ 5.710520] mmc1: new UHS-I speed SDR104 SDHC card at address 5048
[ 5.721976] mmcblk1: mmc1:5048 SD32G 29.7 GiB
[ 5.747258] mmcblk1: p1 p2
[ 5.753324] probe of mmc1:5048 returned 0 after 40002 usecs
[ 15.595240] ti_sci_pm_domains 44043000.system-controller:power-controller: sync_state() pending due to 30040000.pruss
[ 15.595282] ti_sci_pm_domains 44043000.system-controller:power-controller: sync_state() pending due to e010000.watchdog
[ 15.595297] ti_sci_pm_domains 44043000.system-controller:power-controller: sync_state() pending due to e000000.watchdog
[ 15.595437] ti_sci_pm_domains 44043000.system-controller:power-controller: sync_state() pending due to 30300000.crc
[ 146.275961] -console_on_rootfs/filp_open ...
and with:
[ 5.477122] +console_on_rootfs/filp_open
[ 5.595814] mmc1: SDHCI controller on fa00000.mmc [fa00000.mmc] using ADMA 64-bit
[ 5.596181] probe of fa00000.mmc returned 0 after 312757 usecs
[ 5.662813] mmc1: new UHS-I speed SDR104 SDHC card at address 5048
[ 5.674367] mmcblk1: mmc1:5048 SD32G 29.7 GiB
[ 5.699320] mmcblk1: p1 p2
[ 5.705494] probe of mmc1:5048 returned 0 after 39987 usecs
[ 6.418682] -console_on_rootfs/filp_open ...
...
[ 15.593509] ti_sci_pm_domains 44043000.system-controller:power-controller: sync_state() pending due to 30040000.pruss
[ 15.593551] ti_sci_pm_domains 44043000.system-controller:power-controller: sync_state() pending due to e010000.watchdog
[ 15.593566] ti_sci_pm_domains 44043000.system-controller:power-controller: sync_state() pending due to e000000.watchdog
[ 15.593704] ti_sci_pm_domains 44043000.system-controller:power-controller: sync_state() pending due to 30300000.crc
Where I've added a printk surrounding the call in console_on_rootfs to filp_open.
Suggested-by: Petr Mladek <pmladek@suse.com>
Signed-off-by: Andrew Murray <amurray@thegoodpenguin.co.uk>
---
kernel/printk/printk.c | 22 ++++++++++++++++------
1 file changed, 16 insertions(+), 6 deletions(-)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 6c846d2d37d9..885506fa0178 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -3644,17 +3644,27 @@ static bool legacy_kthread_should_wakeup(void)
static int legacy_kthread_func(void *unused)
{
- for (;;) {
- wait_event_interruptible(legacy_wait, legacy_kthread_should_wakeup());
+ bool try_again;
+
+wait_for_event:
+ wait_event_interruptible(legacy_wait,
+ legacy_kthread_should_wakeup());
+
+ do {
+ bool handover = false;
+ u64 next_seq;
if (kthread_should_stop())
- break;
+ return 0;
console_lock();
- __console_flush_and_unlock();
- }
+ console_flush_one_record(true, &next_seq, &handover, &try_again);
+ if (!handover)
+ __console_unlock();
- return 0;
+ } while (try_again);
+
+ goto wait_for_event;
}
static bool legacy_kthread_create(void)
--
2.51.0
On 2025-10-03, Petr Mladek <pmladek@suse.com> wrote:
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 6c846d2d37d9..885506fa0178 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -3644,17 +3644,27 @@ static bool legacy_kthread_should_wakeup(void)
>
> static int legacy_kthread_func(void *unused)
> {
> - for (;;) {
> - wait_event_interruptible(legacy_wait, legacy_kthread_should_wakeup());
> + bool try_again;
> +
> +wait_for_event:
> + wait_event_interruptible(legacy_wait,
> + legacy_kthread_should_wakeup());
This should be on one line. Even with an 80-character limit it would
fit. ;-)
> +
> + do {
> + bool handover = false;
> + u64 next_seq;
Even though legacy_kthread_func() does not care, @next_seq should be
initialized to something since console_flush_one_record() reads this
value to decide if it should be increased. It really doesn't matter what
it is initialized to, but I guess 0 makes the most sense.
John
On 2025-09-27, Andrew Murray <amurray@thegoodpenguin.co.uk> wrote:
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index e2c1cacdb4164489c60fe38f1e2837eb838107d6..2c9b9383df76de956a05211537264fd6e06366da 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -3668,17 +3668,29 @@ static bool legacy_kthread_should_wakeup(void)
>
> static int legacy_kthread_func(void *unused)
> {
> - for (;;) {
> - wait_event_interruptible(legacy_wait, legacy_kthread_should_wakeup());
> + bool any_progress;
> +
> +wait_for_event:
> + wait_event_interruptible(legacy_wait,
> + legacy_kthread_should_wakeup());
> +
> + do {
> + bool any_usable;
> + bool handover = false;
> + u64 next_seq;
Please sort by length. It looks nicer. ;-)
bool handover = false;
bool any_usable;
u64 next_seq;
Note that it is fine that @any_usable is not initialized here because
legacy_kthread_func() does not actually care about this variable.
John
On Tue, 30 Sept 2025 at 14:03, John Ogness <john.ogness@linutronix.de> wrote:
>
> On 2025-09-27, Andrew Murray <amurray@thegoodpenguin.co.uk> wrote:
> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > index e2c1cacdb4164489c60fe38f1e2837eb838107d6..2c9b9383df76de956a05211537264fd6e06366da 100644
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -3668,17 +3668,29 @@ static bool legacy_kthread_should_wakeup(void)
> >
> > static int legacy_kthread_func(void *unused)
> > {
> > - for (;;) {
> > - wait_event_interruptible(legacy_wait, legacy_kthread_should_wakeup());
> > + bool any_progress;
> > +
> > +wait_for_event:
> > + wait_event_interruptible(legacy_wait,
> > + legacy_kthread_should_wakeup());
> > +
> > + do {
> > + bool any_usable;
> > + bool handover = false;
> > + u64 next_seq;
>
> Please sort by length. It looks nicer. ;-)
>
> bool handover = false;
> bool any_usable;
> u64 next_seq;
I agree :)
>
> Note that it is fine that @any_usable is not initialized here because
> legacy_kthread_func() does not actually care about this variable.
Yes, that's correct. I wasn't sure whether to set it to something
which would likely get optimised away, or if there was some way I
could mark it as not used (didn't see anything beneficial).
Thanks,
Andrew Murray
>
> John
© 2016 - 2026 Red Hat, Inc.