Re: [PATCH printk v5 1/1] printk: extend console_lock for per-console locking

From: Geert Uytterhoeven
Date: Wed Jun 08 2022 - 11:16:10 EST

Hi John,

On Mon, May 2, 2022 at 3:19 PM John Ogness <john.ogness@xxxxxxxxxxxxx> wrote:
> On 2022-05-02, Marek Szyprowski <m.szyprowski@xxxxxxxxxxx> wrote:
> > Data written to /dev/kmsg and all kernel logs were always displayed
> > correctly. Also data written directly to /dev/ttyAML0 is displayed
> > properly on the console. The latter doesn't however trigger the input
> > related activity.
> >
> > It looks that the data read from the uart is delivered only if other
> > activity happens on the kernel console. If I type 'reboot' and press
> > enter, nothing happens immediately. If I type 'date >/dev/ttyAML0' via
> > ssh then, I only see the date printed on the console. However if I
> > type 'date >/dev/kmsg', the the date is printed and reboot happens.
>
> I suppose if you login via ssh and check /proc/interrupts, then type
> some things over serial, then check /proc/interrupts again, you will see
> there have been no interrupts for the uart. But interrupts for other
> devices are happening. Is this correct?
>
> > For comparison, here is a 't' sysrq result from the 'working' serial
> > console (next-20220429), which happens usually 1 of 4 boots:
> >
> > https://pastebin.com/mp8zGFbW
>
> This still looks odd to me. We should be seeing a trace originating from
> ret_from_fork+0x10/0x20 and kthread+0x118/0x11c.
>
> I wonder if the early creation of the thread is somehow causing
> problems. Could you try the following patch to see if it makes a
> difference? I would also like to see the sysrq-t output with this patch
> applied:

On one board, I'm seeing a new splat during early boot, pointing to
printk_activate_kthreads:

Calibrating delay loop (skipped), value calculated using timer
frequency.. 48.00 BogoMIPS (lpj=96000)
pid_max: default: 32768 minimum: 301
Mount-cache hash table entries: 4096 (order: 3, 32768 bytes, linear)
Mountpoint-cache hash table entries: 4096 (order: 3, 32768 bytes, linear)

=============================
[ BUG: Invalid wait context ]
5.19.0-rc1-ebisu-00802-g06a0dd60d6e4 #431 Not tainted
-----------------------------
swapper/0/1 is trying to lock:
ffffffc00910bac8 (base_crng.lock){....}-{3:3}, at:
crng_make_state+0x148/0x1e4
other info that might help us debug this:
context-{5:5}
2 locks held by swapper/0/1:
#0: ffffffc008f8ae00 (console_lock){+.+.}-{0:0}, at:
printk_activate_kthreads+0x10/0x54
#1: ffffffc009da4a28 (&meta->lock){....}-{2:2}, at:
__kfence_alloc+0x378/0x5c4
stack backtrace:
CPU: 0 PID: 1 Comm: swapper/0 Not tainted
5.19.0-rc1-ebisu-00802-g06a0dd60d6e4 #431
Hardware name: Renesas Ebisu-4D board based on r8a77990 (DT)
Call trace:
dump_backtrace.part.0+0x98/0xc0
show_stack+0x14/0x28
dump_stack_lvl+0xac/0xec
dump_stack+0x14/0x2c
__lock_acquire+0x388/0x10a0
lock_acquire+0x190/0x2c0
_raw_spin_lock_irqsave+0x6c/0x94
crng_make_state+0x148/0x1e4
_get_random_bytes.part.0+0x4c/0xe8
get_random_u32+0x4c/0x140
__kfence_alloc+0x460/0x5c4
kmem_cache_alloc_trace+0x194/0x1dc
__kthread_create_on_node+0x5c/0x1a8
kthread_create_on_node+0x58/0x7c
printk_start_kthread.part.0+0x34/0xa8
printk_activate_kthreads+0x4c/0x54
do_one_initcall+0xec/0x278
kernel_init_freeable+0x11c/0x214
kernel_init+0x24/0x124
ret_from_fork+0x10/0x20
rcu: Hierarchical SRCU implementation.
printk: console [tty0] printing thread started
EFI services will not be available.
smp: Bringing up secondary CPUs ...
Detected VIPT I-cache on CPU1
CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
smp: Brought up 1 node, 2 CPUs
SMP: Total of 2 processors activated.

> ---------------- BEGIN PATCH ---------------
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 2311a0ad584a..c4362d25de22 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -3837,7 +3837,7 @@ static int __init printk_activate_kthreads(void)
>
> return 0;
> }
> -early_initcall(printk_activate_kthreads);
> +late_initcall(printk_activate_kthreads);
>
> #if defined CONFIG_PRINTK
> /* If @con is specified, only wait for that console. Otherwise wait for all. */
> ---------------- END PATCH ---------------

Doesn't seem to make much of a difference, only a slightly different
backtrace, compared to the above:

Mount-cache hash table entries: 4096 (order: 3, 32768 bytes, linear)
Mountpoint-cache hash table entries: 4096 (order: 3, 32768 bytes, linear)
+rcu: Hierarchical SRCU implementation.

=============================
[ BUG: Invalid wait context ]
-5.19.0-rc1-ebisu-00802-g06a0dd60d6e4 #431 Not tainted
+5.19.0-rc1-ebisu-00802-g06a0dd60d6e4-dirty #433 Not tainted
-----------------------------
swapper/0/1 is trying to lock:
ffffffc00910bac8 (base_crng.lock){....}-{3:3}, at:
crng_make_state+0x148/0x1e4
other info that might help us debug this:
context-{5:5}
-2 locks held by swapper/0/1:
- #0: ffffffc008f8ae00 (console_lock){+.+.}-{0:0}, at:
printk_activate_kthreads+0x10/0x54
- #1: ffffffc009da4a28 (&meta->lock){....}-{2:2}, at:
__kfence_alloc+0x378/0x5c4
+1 lock held by swapper/0/1:
+ #0: ffffffc009da4a28 (&meta->lock){....}-{2:2}, at:
__kfence_alloc+0x378/0x5c4
stack backtrace:
-CPU: 0 PID: 1 Comm: swapper/0 Not tainted
5.19.0-rc1-ebisu-00802-g06a0dd60d6e4 #431
+CPU: 0 PID: 1 Comm: swapper/0 Not tainted
5.19.0-rc1-ebisu-00802-g06a0dd60d6e4-dirty #433
Hardware name: Renesas Ebisu-4D board based on r8a77990 (DT)
Call trace:
dump_backtrace.part.0+0x98/0xc0
@@ -33,20 +32,14 @@ Call trace:
kmem_cache_alloc_trace+0x194/0x1dc
__kthread_create_on_node+0x5c/0x1a8
kthread_create_on_node+0x58/0x7c
- printk_start_kthread.part.0+0x34/0xa8
- printk_activate_kthreads+0x4c/0x54
+ rcu_spawn_gp_kthread+0x54/0x208
do_one_initcall+0xec/0x278
kernel_init_freeable+0x11c/0x214
kernel_init+0x24/0x124
ret_from_fork+0x10/0x20
-rcu: Hierarchical SRCU implementation.
-printk: console [tty0] printing thread started
EFI services will not be available.
smp: Bringing up secondary CPUs ...
Detected VIPT I-cache on CPU1
...
+printk: console [tty0] printing thread started

Gr{oetje,eeting}s,

Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@xxxxxxxxxxxxxx

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
-- Linus Torvalds