Problem with nbcon console and amba-pl011 serial port

Michael Kelley
2025-06-03T03:18:25Z

I'm seeing a problem in the panic path of an ARM64 VM on Hyper-V
in the Azure public cloud. Here's the output from the VM's serial port:

# taskset -c 4 /bin/echo c >/proc/sysrq-trigger

[
** replaying previous printk message **
[ 51.616656] sysrq: Trigger a crash
[ 51.616689] Kernel panic - not syncing: sysrq triggered crash
[ 51.624212] CPU: 4 UID: 0 PID: 2278 Comm: echo Tainted: G E 6.15.0-rc7-next-20250521 #1 VOLUNTARY
[ 51.630165] Tainted: [E]=UNSIGNED_MODULE
[ 51.632331] Hardware name: Microsoft Corporation Virtual Machine/Virtual Machine, BIOS Hyper-V UEFI Release v4.1 09/28/2024
[ 51.638771] Call trace:
[ 51.640179] show_stack+0x20/0x38 (C)
[ 51.642488] dump_stack_lvl+0xc8/0xf8
[ 51.644638] dump_stack+0x18/0x28
[ 51.646654] panic+0x384/0x478
[ 51.648371] sysrq_handle_crash+0x20/0x28
[ 51.650815] __handle_sysrq+0xdc/0x2b8
[ 51.653080] write_sysrq_trigger+0x124/0x240
[ 51.655508] proc_reg_write+0xa4/0x100
[ 51.657917] vfs_write+0xd8/0x3e0
[ 51.659836] ksys_write+0x74/0x110
[ 51.661735] __arm64_sys_write+0x24/0x38
[ 51.663967] invoke_syscall+0x6c/0xf8
[ 51.666025] el0_svc_common.constprop.0+0xc8/0xf0
[ 51.668771] do_el0_svc+0x24/0x38
[ 51.670713] el0_svc+0x40/0x198
[ 51.672509] el0t_64_sync_handler+0xc8/0xd0
[ 51.675170] el0t_64_sync+0x1b0/0x1b8
[ 51.677351] SMP: stopping secondary CPUs
[ 52.728175] SMP: failed to stop secondary CPUs 2
[ 52.731229] Kernel Offset: 0x5706ebce0000 from 0xffff800080000000
[ 52.734528] PHYS_OFFSET: 0x0
[ 52.736115] CPU features: 0x2000,400007c0,02110ca1,5401faab
[ 52.739275] Memory Limit: none
[ 52.803615] ---[ end Kernel panic - not syncing: sysrq triggered crash ]---

The problem is the failure to stop secondary CPU 2. (The CPU # that fails
to stop varies from run-to-run.) It is mostly reproducible, but not always. I
bisected to commit 2eb2608618ce ("serial: amba-pl011: Implement nbcon
console") in the 6.15 kernel. Further custom logging shows the details of
why the problem can happen. Here are the steps:

1. The "echo" command ends up in __handle_sysrq(), which outputs the
"sysrq: Trigger a crash" message using pr_info(). I always ran the "echo"
command on CPU 4 just for consistency in my testing/debugging -- there's
nothing special about CPU 4.

2. The "pr/ttyAMA0" kernel thread handles the outputting of the message.
nbcon_kthread_func() calls nbcon_emit_one() with the "use_atomic" parameter
set to false. nbcon_emit_one() in turn calls nbcon_emit_next_record() with
the console spin lock held and interrupts disabled. nbcon_emit_next_record()
then calls pl011_console_write_thread(). The latter has a "for" loop to output
each character of the message, and my custom logging shows that it is indeed
outputting the string "[ 51.616656] sysrq: Trigger a crash".

3. While "pr/ttyAMA0" is doing its thing, __handle_sysrq() calls
sysrq_handle_crash(), which calls panic(). After some preliminaries, panic()
outputs the message "Kernel panic - not syncing: sysrq triggered crash"
using pr_emerg().

4. pr_emerg() has a high logging level, and it effectively steals the console
from the "pr/ttyAMA0" task, which I believe is intentional in the nbcon design.
Down in pl011_console_write_thread(), the "pr/ttyAMA0" task is doing
nbcon_enter_unsafe() and nbcon_exit_unsafe() around each character
that it outputs. When pr_emerg() steals the console, nbcon_exit_unsafe()
returns 0, so the "for" loop exits. pl011_console_write_thread() then
enters a busy "while" loop waiting to reclaim the console. It's doing this
busy "while" loop with interrupts disabled, and because of the panic,
it never succeeds. Whatever CPU is running "pr/ttyAMA0" is effectively
stuck at this point.

5. Meanwhile panic() continues, calling panic_other_cpus_shutdown(). On
ARM64, other CPUs are stopped by sending them an IPI. Each CPU receives
the IPI and calls the PSCI function to stop itself. But the CPU running
"pr/ttyAMA0" is looping forever with interrupts disabled, so it never
processes the IPI and it never stops. ARM64 doesn't have a true NMI that
can override the looping with interrupts disabled, so there's no way to
stop that CPU.

6. The failure to stop the "pr/ttyAMA0" CPU then causes downstream
problems, such as when loading and running a kdump kernel.

The problem is timing dependent. In some cases, the "pr/ttyAMA0"
thread is evidently able to get the message out before panic() calls
pr_emerg(). In my case running as a guest on Hyper-V, the pl011 device
in the guest VM is emulated by Hyper-V. Each pl011 register access
traps to the hypervisor, which slows things down and probably makes
the problem more likely. But from what I can see, the underlying
race condition exists regardless.

At this point, I just wanted to surface the problem. I don't have any
specific ideas on how to fix it, as my knowledge of nbcon is limited
to what I've learned in figuring out the failure path.

Toshiyuki -- what are your thoughts how to fix this?

Michael Kelley