Re: [PATCH v4 00/10] tracing: introducing eventfs

Steven Rostedt
2023-07-19T18:40:53Z

On Wed, 19 Jul 2023 18:37:12 +0000
Ajay Kaher <akaher@vmware.com> wrote:

> > Here's the reproducer (of both v3 splat and the bug I'm hitting now).
> >
> > ~# echo 'p:sock_getattr 0xffffffff9b55cef0 sk=%di' > /sys/kernel/tracing/kprobe_events
> > ~# ls /sys/kernel/debug/tracing/events/kprobes/sock_getattr/
> > ~# echo '-:sock_getattr 0xffffffff9b55cef0 sk=%di' > /sys/kernel/tracing/kprobe_events
>
> I tried above steps on v4 but couldn’t reproduce:
>
> root@photon-6 [ ~/sdb/linux ]# echo 'p:sock_getattr 0xffffffff9b55cef0 sk=%di' > /sys/kernel/tracing/kprobe_events
> root@photon-6 [ ~/sdb/linux ]# ls /sys/kernel/debug/tracing/events/kprobes/sock_getattr/
> enable filter format id trigger
> root@photon-6 [ ~/sdb/linux ]# echo '-:sock_getattr 0xffffffff9b55cef0 sk=%di' > /sys/kernel/tracing/kprobe_events
> -bash: echo: write error: No such file or directory
>
> I have doubt on call_srcu(), it may first end the grace period for parent then for child. If this is true then free_list
> will have unordered list and could cause problem.

I modified the srcu portion a bit. Will post soon. I think I got something
working.

I'm having doubt that the dput()s were needed in the eventfs_remove_rec(),
as the d_invalidate() appears to be enough. I'm still testing.

>
>
> >
> > v3 gives me (and my updates too)
> >
> > ======================================================
> > WARNING: possible circular locking dependency detected
> > 6.5.0-rc1-test+ #576 Not tainted
> > ------------------------------------------------------
> > trace-cmd/840 is trying to acquire lock:
> > ffff8881007e5de0 (&sb->s_type->i_mutex_key#5){++++}-{3:3}, at: dcache_dir_open_wrapper+0xc1/0x1b0
> >
> > but task is already holding lock:
> > ffff888103ad7e70 (eventfs_rwsem/1){.+.+}-{3:3}, at: dcache_dir_open_wrapper+0x6f/0x1b0
> >
> > which lock already depends on the new lock.
> >
> >
> > the existing dependency chain (in reverse order) is:
> >
> > -> #1 (eventfs_rwsem/1){.+.+}-{3:3}:
> > down_read_nested+0x41/0x180
> > eventfs_root_lookup+0x42/0x120
> > __lookup_slow+0xff/0x1b0
> > walk_component+0xdb/0x150
> > path_lookupat+0x67/0x1a0
> > filename_lookup+0xe4/0x1f0
> > vfs_statx+0x9e/0x180
> > vfs_fstatat+0x51/0x70
> > __do_sys_newfstatat+0x3f/0x80
> > do_syscall_64+0x3a/0xc0
> > entry_SYSCALL_64_after_hwframe+0x6e/0xd8
> >
> > -> #0 (&sb->s_type->i_mutex_key#5){++++}-{3:3}:
> > __lock_acquire+0x165d/0x2390
> > lock_acquire+0xd4/0x2d0
> > down_write+0x3b/0xd0
> > dcache_dir_open_wrapper+0xc1/0x1b0
> > do_dentry_open+0x20c/0x510
> > path_openat+0x7ad/0xc60
> > do_filp_open+0xaf/0x160
> > do_sys_openat2+0xab/0xe0
> > __x64_sys_openat+0x6a/0xa0
> > do_syscall_64+0x3a/0xc0
> > entry_SYSCALL_64_after_hwframe+0x6e/0xd8
> >
> > other info that might help us debug this:
> >
> > Possible unsafe locking scenario:
> >
> > CPU0 CPU1
> > ---- ----
> > rlock(eventfs_rwsem/1);
> > lock(&sb->s_type->i_mutex_key#5);
> > lock(eventfs_rwsem/1);
> > lock(&sb->s_type->i_mutex_key#5);
> >
> > *** DEADLOCK ***
> >
> > 1 lock held by trace-cmd/840:
> > #0: ffff888103ad7e70 (eventfs_rwsem/1){.+.+}-{3:3}, at: dcache_dir_open_wrapper+0x6f/0x1b0
> >
> > stack backtrace:
> > CPU: 7 PID: 840 Comm: trace-cmd Not tainted 6.5.0-rc1-test+ #576
> > Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
> > Call Trace:
> > <TASK>
> > dump_stack_lvl+0x57/0x90
> > check_noncircular+0x14b/0x160
> > __lock_acquire+0x165d/0x2390
> > lock_acquire+0xd4/0x2d0
> > ? dcache_dir_open_wrapper+0xc1/0x1b0
> > down_write+0x3b/0xd0
> > ? dcache_dir_open_wrapper+0xc1/0x1b0
> > dcache_dir_open_wrapper+0xc1/0x1b0
> > ? __pfx_dcache_dir_open_wrapper+0x10/0x10
> > do_dentry_open+0x20c/0x510
> > path_openat+0x7ad/0xc60
> > do_filp_open+0xaf/0x160
> > do_sys_openat2+0xab/0xe0
> > __x64_sys_openat+0x6a/0xa0
> > do_syscall_64+0x3a/0xc0
> > entry_SYSCALL_64_after_hwframe+0x6e/0xd8
> > RIP: 0033:0x7f1743267e41
> > Code: 44 24 18 31 c0 41 83 e2 40 75 3e 89 f0 25 00 00 41 00 3d 00 00 41 00 74 30 89 f2 b8 01 01 00 00 48 89 fe bf 9c ff ff ff 0f 05 <48> 3d 00 f0 ff ff 77 3f 48 8b 54 24 18 64 48 2b 14 25 28 00 00 00
> > RSP: 002b:00007ffec10ff5d0 EFLAGS: 00000287 ORIG_RAX: 0000000000000101
> > RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f1743267e41
> > RDX: 0000000000090800 RSI: 00007ffec10ffdb0 RDI: 00000000ffffff9c
> > RBP: 00007ffec10ffda0 R08: 00007ffec11003e0 R09: 0000000000000040
> > R10: 0000000000000000 R11: 0000000000000287 R12: 00007ffec11003e0
> > R13: 0000000000000040 R14: 0000000000000000 R15: 00007ffec110034b
> > </TASK>
> >
>
> This is expected from v3 (just ignore as of now), if eventfs_set_ef_status_free crash not
> reproduced on v3 then it’s v4 issue.

The issue comes from fixing the above ;-)

-- Steve