[PATCH printk v2 00/18] add threaded printing + the rest

[PATCH printk v2 00/18] add threaded printing + the rest

[John Ogness]

Hi,

This is v2 of a series to implement threaded console printing as well
as some other minor pieces (such as proc and sysfs support). This
series is only a subset of the original v1 [0]. In particular, this
series represents patches 11, 12, 15 of the v1 series. For information
about the motivation of the nbcon consoles, please read the cover
letter of v1.

This series provides the remaining pieces of the printk rework. All
other components are either already mainline or are currently in
linux-next. In particular this series does:

- Implement dedicated printing threads per nbcon console.

- Implement "threadprintk" boot argument to force threading of legacy
  consoles.

- Implement nbcon support for proc and sysfs console-related files.

- Provide a new helper function nbcon_reacquire() to allow nbcon
  console drivers to reacquire ownership.

Note that this series does *not* provide an nbcon console driver. That
will come in a follow-up series.

Also note that the first 3 patches of the series are either already
mainline or are queued for 6.11. They are included in this series for
completeness when applied to the printk for-next branch.

Much has changed since v1 and the patches no longer correlate
1:1. Here is an attempt to list the changes:

- Implement a special dedicated thread to force threading of legacy
  console drivers.

- Add "threadprintk" boot argument to force threading of legacy
  console drivers. (For PREEMPT_RT, this is automatically enabled.)

- Add sparse notation for console_srcu_read_lock/unlock().

- Define a dedicated wait queue for the legacy thread.

- Stop threads on shutdown/reboot for a clean transition to atomic
  printing.

- Print a replay message when a higher priority printer context takes
  over another printer context.

- Reset lockdep context for legacy printing on !PREEMPT_RT to avoid
  false positive lockdep splats.

- Use write_thread() callback if printing from console_flush_all() and
  @do_cond_resched is 1.

- Do not allocate separate pbufs for printing threads. Use the same
  pbufs that the atomic printer uses.

- Wake printing threads without considering nbcon lock state.

- Implement rcuwait_has_sleeper() to check for waiting tasks instead
  of using a custom atomic variable @kthread_waiting.

John Ogness

[0] https://lore.kernel.org/lkml/20230302195618.156940-1-john.ogness@linutronix.de

John Ogness (13):
  printk: Atomic print in printk context on shutdown
  printk: nbcon: Add context to console_is_usable()
  printk: nbcon: Stop threads on shutdown/reboot
  printk: nbcon: Start printing threads
  printk: Provide helper for message prepending
  printk: nbcon: Show replay message on takeover
  printk: Add kthread for all legacy consoles
  proc: consoles: Add notation to c_start/c_stop
  proc: Add nbcon support for /proc/consoles
  tty: sysfs: Add nbcon support for 'active'
  printk: Provide threadprintk boot argument
  printk: Avoid false positive lockdep report for legacy printing
  printk: nbcon: Add function for printers to reacquire ownership

Sreenath Vijayan (3):
  printk: Add function to replay kernel log on consoles
  tty/sysrq: Replay kernel log messages on consoles via sysrq
  printk: Rename console_replay_all() and update context

Thomas Gleixner (2):
  printk: nbcon: Introduce printing kthreads
  printk: nbcon: Add printer thread wakeups

 .../admin-guide/kernel-parameters.txt         |  12 +
 Documentation/admin-guide/sysrq.rst           |   9 +
 drivers/tty/sysrq.c                           |  13 +-
 drivers/tty/tty_io.c                          |   9 +-
 fs/proc/consoles.c                            |  16 +-
 include/linux/console.h                       |  38 ++
 include/linux/printk.h                        |   6 +-
 kernel/printk/internal.h                      |  55 +-
 kernel/printk/nbcon.c                         | 421 ++++++++++++++-
 kernel/printk/printk.c                        | 482 +++++++++++++++---
 10 files changed, 945 insertions(+), 116 deletions(-)


base-commit: f3760c80d06a838495185c0fe341c043e6495142
-- 
2.39.2

[PATCH printk v2 16/18] printk: Provide threadprintk boot argument

[John Ogness]

For PREEMPT_RT, legacy console printing is performed in a dedicated
kthread. However, this behavior can also be interesting for other
preemption models as it minimizes the duration of printk() calls by
deferring all printing.

