Re: NMIs reported by console_blast.sh with 6.6.20-rt25

[Sebastian Andrzej Siewior <bigeasy@linutronix.de>]

On 2024-03-15 15:21:19 [-0400], John B. Wyatt IV wrote:
> Hello John,
Hi John B.,

> The real-time team at Red Hat is discussing backporting the rt patchset in 6.6
> to RHEL 9/Stream 9. I decided to test v6.6.20-rt25 from stable-rt with
> console_blast.sh. It reported similar NMIs from my testing of 6.7.0-rt6 with
> that high cpu count server over uart 8250; which is expected since the patchset
> is similar.
> 
> One interesting thing is that 6.7.0-rt6 fully preemptive + realtime tuned profile
> did not return any NMIs while 6.6 did with that same configuration.

The thing is that console_blast.sh does this "show a backtrace on all
CPUs, please" which triggers NMIs on all CPUs for backtrace. I can't
imagine how you did obtain the backtraces without an NMI. Unless the
tuned profile disables this somehow.

> Another aspect I noticed during my testing. I did not set grub to
> start with the realtime profile at boot for this machine. When I did set
> it the second (and latter) NMI did not show for fully preemptive (the
> 3rd set at the bottom of this email). 
> 
> Caller info was enabled. No modifications to the source code were made.
> 
> I have not tested previous versions before 6.7.0-rt6 or 6.6.20-rt25;
> with the exception of accidently testing 6.6.10-rt19. 6.6.10 also
> reported NMIs during this test. If you wish to see these reports please
> let me know.

This NMI part has nothing todo with printk. If you need this clarified,
I would need a reproducer.

…
> -----------------------------
> NMI Backtrace for 6.6.20-rt25 no forced preemption with tuned realtime profile
> -----------------------------
> 
> [ T2614] Kernel panic - not syncing: sysrq triggered crash
> [   C56] NMI backtrace for cpu 56
> [   C56] Hardware name: Intel Corporation D50DNP1SBB/D50DNP1SBB, BIOS SE5C7411.86B.9409.D04.2212261349 12/26/2022
> [ C56] RIP: 0010:io_serial_out (arch/x86/kernel/early_printk.c:105) 
> [ C56] Code: 0f 1f 00 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 90 0f 1f 44 00 00 0f b6 8f c1 00 00 00 89 d0 0f b7 57 08 d3 e6 01 f2 ee <c3> cc cc cc cc 0f 1f 40 00 90 90 90 90 90 90 90 90 90 90 90 90 90
> All code
> =======
…
>   12:	90                   	nop
>   13:	0f 1f 44 00 00       	nopl   0x0(%rax,%rax,1)
>   18:	0f b6 8f c1 00 00 00 	movzbl 0xc1(%rdi),%ecx
>   1f:	89 d0                	mov    %edx,%eax
>   21:	0f b7 57 08          	movzwl 0x8(%rdi),%edx
>   25:	d3 e6                	shl    %cl,%esi
>   27:	01 f2                	add    %esi,%edx
>   29:	ee                   	out    %al,(%dx)
>   2a:*	c3                   	ret		<-- trapping instruction

where is this output from? The `ret' opcode usually does not cause a
trap. My guess is that the machine has been interrupted by an external
user at this position.
Side note: This is using early_printk, correct?
…

> [   C56] Call Trace:
> [   C56]  <NMI>
> [ C56] ? nmi_cpu_backtrace (lib/nmi_backtrace.c:115) 
> [ C56] ? nmi_cpu_backtrace_handler (arch/x86/kernel/apic/hw_nmi.c:47 (discriminator 1)) 
> [ C56] ? nmi_handle (arch/x86/kernel/nmi.c:149) 
> [ C56] ? io_serial_out (arch/x86/kernel/early_printk.c:105) 
> [ C56] ? default_do_nmi (arch/x86/kernel/nmi.c:347) 
> [ C56] ? exc_nmi (arch/x86/kernel/nmi.c:538) 
> [ C56] ? end_repeat_nmi (arch/x86/entry/entry_64.S:1458) 
> [ C56] ? io_serial_out (arch/x86/kernel/early_printk.c:105) 
> [ C56] ? io_serial_out (arch/x86/kernel/early_printk.c:105) 
> [ C56] ? io_serial_out (arch/x86/kernel/early_printk.c:105) 
> [   C56]  </NMI>

This looks okay. The NMI did the backtrace as expected.

> [   C56]  <TASK>
> [ C56] serial8250_console_putchar (./include/linux/serial_core.h:704 drivers/tty/serial/8250/8250_port.c:3347) 
> [ C56] ? __pfx_serial8250_console_putchar (drivers/tty/serial/8250/8250_port.c:3343) 
> [ C56] uart_console_write (drivers/tty/serial/serial_core.c:2134) 
> [ C56] serial8250_console_write_atomic (drivers/tty/serial/8250/8250_port.c:3628) 
> [ C56] nbcon_emit_next_record (kernel/printk/nbcon.c:940) 
> [ C56] __nbcon_atomic_flush_all (kernel/printk/nbcon.c:1192 (discriminator 1) kernel/printk/nbcon.c:1326 (discriminator 1)) 
> [ C56] vprintk_emit (kernel/printk/printk.c:2414) 
> [ C56] _printk (kernel/printk/printk.c:2474) 
> [ C56] panic (./arch/x86/include/asm/bitops.h:207 ./arch/x86/include/asm/bitops.h:239 ./include/asm-generic/bitops/instrumented-non-atomic.h:142 kernel/panic.c:528 kernel/panic.c:339) 
> [ C56] ? _printk (kernel/printk/printk.c:2474) 
> [ C56] sysrq_handle_crash (drivers/tty/sysrq.c:154) 
> [ C56] __handle_sysrq (drivers/tty/sysrq.c:601) 
> [ C56] write_sysrq_trigger (drivers/tty/sysrq.c:1165) 
> [ C56] proc_reg_write (fs/proc/inode.c:340 fs/proc/inode.c:352) 
> [ C56] ? preempt_count_add (./include/linux/ftrace.h:974 (discriminator 1) kernel/sched/core.c:5847 (discriminator 1) kernel/sched/core.c:5844 (discriminator 1) kernel/sched/core.c:5872 (discriminator 1)) 
> [ C56] vfs_write (fs/read_write.c:582) 
> [ C56] ksys_write (fs/read_write.c:637) 
> [ C56] do_syscall_64 (arch/x86/entry/common.c:51 arch/x86/entry/common.c:81) 
> [ C56] ? do_dup2 (fs/file.c:1142) 
> [ C56] ? syscall_exit_to_user_mode (kernel/entry/common.c:299) 
> [ C56] ? do_syscall_64 (arch/x86/entry/common.c:88) 
> [ C56] ? exc_page_fault (./arch/x86/include/asm/irqflags.h:37 ./arch/x86/include/asm/irqflags.h:72 arch/x86/mm/fault.c:1513 arch/x86/mm/fault.c:1561) 
> [ C56] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120) 

According to this, someone issued a `crash' via sysrq. Why?

…
> [ T2614] ---[ end Kernel panic - not syncing: sysrq triggered crash ]---
yes exactly.
…
> NMI Backtrace for 6.6.20-rt25 no forced preemption with tuned throughput-performance profile
> -----------------------------

This and the following backtrace shows the same picture: The CPU is
crashing due to proc/sysrq request and does CPU-backtraces via NMI and
polls in early_printk, waiting for the UART to become idle (probably).

I don't see an issue here so far.

…
> -- 
> Sincerly,
> John Wyatt
> Software Engineer, Core Kernel

Sebastian