Re: [RFC 0/1] serial: 8250: nbcon_atomic_flush_pending() might trigger watchdog warnigns

John Ogness
2025-08-25T11:00:29Z

On 2025-08-22, Petr Mladek <pmladek@suse.com> wrote:
> Hi,
>
> this is a followup for the patchset which converted serial 8250
> console driver to nbcon [1]. It was added into upstream but
> the last two patches were later reverted because they caused
> regressions.
>
> We have seen the following hardlockup report when using the converted
> serial 8250 console driver:
>
> [ 0.000000][ T0] Command line: elfcorehdr=0x145f000000 mitigations=auto security=selinux selinux=1 console=ttyS0,115200 earlyprintk=ttyS0,115200 ignore_loglevel panic=13 intel_iommu=on sysrq=yes reset_devices acpi_no_memhotplug cgroup_disable=memory nokaslr numa=off irqpoll nr_cpus=4 root=kdump rootflags=bind rd.udev.children-max=8 disable_cpu_apicid=0
> [...]
> [ 3.771531][ T1] pci 0000:3e:08.1: [8086:324
> ** replaying previous printk message **
> [ 3.771531][ T1] pci 0000:3e:08.1: [8086:3246] type 00 class 0x088000 PCIe Root Complex Integrated Endpoint
> [ ... more than 2000 lines, about 200kB messages ... ]
> [ 3.837752][ T1] pci 0000:20:01.0: Adding to iommu group 18
> [ 3.837851][ T
> ** replaying previous printk message **
> [ 3.837851][ T1] pci 0000:20:03.0: Adding to iommu group 19
> [ 3.837946][ T1] pci 0000:20:05.0: Adding to iommu group 20
> [ ... more than 500 messages for iommu groups 21-590 ...]
> [ 3.912932][ T1] pci 0000:f6:00.1: Adding to iommu group 591
> [ 3.913070][ T1] pci 0000:f6:00.2: Adding to iommu group 592
> [ 3.913243][ T1] DMAR: Intel(R) Virtualization Technology for Directed I/O
> [ 3.913245][ T1] PCI-DMA: Using software bounce buffering for IO (SWIOTLB)
> [ 3.913245][ T1] software IO TLB: mapped [mem 0x000000004f000000-0x0000000053000000] (64MB)
> [ 3.913324][ T1] RAPL PMU: API unit is 2^-32 Joules, 3 fixed counters, 655360 ms ovfl timer
> [ 3.913325][ T1] RAPL PMU: hw unit of domain package 2^-14 Joules
> [ 3.913326][ T1] RAPL PMU: hw unit of domain dram 2^-14 Joules
> [ 3.913327][ T1] RAPL PMU: hw unit of domain psys 2^-0 Joules
> [ 3.933486][ T1] ------------[ cut here ]------------
> [ 3.933488][ T1] WARNING: CPU: 2 PID: 1 at arch/x86/events/intel/uncore.c:1156 uncore_pci_pmu_register+0x15e/0x180
> [ 3.930291][ C0] watchdog: Watchdog detected hard LOCKUP on cpu 0
> [ 3.930291][ C0] Modules linked in:
> [ 3.930291][ C0] Supported: No, Unreleased kernel
> [ 3.930291][ C0] CPU: 0 UID: 0 PID: 18 Comm: pr/ttyS0 Not tainted 6.12.0-160000.18-default #1 PREEMPT(voluntary) SLFO-1.2 (unreleased) dd174c2cca19586eee16eaccfeba02f4d5b57c67
> [ 3.930291][ C0] Hardware name: HPE ProLiant DL560 Gen11/ProLiant DL560 Gen11, BIOS 2.48 03/11/2025
> [ 3.930291][ C0] RIP: 0010:nbcon_reacquire_nobuf+0x11/0x50
> [ 3.930291][ C0] Code: 2e 0f 1f 84 00 00 00 00 00 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 f3 0f 1e fa 0f 1f 44 00 00 53 48 89 fb eb 02 f3 90 <48> 89 df e8 b7 fc ff ff 84 c0 74 f2 48 8b 03 48 c7 43 28 00 00 00
> [ 3.930291][ C0] RSP: 0000:ffa0000000147d38 EFLAGS: 00000046
> [ 3.930291][ C0] RAX: 0000000000000000 RBX: ffa0000000147e78 RCX: 0000000000000001
> [ 3.930291][ C0] RDX: 0000000000000000 RSI: 0000000000000001 RDI: ffa0000000147e78
> [ 3.930291][ C0] RBP: ffa0000000147e78 R08: 0000000000000010 R09: 0000000000000000
> [ 3.930291][ C0] R10: 312e38303a65333a R11: 3030303020696370 R12: ff1100145f53f032
> [ 3.930291][ C0] R13: 0000000000000000 R14: ff1100145f53f032 R15: ff1100145f53f072
> [ 3.930291][ C0] FS: 0000000000000000(0000) GS:ff1100147ea00000(0000) knlGS:0000000000000000
> [ 3.930291][ C0] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 3.930291][ C0] CR2: ff1100147e402000 CR3: 000000147d238001 CR4: 0000000000f71ef0
> [ 3.930291][ C0] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [ 3.930291][ C0] DR3: 0000000000000000 DR6: 00000000fffe07f0 DR7: 0000000000000400
> [ 3.930291][ C0] PKRU: 55555554
> [ 3.930291][ C0] Call Trace:
> [ 3.930291][ C0] <NMI>
> [ 3.930291][ C0] ? watchdog_hardlockup_check.cold+0xe7/0xec
> [ 3.930291][ C0] ? __perf_event_overflow+0x11b/0x380
> [ 3.930291][ C0] ? handle_pmi_common+0x15c/0x3d0
> [ 3.930291][ C0] ? intel_pmu_handle_irq+0x10f/0x5b0
> [ 3.930291][ C0] ? perf_event_nmi_handler+0x2a/0x50
> [ 3.930291][ C0] ? nmi_handle+0x5e/0x120
> [ 3.930291][ C0] ? default_do_nmi+0x40/0x130
> [ 3.930291][ C0] ? exc_nmi+0x187/0x240
> [ 3.930291][ C0] ? end_repeat_nmi+0xf/0x53
> [ 3.930291][ C0] ? nbcon_reacquire_nobuf+0x11/0x50
> [ 3.930291][ C0] ? nbcon_reacquire_nobuf+0x11/0x50
> [ 3.930291][ C0] ? nbcon_reacquire_nobuf+0x11/0x50
> [ 3.930291][ C0] </NMI>
> [ 3.930291][ C0] <TASK>
> [ 3.930291][ C0] serial8250_console_write+0x16d/0x5c0
> [ 3.930291][ C0] ? asm_sysvec_apic_timer_interrupt+0x1a/0x20
> [ 3.930291][ C0] nbcon_emit_next_record+0x22c/0x250
> [ 3.930291][ C0] nbcon_emit_one+0x93/0xe0
> [ 3.930291][ C0] nbcon_kthread_func+0x13c/0x1c0
> [ 3.930291][ C0] ? __pfx_nbcon_kthread_func+0x10/0x10
> [ 3.930291][ C0] kthread+0xcd/0x110
> [ 3.930291][ C0] ? __pfx_kthread+0x10/0x10
> [ 3.930291][ C0] ret_from_fork+0x31/0x50
> [ 3.930291][ C0] ? __pfx_kthread+0x10/0x10
> [ 3.930291][ C0] ret_from_fork_asm+0x1a/0x30
> [ 3.930291][ C0] </TASK>
> [ 3.930291][ C0] Kernel panic - not syncing: Hard LOCKUP
> [ 3.930291][ C0] CPU: 0 UID: 0 PID: 18 Comm: pr/ttyS0 Not tainted 6.12.0-160000.18-default #1 PREEMPT(voluntary) SLFO-1.2 (unreleased) dd174c2cca19586eee16eaccfeba02f4d5b57c67
> [ 3.930291][ C0] Hardware name: HPE ProLiant DL560 Gen11/ProLiant DL560 Gen11, BIOS 2.48 03/11/2025
> [ 3.930291][ C0] Call Trace:
> [ 3.930291][ C0] <NMI>
> [ 3.930291][ C0] dump_stack_lvl+0x4b/0x70
> [ 3.930291][ C0] panic+0x106/0x2d3
> [ 3.930291][ C0] nmi_panic.cold+0xc/0xc
> [ 3.930291][ C0] watchdog_hardlockup_check.cold+0xca/0xec
> [ 3.930291][ C0] __perf_event_overflow+0x11b/0x380
> [ 3.930291][ C0] handle_pmi_common+0x15c/0x3d0
> [ 3.930291][ C0] intel_pmu_handle_irq+0x10f/0x5b0
> [ 3.930291][ C0] perf_event_nmi_handler+0x2a/0x50
> [ 3.930291][ C0] nmi_handle+0x5e/0x120
> [ 3.930291][ C0] default_do_nmi+0x40/0x130
> [ 3.930291][ C0] exc_nmi+0x187/0x240
> [ 3.930291][ C0] end_repeat_nmi+0xf/0x53
> [ 3.930291][ C0] RIP: 0010:nbcon_reacquire_nobuf+0x11/0x50
> [ 3.930291][ C0] Code: 2e 0f 1f 84 00 00 00 00 00 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 f3 0f 1e fa 0f 1f 44 00 00 53 48 89 fb eb 02 f3 90 <48> 89 df e8 b7 fc ff ff 84 c0 74 f2 48 8b 03 48 c7 43 28 00 00 00
> [ 3.930291][ C0] RSP: 0000:ffa0000000147d38 EFLAGS: 00000046
> [ 3.930291][ C0] RAX: 0000000000000000 RBX: ffa0000000147e78 RCX: 0000000000000001
> [ 3.930291][ C0] RDX: 0000000000000000 RSI: 0000000000000001 RDI: ffa0000000147e78
> [ 3.930291][ C0] RBP: ffa0000000147e78 R08: 0000000000000010 R09: 0000000000000000
> [ 3.930291][ C0] R10: 312e38303a65333a R11: 3030303020696370 R12: ff1100145f53f032
> [ 3.930291][ C0] R13: 0000000000000000 R14: ff1100145f53f032 R15: ff1100145f53f072
> [ 3.930291][ C0] ? nbcon_reacquire_nobuf+0x11/0x50
> [ 3.930291][ C0] ? nbcon_reacquire_nobuf+0x11/0x50
> [ 3.930291][ C0] </NMI>
> [ 3.930291][ C0] <TASK>
> [ 3.930291][ C0] serial8250_console_write+0x16d/0x5c0
> [ 3.930291][ C0] ? asm_sysvec_apic_timer_interrupt+0x1a/0x20
> [ 3.930291][ C0] nbcon_emit_next_record+0x22c/0x250
> [ 3.930291][ C0] nbcon_emit_one+0x93/0xe0
> [ 3.930291][ C0] nbcon_kthread_func+0x13c/0x1c0
> [ 3.930291][ C0] ? __pfx_nbcon_kthread_func+0x10/0x10
> [ 3.930291][ C0] kthread+0xcd/0x110
> [ 3.930291][ C0] ? __pfx_kthread+0x10/0x10
> [ 3.930291][ C0] ret_from_fork+0x31/0x50
> [ 3.930291][ C0] ? __pfx_kthread+0x10/0x10
> [ 3.930291][ C0] ret_from_fork_asm+0x1a/0x30
> [ 3.930291][ C0] </TASK>
> [ 3.930291][ C0] Shutting down cpus with NMI
> [ 3.930291][ C0] Rebooting in 13 seconds..
>
>
> There are clearly visible two points where nbcon_atomic_flush_pending()
> took over the ownership from a lover priority context. I believe that:
>
> + 1st occurrence is triggered by the "WARNING: CPU: 2 PID: 1 at
> arch/x86/..." line printed with NBCON_PRIO_EMERGENCY.
>
> + 2nd occurrence is triggered by the "Kernel panic - not syncing:
> Hard LOCKUP" line printed with NBCON_PRIO_PANIC.
>
> There were flushed more than 2500lines, about 240kB of characters,
> in the NBCON_PRIO_EMERGENCY before the hardlockup detector
> triggered panic.
>
> If I count it correctly, a serial console with the speed 115200 baud/sec
> would be able to emit about 11.5kB/sec. And it would take about 20sec
> to emit the 240kB of messages.
>
> => softlockup is quite realistic
>
> Solution:
>
> IMHO, we really should flush all pending messages atomically.
> It means that the watchdog reports need to be prevented
> by touching the watchdog. It is not needed in
> univ8250_console_write_thread()
>
> => put back touch_nmi_watchdog() into univ8250_console_write_atomic().

I would expect the touch_nmi_watchdog() within wait_for_lsr() to be
sufficient. After all, that is the loop that leads to the large emit
times.

For QEMU, the touch_nmi_watchdog() within wait_for_lsr() will never be
called because QEMU does not implement baud rates. So that may be reason
enough to accept this change.

John

> [1] https://lore.kernel.org/r/20250107212702.169493-1-john.ogness@linutronix.de