Provide a new boot argument "threadprintk" that will create the
dedicated kthread for legacy console printing for !PREEMPT_RT
systems.

The implementation is the same as the "threadirqs" boot argument.

Users should be aware that if this option is enabled, the shutdown,
reboot, and panic messages probably will not be visible on the
legacy consoles.

Non-legacy consoles (NBCON) already have their own dedicated kernel
threads for printing and reliable shutdown, reboot, and panic
printing. This option really only applies to legacy consoles.

Users can view /proc/consoles to see if their console driver is
legacy or not. NBCON console drivers are shown with 'N'.

Signed-off-by: John Ogness <john.ogness@linutronix.de>
---
 Documentation/admin-guide/kernel-parameters.txt | 12 ++++++++++++
 kernel/printk/internal.h                        |  4 +++-
 kernel/printk/printk.c                          | 11 +++++++++++
 3 files changed, 26 insertions(+), 1 deletion(-)

diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt
index 45d95614ec44..17977dd4fafa 100644
--- a/Documentation/admin-guide/kernel-parameters.txt
+++ b/Documentation/admin-guide/kernel-parameters.txt
@@ -6572,6 +6572,18 @@
 			Force threading of all interrupt handlers except those
 			marked explicitly IRQF_NO_THREAD.
 
+	threadprintk	[KNL]
+			Force threaded printing of all legacy consoles. Be
+			aware that with this option, the shutdown, reboot, and
+			panic messages may not be printed on the legacy
+			consoles. Also, earlycon/earlyprintk printing will be
+			delayed until a regular console or the kthread is
+			available.
+
+			Users can view /proc/consoles to see if their console
+			driver is legacy or not. Non-legacy (NBCON) console
+			drivers are already threaded and are shown with 'N'.
+
 	topology=	[S390,EARLY]
 			Format: {off | on}
 			Specify if the kernel should make use of the cpu
diff --git a/kernel/printk/internal.h b/kernel/printk/internal.h
index b66dfa865591..48c3564f95eb 100644
--- a/kernel/printk/internal.h
+++ b/kernel/printk/internal.h
@@ -3,6 +3,7 @@
  * internal.h - printk internal definitions
  */
 #include <linux/console.h>
+#include <linux/jump_label.h>
 #include <linux/percpu.h>
 #include <linux/types.h>
 
@@ -24,7 +25,8 @@ int devkmsg_sysctl_set_loglvl(struct ctl_table *table, int write,
 #ifdef CONFIG_PREEMPT_RT
 # define force_printkthreads()		(true)
 #else
-# define force_printkthreads()		(false)
+DECLARE_STATIC_KEY_FALSE(force_printkthreads_key);
+# define force_printkthreads()		(static_branch_unlikely(&force_printkthreads_key))
 #endif
 
 #ifdef CONFIG_PRINTK
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 1c63fd0c1166..ea2d66152256 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -195,6 +195,17 @@ static int __init control_devkmsg(char *str)
 }
 __setup("printk.devkmsg=", control_devkmsg);
 
