[BUG] suspicious RCU usage in event_filter_pid_sched_process_fork()

[Google]

Hi,

On the latest tracing/for-next branch, I hit the following
suspicious RCU usage in event_filter_pid_sched_process_fork().
It seems that kernel_clone() calls back this event without
holding rcu_read_lock().

[37] event tracing - restricts events based on pid notrace filtering[  156.217609] 
[  156.218272] =============================
[  156.219569] WARNING: suspicious RCU usage
[  156.220887] 6.19.0-09924-g9678e53179aa #38 Not tainted
[  156.222336] -----------------------------
[  156.223481] kernel/trace/trace_events.c:1057 suspicious rcu_dereference_check() usage!
[  156.225660] 
[  156.225660] other info that might help us debug this:
[  156.225660] 
[  156.227958] 
[  156.227958] rcu_scheduler_active = 2, debug_locks = 1
[  156.229815] no locks held by ftracetest/4360.
[  156.231103] 
[  156.231103] stack backtrace:
[  156.232415] CPU: 1 UID: 0 PID: 4360 Comm: ftracetest Not tainted 6.19.0-09924-g9678e53179aa #38 PREEMPT(lazy) 
[  156.232418] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-debian-1.17.0-1 04/01/2014
[  156.232419] Call Trace:
[  156.232422]  <TASK>
[  156.232425]  dump_stack_lvl+0x67/0x90
[  156.232430]  lockdep_rcu_suspicious+0x154/0x1a0
[  156.232436]  event_filter_pid_sched_process_fork+0x9a/0xd0
[  156.232440]  kernel_clone+0x367/0x3a0
[  156.232448]  __x64_sys_clone+0x116/0x140
[  156.232454]  do_syscall_64+0x158/0x460
[  156.232457]  ? entry_SYSCALL_64_after_hwframe+0x77/0x7f
[  156.232459]  ? trace_irq_disable+0x1d/0xc0
[  156.232464]  entry_SYSCALL_64_after_hwframe+0x77/0x7f
[  156.232466] RIP: 0033:0x4697c3
[  156.232470] Code: 1f 84 00 00 00 00 00 64 48 8b 04 25 10 00 00 00 45 31 c0 31 d2 31 f6 bf 11 00 20 01 4c 8d 90 d0 02 00 00 b8 38 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 35 89 c2 85 c0 75 2c 64 48 8b 04 25 10 00 00
[  156.232472] RSP: 002b:00007ffd8a0c1d58 EFLAGS: 00000246 ORIG_RAX: 0000000000000038
[  156.232474] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00000000004697c3
[  156.232476] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000001200011
[  156.232477] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000026970990
[  156.232478] R10: 000000002696e690 R11: 0000000000000246 R12: 0000000000000001
[  156.232479] R13: 0000000026989103 R14: 0000000000000001 R15: 0000000000000000
[  156.232484]  </TASK>
[  156.232495] 
[  156.268667] =============================
[  156.269872] WARNING: suspicious RCU usage
[  156.271089] 6.19.0-09924-g9678e53179aa #38 Not tainted
[  156.272544] -----------------------------
[  156.273704] kernel/trace/trace_events.c:1060 suspicious rcu_dereference_check() usage!
[  156.275903] 
[  156.275903] other info that might help us debug this:
[  156.275903] 
[  156.278122] 
[  156.278122] rcu_scheduler_active = 2, debug_locks = 1
[  156.279962] no locks held by ftracetest/4360.
[  156.281216] 
[  156.281216] stack backtrace:
[  156.282551] CPU: 1 UID: 0 PID: 4360 Comm: ftracetest Not tainted 6.19.0-09924-g9678e53179aa #38 PREEMPT(lazy) 
[  156.282553] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-debian-1.17.0-1 04/01/2014
[  156.282555] Call Trace:
[  156.282558]  <TASK>
[  156.282560]  dump_stack_lvl+0x67/0x90
[  156.282566]  lockdep_rcu_suspicious+0x154/0x1a0
[  156.282572]  event_filter_pid_sched_process_fork+0xcd/0xd0
[  156.282576]  kernel_clone+0x367/0x3a0
[  156.282584]  __x64_sys_clone+0x116/0x140
[  156.282589]  do_syscall_64+0x158/0x460
[  156.282592]  ? entry_SYSCALL_64_after_hwframe+0x77/0x7f
[  156.282594]  ? trace_irq_disable+0x1d/0xc0
[  156.282600]  entry_SYSCALL_64_after_hwframe+0x77/0x7f
[  156.282602] RIP: 0033:0x4697c3
[  156.282606] Code: 1f 84 00 00 00 00 00 64 48 8b 04 25 10 00 00 00 45 31 c0 31 d2 31 f6 bf 11 00 20 01 4c 8d 90 d0 02 00 00 b8 38 00 00 00 0f 05 <48> 3d 00 f0 ff ff 77 35 89 c2 85 c0 75 2c 64 48 8b 04 25 10 00 00
[  156.282608] RSP: 002b:00007ffd8a0c1d58 EFLAGS: 00000246 ORIG_RAX: 0000000000000038
[  156.282610] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00000000004697c3
[  156.282611] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000001200011
[  156.282612] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000026970990
[  156.282613] R10: 000000002696e690 R11: 0000000000000246 R12: 0000000000000001
[  156.282615] R13: 0000000026989103 R14: 0000000000000001 R15: 0000000000000000
[  156.282621]  </TASK>

Thanks,

-- 
Masami Hiramatsu (Google) <mhiramat@xxxxxxxxxx>