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) <[email protected]>
