Re: printk NMI splat on boot

[John Ogness <john.ogness@linutronix.de>]

Added Cc: Paul E. McKenney <paulmck@kernel.org>

Hi Jens,

On 2025-05-20, Jens Axboe <axboe@kernel.dk> wrote:
> This has been going on for a while, and finally getting around to
> reporting it. For every boot on my Dell R7625, I get one of these:

Is it possible that you could compile with:

CONFIG_PRINTK_TIME=y
CONFIG_PRINTK_CALLER=y

so that we can see some timestamps and from which CPU the printk calls
are originating from?

> bnxt_en 0000:01:00.2 eno12419np2: renamed from eth2
> usb 1-1.2: new low-speed USB device number 3 using xhci_hcd
> usb 1-1.2: New USB device found, idVendor=047b, idProduct=0011, bcdDevice= 1.00
> usb 3-1: New USB device found, idVendor=1604, idProduct=10c0, bcdDevice= 0.00
> usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
> rcu: INFO: rcu_sched detected expedited stalls on CPUs/tasks: { 96-.... } 3 jiffies s: 53 root: 0x40/.

The expedited grace period has only been going on for 3 jiffies.

What values are you using for CONFIG_RCU_EXP_CPU_STALL_TIMEOUT and
CONFIG_RCU_CPU_STALL_TIMEOUT?

What CONFIG_*HZ* options are you using?

> rcu: blocking rcu_node structures (internal RCU debug): l=1:96-111:0x1/.
> Sending NMI from CPU 0 to CPUs 96:
> NMI backtrace for cpu 96
> CPU: 96 UID: 0 PID: 3241 Comm: kworker/96:1 Not tainted 6.15.0-rc7+ #254 NONE 
> Hardware name: Dell Inc. PowerEdge R7625/06444F, BIOS 1.11.2 12/18/2024
> Workqueue: usb_hub_wq hub_event [usbcore]
> RIP: 0010:vprintk_emit+0x360/0x430
> Code: 87 01 0f 84 91 00 00 00 c6 05 36 ec 8a 01 01 c6 05 3c ec 8a 01 00 0f b6 05 28 ec 8a 01 84 c0 74 0d f3 90 0f b6 05 1b ec 8a 01 <84> c0 75 f3 e8 47 0d 00 00 80 e7 02 74 01 fb c7 05 bb ec 8c 01 00
> RSP: 0018:ffffbe47220c7b78 EFLAGS: 00000002
> RAX: 0000000000000001 RBX: 0000000000000246 RCX: 0000000000000000
> RDX: 0000000000000000 RSI: 0000000000000002 RDI: ffffffff93019c48
> RBP: ffffbe47220c7c48 R08: 00000000fffdffff R09: ffffa1bf658fffa8
> R10: ffffa1bf64e00000 R11: 0000000000000002 R12: ffffbe47220c7be0
> R13: ffffffff9260f8ee R14: ffffbe47220c7c58 R15: 0000000000000043
> FS:  0000000000000000(0000) GS:ffffa14dd4a34000(0000) knlGS:0000000000000000
> CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 0000561066512398 CR3: 00000090a0a11002 CR4: 0000000000370ef0
> Call Trace:
>  <TASK>
>  dev_vprintk_emit+0x130/0x140
>  dev_printk_emit+0x3e/0x40
>  ? __dev_printk+0x2d/0x70
>  _dev_info+0x5c/0x5e
>  usb_new_device.cold+0x87/0x3a0 [usbcore]
>  hub_event+0x1113/0x1900 [usbcore]
>  ? __schedule+0x4e5/0xaf0
>  process_one_work+0x140/0x2b0
>  worker_thread+0x2ea/0x430
>  ? process_one_work+0x2b0/0x2b0
>  kthread+0xd4/0x1d0
>  ? kthreads_online_cpu+0xf0/0xf0
>  ret_from_fork+0x2d/0x50
>  ? kthreads_online_cpu+0xf0/0xf0
>  ret_from_fork_asm+0x11/0x20
>  </TASK>
> usb 3-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
> usb 1-1.2: Product: Standard USB Keyboard 
> hub 3-1:1.0: USB hub found
> usb 1-1.2: Manufacturer: Silitek
>
> which appears to be this spin section:
>
>         /* We spin waiting for the owner to release us */
>         spin_acquire(&console_owner_dep_map, 0, 0, _THIS_IP_);
>         /* Owner will clear console_waiter on hand off */
>         while (READ_ONCE(console_waiter))
>                 cpu_relax();
>         spin_release(&console_owner_dep_map, _THIS_IP_);

This code is waiting for a CPU to finish printing a line so that it can
take over printing the next line.

If you are using CONFIG_HZ_1000 and a baud rate of 115200bps, you will
only get about 14 characters printed per jiffy. The last line
successfully printed has 68 characters and the expedited grace period
timed out after only 3 jiffies (which would be around 42 characters). So
the numbers and the timeout make sense. But why is the grace period so
short?

John Ogness