+#if !defined(CONFIG_PREEMPT_RT)
+DEFINE_STATIC_KEY_FALSE(force_printkthreads_key);
+
+static int __init setup_forced_printkthreads(char *arg)
+{
+	static_branch_enable(&force_printkthreads_key);
+	return 0;
+}
+early_param("threadprintk", setup_forced_printkthreads);
+#endif
+
 char devkmsg_log_str[DEVKMSG_STR_MAX_SIZE] = "ratelimit";
 #if defined(CONFIG_PRINTK) && defined(CONFIG_SYSCTL)
 int devkmsg_sysctl_set_loglvl(struct ctl_table *table, int write,
-- 
2.39.2

Re: [PATCH printk v2 16/18] printk: Provide threadprintk boot argument

[Petr Mladek]

On Tue 2024-06-04 01:30:51, John Ogness wrote:
> For PREEMPT_RT, legacy console printing is performed in a dedicated
> kthread. However, this behavior can also be interesting for other
> preemption models as it minimizes the duration of printk() calls by
> deferring all printing.
> 
> Provide a new boot argument "threadprintk" that will create the
> dedicated kthread for legacy console printing for !PREEMPT_RT
> systems.
> 
> The implementation is the same as the "threadirqs" boot argument.
>
> Users should be aware that if this option is enabled, the shutdown,
> reboot, and panic messages probably will not be visible on the
> legacy consoles.

printk() is _heavily_ limited in this mode. Users would see the
messages only when the system is running well.

I think that this is a _big_ difference against "threadirqs".
It still allows to handle some critical IRQ handlers directly
by using IRQF_NO_THREAD.

> Non-legacy consoles (NBCON) already have their own dedicated kernel
> threads for printing and reliable shutdown, reboot, and panic
> printing. This option really only applies to legacy consoles.

OK, the NBCON consoles might make it a bit more useful. But there
will be only one at the beginning. And it won't work with boot
consoles.

All I want to say is that this mode has big limitations
and kind of weird semantic. This semantic is basically
needed only with PREEMPT_RT.

I would prefer to remove this patch for now. It would give us
more time to think about the threaded and sync modes.

Or I would at least use "force" in the name to make it more clear
that it forces some non-default (non-optimal) behavior.
I would call it "printk_thread_force" or "printk_legacy_thread_force".

Best Regards,
Petr

Re: [PATCH printk v2 00/18] add threaded printing + the rest

[Juri Lelli]

Hi John,

On 04/06/24 01:30, John Ogness wrote:
> Hi,
> 
> This is v2 of a series to implement threaded console printing as well
> as some other minor pieces (such as proc and sysfs support). This
> series is only a subset of the original v1 [0]. In particular, this
> series represents patches 11, 12, 15 of the v1 series. For information
> about the motivation of the nbcon consoles, please read the cover
> letter of v1.
> 
> This series provides the remaining pieces of the printk rework. All
> other components are either already mainline or are currently in
> linux-next. In particular this series does:

Our QE reported something like the following while testing the latest
rt-devel branch (I then could reproduce with this set applied on top of
linux-next).

---
... kernel: INFO: task khugepaged:351 blocked for more than 1 seconds.
... kernel:       Not tainted 6.9.0-thrdprintk+ #3
... kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
... kernel: task:khugepaged      state:D stack:0     pid:351   tgid:351   ppid:2      flags:0x00004000
... kernel: Call Trace:
... kernel:  <TASK>
... kernel:  __schedule+0x2bd/0x7f0
... kernel:  ? __lock_release.isra.0+0x5e/0x170
... kernel:  schedule+0x3d/0x100
... kernel:  schedule_timeout+0x1ca/0x1f0
... kernel:  ? mark_held_locks+0x49/0x80
... kernel:  ? _raw_spin_unlock_irq+0x24/0x50
... kernel:  ? lockdep_hardirqs_on+0x77/0x100
... kernel:  __wait_for_common+0xb7/0x220
... kernel:  ? __pfx_schedule_timeout+0x10/0x10
... kernel:  __flush_work+0x70/0x90
... kernel:  ? __pfx_wq_barrier_func+0x10/0x10
... kernel:  __lru_add_drain_all+0x179/0x210
... kernel:  khugepaged+0x73/0x200
... kernel:  ? lockdep_hardirqs_on+0x77/0x100
... kernel:  ? _raw_spin_unlock_irqrestore+0x38/0x60
... kernel:  ? __pfx_khugepaged+0x10/0x10
... kernel:  kthread+0xec/0x120
... kernel:  ? __pfx_kthread+0x10/0x10
... kernel:  ret_from_fork+0x2d/0x50
... kernel:  ? __pfx_kthread+0x10/0x10
... kernel:  ret_from_fork_asm+0x1a/0x30
... kernel:  </TASK>
... kernel:
...         Showing all locks held in the system:
... kernel: 1 lock held by khungtaskd/345:
... kernel:  #0: ffffffff8cbff1c0 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x32/0x1d0
... kernel: BUG: using smp_processor_id() in preemptible [00000000] code: khungtaskd/345
... kernel: caller is nbcon_get_cpu_emergency_nesting+0x25/0x40
... kernel: CPU: 30 PID: 345 Comm: khungtaskd Kdump: loaded Not tainted 6.9.0-thrdprintk+ #3
... kernel: Hardware name: Dell Inc. PowerEdge R740/04FC42, BIOS 2.10.2 02/24/2021
... kernel: Call Trace:
... kernel:  <TASK>
... kernel:  dump_stack_lvl+0x7f/0xa0
... kernel:  check_preemption_disabled+0xbf/0xe0
... kernel:  nbcon_get_cpu_emergency_nesting+0x25/0x40
... kernel:  nbcon_cpu_emergency_flush+0xa/0x60
... kernel:  debug_show_all_locks+0x9d/0x1d0
... kernel:  check_hung_uninterruptible_tasks+0x4f0/0x540
... kernel:  ? check_hung_uninterruptible_tasks+0x185/0x540
... kernel:  ? __pfx_watchdog+0x10/0x10
... kernel:  watchdog+0x99/0xa0
... kernel:  kthread+0xec/0x120
... kernel:  ? __pfx_kthread+0x10/0x10
... kernel:  ret_from_fork+0x2d/0x50
... kernel:  ? __pfx_kthread+0x10/0x10
... kernel:  ret_from_fork_asm+0x1a/0x30
... kernel:  </TASK>
---

It requires DEBUG_PREEMPT and LOCKDEP enabled, sched_rt_runtime_us = -1
and a while(1) loop running at FIFO for some time (I also set sysctl
kernel.hung_task_timeout_secs=1 to speed up reproduction).

Looks like check_hung_uninterruptible_tasks() requires some care as you
did already in linux-next for panic, rcu and lockdep ("Make emergency
sections ...")?

Thanks,
Juri

Re: [PATCH printk v2 00/18] add threaded printing + the rest

[John Ogness]

Hi Juri,

On 2024-06-04, Juri Lelli <juri.lelli@redhat.com> wrote:
> Our QE reported something like the following while testing the latest
> rt-devel branch (I then could reproduce with this set applied on top of
> linux-next).
>
> ---
> ... kernel: INFO: task khugepaged:351 blocked for more than 1 seconds.
> ... kernel:       Not tainted 6.9.0-thrdprintk+ #3
> ... kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> ... kernel: task:khugepaged      state:D stack:0     pid:351   tgid:351   ppid:2      flags:0x00004000
> ... kernel: Call Trace:
> ... kernel:  <TASK>
> ... kernel:  __schedule+0x2bd/0x7f0
> ... kernel:  ? __lock_release.isra.0+0x5e/0x170
> ... kernel:  schedule+0x3d/0x100
> ... kernel:  schedule_timeout+0x1ca/0x1f0
> ... kernel:  ? mark_held_locks+0x49/0x80
> ... kernel:  ? _raw_spin_unlock_irq+0x24/0x50
> ... kernel:  ? lockdep_hardirqs_on+0x77/0x100
> ... kernel:  __wait_for_common+0xb7/0x220
> ... kernel:  ? __pfx_schedule_timeout+0x10/0x10
> ... kernel:  __flush_work+0x70/0x90
> ... kernel:  ? __pfx_wq_barrier_func+0x10/0x10
> ... kernel:  __lru_add_drain_all+0x179/0x210
> ... kernel:  khugepaged+0x73/0x200
> ... kernel:  ? lockdep_hardirqs_on+0x77/0x100
> ... kernel:  ? _raw_spin_unlock_irqrestore+0x38/0x60
> ... kernel:  ? __pfx_khugepaged+0x10/0x10
> ... kernel:  kthread+0xec/0x120
> ... kernel:  ? __pfx_kthread+0x10/0x10
> ... kernel:  ret_from_fork+0x2d/0x50
> ... kernel:  ? __pfx_kthread+0x10/0x10
> ... kernel:  ret_from_fork_asm+0x1a/0x30
> ... kernel:  </TASK>
> ... kernel:
> ...         Showing all locks held in the system:
> ... kernel: 1 lock held by khungtaskd/345:
> ... kernel:  #0: ffffffff8cbff1c0 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x32/0x1d0
> ... kernel: BUG: using smp_processor_id() in preemptible [00000000] code: khungtaskd/345
> ... kernel: caller is nbcon_get_cpu_emergency_nesting+0x25/0x40
> ... kernel: CPU: 30 PID: 345 Comm: khungtaskd Kdump: loaded Not tainted 6.9.0-thrdprintk+ #3
> ... kernel: Hardware name: Dell Inc. PowerEdge R740/04FC42, BIOS 2.10.2 02/24/2021
> ... kernel: Call Trace:
> ... kernel:  <TASK>
> ... kernel:  dump_stack_lvl+0x7f/0xa0
> ... kernel:  check_preemption_disabled+0xbf/0xe0
> ... kernel:  nbcon_get_cpu_emergency_nesting+0x25/0x40
> ... kernel:  nbcon_cpu_emergency_flush+0xa/0x60
> ... kernel:  debug_show_all_locks+0x9d/0x1d0
> ... kernel:  check_hung_uninterruptible_tasks+0x4f0/0x540
> ... kernel:  ? check_hung_uninterruptible_tasks+0x185/0x540
> ... kernel:  ? __pfx_watchdog+0x10/0x10
> ... kernel:  watchdog+0x99/0xa0
> ... kernel:  kthread+0xec/0x120
> ... kernel:  ? __pfx_kthread+0x10/0x10
> ... kernel:  ret_from_fork+0x2d/0x50
> ... kernel:  ? __pfx_kthread+0x10/0x10
> ... kernel:  ret_from_fork_asm+0x1a/0x30
> ... kernel:  </TASK>
> ---
>
> It requires DEBUG_PREEMPT and LOCKDEP enabled, sched_rt_runtime_us = -1
> and a while(1) loop running at FIFO for some time (I also set sysctl
> kernel.hung_task_timeout_secs=1 to speed up reproduction).
>
> Looks like check_hung_uninterruptible_tasks() requires some care as you
> did already in linux-next for panic, rcu and lockdep ("Make emergency
> sections ...")?

Yes, that probably is a good candidate for emergency mode.

However, your report is also identifying a real issue:
nbcon_cpu_emergency_flush() was implemented to be callable from
non-emergency contexts (in which case it should do nothing). However, in
order to check if it is an emergency context, migration needs to be
disabled.

Perhaps the below change can be made for v2 of this series?

John

diff --git a/kernel/printk/nbcon.c b/kernel/printk/nbcon.c
index 4b9645e7ed70..eeaf8465f492 100644
--- a/kernel/printk/nbcon.c
+++ b/kernel/printk/nbcon.c
@@ -1581,8 +1581,19 @@ void nbcon_cpu_emergency_exit(void)
  */
 void nbcon_cpu_emergency_flush(void)
 {
+	bool is_emergency;
+
+	/*
+	 * If the current context is not an emergency context, preemption
+	 * might be enabled. To be sure, disable preemption when checking
+	 * if this is an emergency context.
+	 */
+	preempt_disable();
+	is_emergency = (*nbcon_get_cpu_emergency_nesting() != 0);
+	preempt_enable();
+
 	/* The explicit flush is needed only in the emergency context. */
-	if (*(nbcon_get_cpu_emergency_nesting()) == 0)
+	if (!is_emergency)
 		return;
 
 	nbcon_atomic_flush_pending();

Re: [PATCH printk v2 00/18] add threaded printing + the rest

[Juri Lelli]

On 05/06/24 10:15, John Ogness wrote:

...

> Yes, that probably is a good candidate for emergency mode.
> 
> However, your report is also identifying a real issue:
> nbcon_cpu_emergency_flush() was implemented to be callable from
> non-emergency contexts (in which case it should do nothing). However, in
> order to check if it is an emergency context, migration needs to be
> disabled.

I see.

> Perhaps the below change can be made for v2 of this series?

Yes, this seems to cure it.

Thanks for the super quick reply and patch!

Best,
Juri

> diff --git a/kernel/printk/nbcon.c b/kernel/printk/nbcon.c
> index 4b9645e7ed70..eeaf8465f492 100644
> --- a/kernel/printk/nbcon.c
> +++ b/kernel/printk/nbcon.c
> @@ -1581,8 +1581,19 @@ void nbcon_cpu_emergency_exit(void)
>   */
>  void nbcon_cpu_emergency_flush(void)
>  {
> +	bool is_emergency;
> +
> +	/*
> +	 * If the current context is not an emergency context, preemption
> +	 * might be enabled. To be sure, disable preemption when checking
> +	 * if this is an emergency context.
> +	 */
> +	preempt_disable();
> +	is_emergency = (*nbcon_get_cpu_emergency_nesting() != 0);
> +	preempt_enable();
> +
>  	/* The explicit flush is needed only in the emergency context. */
> -	if (*(nbcon_get_cpu_emergency_nesting()) == 0)
> +	if (!is_emergency)
>  		return;
>  
>  	nbcon_atomic_flush_pending();
>