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

Message

John Ogness June 3, 2024, 11:24 p.m. UTC

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/[e-mail]

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

Comments

Juri Lelli June 4, 2024, 1:31 p.m. UTC | #1

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

John Ogness June 5, 2024, 8:09 a.m. UTC | #2

Hi Juri,

On 2024-06-04, Juri Lelli <[e-mail]> 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();

Juri Lelli June 5, 2024, 9:32 a.m. UTC | #3

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();
>