[PATCH RFC 0/2] printk: Release console_lock between printing records in legacy thread

Andrew Murray posted 2 patches 2 weeks, 3 days ago
There is a newer version of this series
kernel/printk/printk.c | 202 +++++++++++++++++++++++++++++++++++--------------
1 file changed, 147 insertions(+), 55 deletions(-)
[PATCH RFC 0/2] printk: Release console_lock between printing records in legacy thread
Posted by Andrew Murray 2 weeks, 3 days ago
The legacy printer kthread uses console_lock and
__console_flush_and_unlock to flush records to the console which
holds the console_lock being held for the entire flush. This
results in large waiting times for console_lock waiters
especially where there is a large volume of records or where the
console is slow (e.g. serial). During boot, this contention causes
delays in the filp_open call in console_on_rootfs.
   
Let's instead release and reacquire console_lock in between
printing individual records.

I've tested this on a PocketBeagle 2, with the following boot args:
"console=ttyS2,9600 initcall_debug=1 loglevel=10"

Without the patches:

[    5.276850] +console_on_rootfs/filp_open
[    5.311995] mmc1: SDHCI controller on fa00000.mmc [fa00000.mmc] using ADMA 64-bit
[    5.313665] probe of 2b300050.target-module returned 517 after 1179 usecs
[    5.315279] probe of fa00000.mmc returned 0 after 263618 usecs
[    5.383935] mmc1: new ultra high speed SDR104 SDHC card at address 5048
[    5.394496] mmcblk1: mmc1:5048 SD32G 29.7 GiB
[    5.417837]  mmcblk1: p1 p2
[    5.423320] probe of mmc1:5048 returned 0 after 36996 usecs
[    5.425531] probe of 2b300050.target-module returned 517 after 1312 usecs
[   15.339051] probe of 2b300050.target-module returned 517 after 1062 usecs
[   15.424672] platform 2b300050.target-module: deferred probe pending: (reason unknown)
[  145.531229] -console_on_rootfs/filp_open

and with:

[    5.090776] +console_on_rootfs/filp_open
[    5.316895] mmc1: SDHCI controller on fa00000.mmc [fa00000.mmc] using ADMA 64-bit
[    5.318994] probe of 2b300050.target-module returned 517 after 1092 usecs
[    5.320578] probe of fa00000.mmc returned 0 after 333601 usecs
[    5.390914] mmc1: new ultra high speed SDR104 SDHC card at address 5048
[    5.405461] mmcblk1: mmc1:5048 SD32G 29.7 GiB
[    5.429104]  mmcblk1: p1 p2
[    5.434603] probe of mmc1:5048 returned 0 after 41200 usecs
[    5.436515] probe of 2b300050.target-module returned 517 after 1040 usecs
[    7.203025] -console_on_rootfs/filp_open

Where I've added a printk surrounding the call in console_on_rootfs to filp_open.
For reference, where loglevel=1 the console_on_rootfs delay is negligible.

Please let me know if there are other ways I can measure the impact of this.

Signed-off-by: Andrew Murray <amurray@thegoodpenguin.co.uk>
---
Andrew Murray (2):
      printk: Introduce console_flush_one_record
      printk: Use console_flush_one_record for legacy printer kthread

 kernel/printk/printk.c | 202 +++++++++++++++++++++++++++++++++++--------------
 1 file changed, 147 insertions(+), 55 deletions(-)
---
base-commit: f83ec76bf285bea5727f478a68b894f5543ca76e
change-id: 20250914-printk_legacy_thread_console_lock-1c27f59bf990

Best regards,
-- 
Andrew Murray <amurray@thegoodpenguin.co.uk>