suspicious RCU usage warning on tracing/urgent

suspicious RCU usage warning on tracing/urgent

[Masami Hiramatsu]

Hi Steve,

I got this suspicious RCU usage warning when I ran ftracetest on
tracing/urgent branch.

[1] Basic trace file check[   17.172817] 
[   17.174621] =============================
[   17.177730] WARNING: suspicious RCU usage
[   17.180962] 6.5.0-10750-g595efe1079cd #47 Tainted: G                 N
[   17.185528] -----------------------------
[   17.188685] fs/tracefs/event_inode.c:455 RCU-list traversed in non-reader section!!
[   17.194633] 
[   17.194633] other info that might help us debug this:
[   17.194633] 
[   17.200969] 
[   17.200969] rcu_scheduler_active = 2, debug_locks = 1
[   17.206086] 1 lock held by ftracetest/171:
[   17.209265]  #0: ffffffff829c2d30 (eventfs_srcu){.+.+}-{0:0}, at: dcache_dir_open_wrapper+0x3f/0x190
[   17.215551] 
[   17.215551] stack backtrace:
[   17.218498] CPU: 5 PID: 171 Comm: ftracetest Tainted: G                 N 6.5.0-10750-g595efe1079cd #47
[   17.223364] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.15.0-1 04/01/2014
[   17.228206] Call Trace:
[   17.230076]  <TASK>
[   17.231812]  dump_stack_lvl+0x66/0x80
[   17.234260]  lockdep_rcu_suspicious+0x158/0x1c0
[   17.237113]  ? __pfx_dcache_dir_open_wrapper+0x10/0x10
[   17.240026]  dcache_dir_open_wrapper+0x14c/0x190
[   17.242663]  ? __pfx_dcache_dir_open_wrapper+0x10/0x10
[   17.245592]  do_dentry_open+0x16a/0x550
[   17.248203]  do_open+0x272/0x3d0
[   17.250584]  path_openat+0x119/0x290
[   17.253046]  ? __lock_acquire+0x504/0xb70
[   17.255658]  do_filp_open+0xb6/0x160
[   17.258015]  ? find_held_lock+0x2b/0x80
[   17.260421]  ? alloc_fd+0x12b/0x220
[   17.262839]  ? trace_preempt_on+0x7a/0x90
[   17.265763]  ? preempt_count_sub+0x4b/0x60
[   17.268631]  ? _raw_spin_unlock+0x2d/0x50
[   17.271249]  do_sys_openat2+0x96/0xd0
[   17.273499]  __x64_sys_openat+0x57/0xa0
[   17.275808]  do_syscall_64+0x3f/0x90
[   17.277995]  entry_SYSCALL_64_after_hwframe+0x6e/0xd8
[   17.281250] RIP: 0033:0x4bce8c
[   17.283498] Code: 24 18 31 c0 41 83 e2 40 75 44 89 f0 25 00 00 41 00 3d 00 00 41 00 74 36 44 89 c2 4c 89 ce bf 9c ff ff ff b8 01 01 00 00 0f 05 <48> 3d 00 f0 ff ff 77 44 48 8b 4c 24 18 64 48 33 0c 25 28 00 00 00
[   17.294543] RSP: 002b:00007fffa59a3e20 EFLAGS: 00000287 ORIG_RAX: 0000000000000101
[   17.299479] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00000000004bce8c
[   17.303935] RDX: 0000000000090800 RSI: 000000000130b0c0 RDI: 00000000ffffff9c
[   17.308187] RBP: 00007fffa59a4098 R08: 0000000000090800 R09: 000000000130b0c0
[   17.312483] R10: 0000000000000000 R11: 0000000000000287 R12: 00000000013099ff
[   17.316401] R13: 0000000000000012 R14: 0000000001309a00 R15: 000000000130b0c7
[   17.320543]  </TASK>

But it seems correctly taking srcu_read_lock().

    452 
    453         ei = ti->private;
    454         idx = srcu_read_lock(&eventfs_srcu);
    455         list_for_each_entry_rcu(ef, &ei->e_top_files, list) {
    456                 create_dentry(ef, dentry, false);
    457         }
    458         srcu_read_unlock(&eventfs_srcu, idx);
    459         return dcache_dir_open(inode, file);
    460 }
    461 

This may false-positive warning, or srcu_read_lock() is not enough for
list_for_each_entry_rcu(). In latter case, maybe we need to use a
mutex instead of srcu for update the ef.

BTW, the ftracetest itself passed without any problem.

Thank you,

-- 
Masami Hiramatsu (Google) <mhiramat@kernel.org>

Re: suspicious RCU usage warning on tracing/urgent

[Steven Rostedt]

On Mon, 11 Sep 2023 12:00:53 +0900
Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote:

> But it seems correctly taking srcu_read_lock().
> 
>     452 
>     453         ei = ti->private;
>     454         idx = srcu_read_lock(&eventfs_srcu);
>     455         list_for_each_entry_rcu(ef, &ei->e_top_files, list) {
>     456                 create_dentry(ef, dentry, false);
>     457         }
>     458         srcu_read_unlock(&eventfs_srcu, idx);
>     459         return dcache_dir_open(inode, file);
>     460 }
>     461 
> 
> This may false-positive warning, or srcu_read_lock() is not enough for
> list_for_each_entry_rcu(). In latter case, maybe we need to use a
> mutex instead of srcu for update the ef.

Oops, that should be list_for_each_entry_srcu().

Thanks!

> 
> BTW, the ftracetest itself passed without any problem.

Thanks for testing as well!

-- Steve