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

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [thread-next>] [day] [month] [year] [list]

Message-Id: <20250915-printk_legacy_thread_console_lock-v1-0-f34d42a9bcb3@thegoodpenguin.co.uk>
Date: Mon, 15 Sep 2025 13:43:04 +0100
From: Andrew Murray <amurray@...goodpenguin.co.uk>
To: Petr Mladek <pmladek@...e.com>, Steven Rostedt <rostedt@...dmis.org>, 
 John Ogness <john.ogness@...utronix.de>, 
 Sergey Senozhatsky <senozhatsky@...omium.org>
Cc: linux-kernel@...r.kernel.org, 
 Andrew Murray <amurray@...goodpenguin.co.uk>
Subject: [PATCH RFC 0/2] printk: Release console_lock between printing
 records in legacy thread

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@...goodpenguin.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@...goodpenguin.co.uk>