On Thu, Jul 18, 2024 at 11:57:04AM GMT, Steven Rostedt wrote:
> On Thu, 18 Jul 2024 10:41:25 -0500
> Andrew Halaney <ahalaney@xxxxxxxxxx> wrote:
>
> > Hi,
> >
> > Recently I was made aware of an issue when running 6.10.0-rc6-rt11+
> > (with a !PREEMPT_RT config, although I'm not sure it matters here).
> >
> > Its easy to reproduce, just printk on a CPU that's coming online (I got
> > pointed to a real splat, but this suffices to reproduce).
>
> I'm more interested in the real splat. Where was the printk() that
> triggered it?
I'll be honest, I only considered this from a printk() point of view so
far and pretty much ignored the original splat (as someone else is
looking at that). Here's the original splat from a centos kernel, I have
yet to look into it other than "we took an exception prior to RCU coming
online for this CPU" and me naively thinking that printk() should work
everywhere. I'll post the splat here for now before considering it more,
but it sounds like my expectation is wrong and that if something goes
awry and needs to printk prior to the CPU coming online, then this RCU
warning is sort of expected?:
[ 13.643007] smp: Bringing up secondary CPUs ...
[ 13.644422] smpboot: x86: Booting SMP configuration:
[ 13.644431] .... node #0, CPUs: #1 #2 #3 #4 #5 #6 #7 #8 #9 #10 #11 #12 #13 #14 #15 #16 #17 #18 #19 #20 #21 #22 #23 #24 #25 #26 #27 #28 #29 #30 #31 #32 #33 #34
[ 13.680691] Callback from call_rcu_tasks_rude() invoked.
[ 13.684308] #35 #36 #37 #38 #39 #40 #41 #42 #43 #44 #45 #46 #47 #48 #49 #50 #51 #52 #53 #54 #55
[ 13.720218] .... node #1, CPUs: #56 #57 #58 #59 #60 #61 #62 #63 #64 #65 #66 #67 #68 #69 #70 #71 #72 #73 #74 #75 #76 #77 #78 #79 #80 #81 #82 #83 #84 #85 #86 #87 #88 #89 #90 #91 #92 #93 #94 #95 #96 #97 #98 #99
[ 13.783247] Callback from call_rcu_tasks() invoked.
[ 13.785941] #100 #101 #102 #103 #104 #105 #106 #107 #108 #109 #110 #111
[ 5.061942] x2apic lock mismatch between BSP and AP.
[ 5.061942] unchecked MSR access error: WRMSR to 0x83f (tried to write 0x00000000000000f6) at rIP: 0xffffffff877434d7 (native_apic_msr_write+0x27/0x40)
[ 5.061942] Call Trace:
[ 5.061942] <TASK>
[ 5.061942] ? show_trace_log_lvl+0x1c4/0x2df
[ 5.061942] ? show_trace_log_lvl+0x1c4/0x2df
[ 5.061942] ? arch_irq_work_raise+0x75/0xb0
[ 5.061942] ? native_apic_msr_write+0x27/0x40
[ 5.061942] ? ex_handler_msr.cold+0xb3/0x151
[ 5.061942] ? fixup_exception+0x8d1/0xab0
[ 5.061942] ? gp_try_fixup_and_notify+0x20/0x50
[ 5.061942] ? exc_general_protection+0xf1/0x220
[ 5.061942] ? asm_exc_general_protection+0x22/0x30
[ 5.061942] ? native_apic_msr_write+0x27/0x40
[ 5.061942] arch_irq_work_raise+0x75/0xb0
[ 5.061942] irq_work_queue+0x2f/0x50
[ 5.061942] nbcon_wake_threads+0x196/0x270
[ 5.061942] vprintk_emit+0x183/0x400
[ 5.061942] _printk+0xb2/0xe7
[ 5.061942] ? _pfx_printk+0x10/0x10
[ 5.061942] ? __pfx_lock_acquire+0x10/0x10
[ 5.061942] lockdep_rcu_suspicious+0x12d/0x200
[ 5.061942] nbcon_wake_threads+0x1e1/0x270
[ 5.061942] vprintk_emit+0x183/0x400
[ 5.061942] _printk+0xb2/0xe7
[ 5.061942] ? _pfx_printk+0x10/0x10
[ 5.061942] ? setup_ghcb+0xa/0x120
[ 5.061942] ? cpu_init_exception_handling+0x5bc/0x7a0
[ 5.061942] x2apic_setup.cold+0xc/0x11
[ 5.061942] cpu_init+0xe9/0x3a0
[ 5.061942] ? __pfx_cpu_init+0x10/0x10
[ 5.061942] start_secondary+0x6d/0x290
[ 5.061942] ? __pfx_start_secondary+0x10/0x10
[ 5.061942] ? set_bringup_idt_handler.constprop.0+0x98/0xc0
[ 5.061942] ? soft_restart_cpu+0x15/0x15
[ 5.061942] secondary_startup_64_no_verify+0x18f/0x19b
[ 5.061942] </TASK>
[ 5.061942] =============================
[ 5.061942] WARNING: suspicious RCU usage
[ 5.061942] 5.14.0-467.el9.x86_64+debug #1 Not tainted
[ 5.061942] -----------------------------
[ 5.061942] kernel/printk/nbcon.c:1118 suspicious rcu_dereference_check() usage!
[ 5.061942]
other info that might help us debug this:
[ 5.061942]
RCU used illegally from offline CPU!
rcu_scheduler_active = 1, debug_locks = 1
[ 5.061942] 2 locks held by swapper/1/0:
[ 5.061942] #0: ffffffff8b721a10 (console_srcu)
{....}-{0:0}, at: console_srcu_read_lock+0x44/0x60
[ 5.061942] #1: ffffffff8b735080 (rcu_read_lock){....}
-
{1:2}
, at: nbcon_wake_threads+0x11d/0x270
[ 5.061942]
stack backtrace:
[ 5.061942] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 5.14.0-467.el9.x86_64+debug #1
[ 5.061942] Hardware name: HPE ProLiant DL380 Gen11/ProLiant DL380 Gen11, BIOS 1.32 03/23/2023
[ 5.061942] Call Trace:
[ 5.061942] <TASK>
[ 5.061942] dump_stack_lvl+0x57/0x81
[ 5.061942] lockdep_rcu_suspicious.cold+0x96/0xfc
[ 5.061942] nbcon_wake_threads+0x1e1/0x270
[ 5.061942] vprintk_emit+0x183/0x400
[ 5.061942] _printk+0xb2/0xe7
[ 5.061942] ? _pfx_printk+0x10/0x10
[ 5.061942] ? setup_ghcb+0xa/0x120
[ 5.061942] ? cpu_init_exception_handling+0x5bc/0x7a0
[ 5.061942] x2apic_setup.cold+0xc/0x11
[ 5.061942] cpu_init+0xe9/0x3a0
[ 5.061942] ? __pfx_cpu_init+0x10/0x10
[ 5.061942] start_secondary+0x6d/0x290
[ 5.061942] ? __pfx_start_secondary+0x10/0x10
[ 5.061942] ? set_bringup_idt_handler.constprop.0+0x98/0xc0
[ 5.061942] ? soft_restart_cpu+0x15/0x15
[ 5.061942] secondary_startup_64_no_verify+0x18f/0x19b
[ 5.061942] </TASK>
[ 5.061942] numa_add_cpu cpu 1 node 0: mask now 0-1
[ 5.061942] x2apic lock mismatch between BSP and AP.
[ 5.061942] numa_add_cpu cpu 2 node 0: mask now 0-2
[ 5.061942] x2apic lock mismatch between BSP and AP.
[ 5.061942] numa_add_cpu cpu 3 node 0: mask now 0-3
[ 5.061942] x2apic lock mismatch between BSP and AP.
>
> > For example:
> >
> > diff --git a/arch/x86/kernel/smpboot.c b/arch/x86/kernel/smpboot.c
> > index 0c35207320cb..eb75a7cffe31 100644
> > --- a/arch/x86/kernel/smpboot.c
> > +++ b/arch/x86/kernel/smpboot.c
> > @@ -274,6 +274,10 @@ static void notrace start_secondary(void *unused)
> > cpuhp_ap_sync_alive();
> >
> > cpu_init();
> > +
> > + /* Let's printk() and see if RCU whines */
> > + printk(KERN_ERR "RCU, what do you think?!\n");
> > +
>
> prink() is normally OK to use on boot up before SMP starts. That's
> because it has nothing to race against. But this is the secondary CPU,
> where we are entering SMP. RCU has to be active to use pretty much
> anything (printk, tracing, etc).
>
> This is why I'm interested in knowing what the real splat was. It could
> be that it is used in an incorrect location.
>
> But if you are just debugging, then you should be safely able to ignore
> this.
Thanks for the explanation.
Please see above for the splat actual splat from a centos kernel (which
is the main reason I didn't want to send the original writeup with the
downstream splat).
Thanks,
Andrew
