On Tue, Jan 24, 2023 at 05:30:29PM +0000, Mark Rutland wrote:
> On Tue, Jan 24, 2023 at 04:34:23PM +0000, Mark Rutland wrote:
> > Hi Peter,
> >
> > On Mon, Jan 23, 2023 at 09:50:09PM +0100, Peter Zijlstra wrote:
> > > 0-day robot reported graph-tracing made the cpuidle-vs-rcu rework go splat.
> >
> > Do you have a link toe the splat somewhere?
> >
> > I'm assuming that this is partially generic, and I'd like to make sure I test
> > the right thing on arm64. I'll throw my usual lockdep options at the ftrace
> > selftests...
>
> Hmm... with the tip sched/core branch, with or without this series applied atop
> I see a couple of splats which I don't see with v6.2-rc1 (which seems to be
> entirely clean). I'm not seeing any other splats.
>
> I can trigger those reliably with the 'toplevel-enable.tc' ftrace test:
>
> ./ftracetest test.d/event/toplevel-enable.tc
>
> Splats below; I'll dig into this a bit more tomorrow.
>
> [ 65.729252] ------------[ cut here ]------------
> [ 65.730397] WARNING: CPU: 3 PID: 1162 at include/trace/events/preemptirq.h:55 trace_preempt_on+0x68/0x70
The line number here is a bit inscrutible, but a bisect led me down to commit
408b961146be4c1a ("tracing: WARN on rcuidle")
... and it appears this must be the RCUIDLE_COND() warning that adds, and that
seems to be because trace_preempt_on() calls trace_preempt_enable_rcuidle():
| void trace_preempt_on(unsigned long a0, unsigned long a1)
| {
| if (!in_nmi())
| trace_preempt_enable_rcuidle(a0, a1);
| tracer_preempt_on(a0, a1);
| }
It looks like that tracing is dependend upon CONFIG_TRACE_PREEMPT_TOGGLE, and I
have that because I enabled CONFIG_PREEMPT_TRACER. I reckon the same should
happen on x86 with CONFIG_PREEMPT_TRACER=y.
IIUC we'll need to clean up that trace_.*_rcuidle() usage too, but I'm not
entirely sure how to do that.
Thanks,
Mark.
> [ 65.732450] Modules linked in:
> [ 65.733204] CPU: 3 PID: 1162 Comm: ftracetest Not tainted 6.2.0-rc1-00100-g1066815869f5 #2
> [ 65.735165] Hardware name: linux,dummy-virt (DT)
> [ 65.736278] pstate: 40400005 (nZcv daif +PAN -UAO -TCO -DIT -SSBS BTYPE=--)
> [ 65.737929] pc : trace_preempt_on+0x68/0x70
> [ 65.738962] lr : preempt_count_sub+0xb4/0xf0
> [ 65.739998] sp : ffff80000e03ba70
> [ 65.740818] x29: ffff80000e03ba70 x28: ffff80000add07e8 x27: ffff800009d0b548
> [ 65.742531] x26: ffff00000742dd10 x25: ffff00000742dd00 x24: ffff80000ade11d0
> [ 65.744246] x23: ffff80000e03bb80 x22: ffff80000a99abb0 x21: ffff8000080a5cf4
> [ 65.745957] x20: ffff8000080a5cf4 x19: 0000000000000001 x18: 0000000000000000
> [ 65.747677] x17: 0000000000000000 x16: 0000000000000000 x15: 0000000000000000
> [ 65.749388] x14: 0000000000000028 x13: 00000000000042d7 x12: 000000000000035f
> [ 65.751105] x11: 000000000000035f x10: 000000000004035f x9 : ffff8000080a5cf4
> [ 65.752820] x8 : ffff80000ae31a18 x7 : 0000000000000000 x6 : 0000000000000001
> [ 65.754526] x5 : ffff80000a8e14e8 x4 : 0000000000000003 x3 : 0000000000000000
> [ 65.756244] x2 : 0000000000000001 x1 : ffff8000080a5cf4 x0 : ffff8000080a5cf4
> [ 65.757957] Call trace:
> [ 65.758572] trace_preempt_on+0x68/0x70
> [ 65.759520] preempt_count_sub+0xb4/0xf0
> [ 65.760477] percpu_up_read.constprop.0+0xc4/0x180
> [ 65.761639] cpus_read_unlock+0x18/0x24
> [ 65.762579] static_key_enable+0x2c/0x40
> [ 65.763572] tracepoint_add_func+0x330/0x3dc
> [ 65.764611] tracepoint_probe_register+0x74/0xc0
> [ 65.765725] trace_event_reg+0x8c/0xa0
> [ 65.766642] __ftrace_event_enable_disable+0x174/0x4d0
> [ 65.767884] __ftrace_set_clr_event_nolock+0xe0/0x150
> [ 65.769109] ftrace_set_clr_event+0x90/0x13c
> [ 65.770143] ftrace_event_write+0xd4/0x120
> [ 65.771145] vfs_write+0xcc/0x2f0
> [ 65.771964] ksys_write+0x78/0x110
> [ 65.772803] __arm64_sys_write+0x24/0x30
> [ 65.773763] invoke_syscall+0x50/0x120
> [ 65.774681] el0_svc_common.constprop.0+0x68/0x124
> [ 65.775848] do_el0_svc+0x40/0xbc
> [ 65.776669] el0_svc+0x48/0xc0
> [ 65.777426] el0t_64_sync_handler+0xf4/0x120
> [ 65.778459] el0t_64_sync+0x190/0x194
> [ 65.779365] irq event stamp: 69686
> [ 65.780199] hardirqs last enabled at (69685): [<ffff8000092d5664>] _raw_spin_unlock_irqrestore+0x80/0xa0
> [ 65.782457] hardirqs last disabled at (69686): [<ffff8000092c3fd4>] el1_dbg+0x24/0x90
> [ 65.784315] softirqs last enabled at (69622): [<ffff800008010b08>] __do_softirq+0x448/0x5bc
> [ 65.786309] softirqs last disabled at (69613): [<ffff800008017288>] ____do_softirq+0x18/0x24
> [ 65.788332] ---[ end trace 0000000000000000 ]---
> [ 65.789588] ------------[ cut here ]------------
> [ 65.790622] WARNING: CPU: 3 PID: 1162 at include/trace/events/preemptirq.h:51 trace_preempt_off+0x68/0xb0
> [ 65.792698] Modules linked in:
> [ 65.793465] CPU: 3 PID: 1162 Comm: ftracetest Tainted: G W 6.2.0-rc1-00100-g1066815869f5 #2
> [ 65.795780] Hardware name: linux,dummy-virt (DT)
> [ 65.796898] pstate: 40400005 (nZcv daif +PAN -UAO -TCO -DIT -SSBS BTYPE=--)
> [ 65.798555] pc : trace_preempt_off+0x68/0xb0
> [ 65.799602] lr : preempt_count_add+0xa0/0xc0
> [ 65.800646] sp : ffff80000e03ba80
> [ 65.801465] x29: ffff80000e03ba80 x28: ffff80000add07e8 x27: ffff800009d0b558
> [ 65.803185] x26: ffff00000742dd90 x25: ffff00000742dd80 x24: ffff80000ade1188
> [ 65.804900] x23: ffff80000e03bb80 x22: ffff80000a99abb0 x21: ffff80000b8b7d18
> [ 65.806612] x20: ffff8000080a5c68 x19: ffff8000080a5c68 x18: 0000000000000000
> [ 65.808334] x17: 0000000000000000 x16: 0000000000000000 x15: 0000000000000000
> [ 65.810041] x14: 0000000000000028 x13: 00000000000042d7 x12: 000000000000035f
> [ 65.811755] x11: 000000000000035f x10: 000000000004035f x9 : ffff8000080a5c68
> [ 65.813460] x8 : ffff80000ae31a18 x7 : 0000000000000000 x6 : 0000000000000003
> [ 65.815174] x5 : 0000000030b5c3ca x4 : 0000000000000003 x3 : 0000000000000000
> [ 65.816886] x2 : 0000000000000001 x1 : ffff8000080a5c68 x0 : ffff8000080a5c68
> [ 65.818592] Call trace:
> [ 65.819216] trace_preempt_off+0x68/0xb0
> [ 65.820171] preempt_count_add+0xa0/0xc0
> [ 65.821131] percpu_up_read.constprop.0+0x38/0x180
> [ 65.822288] cpus_read_unlock+0x18/0x24
> [ 65.823236] static_key_enable+0x2c/0x40
> [ 65.824194] tracepoint_add_func+0x330/0x3dc
> [ 65.825236] tracepoint_probe_register+0x74/0xc0
> [ 65.826351] trace_event_reg+0x8c/0xa0
> [ 65.827276] __ftrace_event_enable_disable+0x174/0x4d0
> [ 65.828506] __ftrace_set_clr_event_nolock+0xe0/0x150
> [ 65.829721] ftrace_set_clr_event+0x90/0x13c
> [ 65.830769] ftrace_event_write+0xd4/0x120
> [ 65.831766] vfs_write+0xcc/0x2f0
> [ 65.832581] ksys_write+0x78/0x110
> [ 65.833422] __arm64_sys_write+0x24/0x30
> [ 65.834376] invoke_syscall+0x50/0x120
> [ 65.835300] el0_svc_common.constprop.0+0x68/0x124
> [ 65.836451] do_el0_svc+0x40/0xbc
> [ 65.837290] el0_svc+0x48/0xc0
> [ 65.838054] el0t_64_sync_handler+0xf4/0x120
> [ 65.839102] el0t_64_sync+0x190/0x194
> [ 65.840006] irq event stamp: 69710
> [ 65.840845] hardirqs last enabled at (69709): [<ffff8000092c4028>] el1_dbg+0x78/0x90
> [ 65.842699] hardirqs last disabled at (69710): [<ffff8000092c3fd4>] el1_dbg+0x24/0x90
> [ 65.844568] softirqs last enabled at (69694): [<ffff800008010b08>] __do_softirq+0x448/0x5bc
> [ 65.846573] softirqs last disabled at (69689): [<ffff800008017288>] ____do_softirq+0x18/0x24
> [ 65.848578] ---[ end trace 0000000000000000 ]---
>
> Thanks,
> Mark.
