Re: [PATCH v3 09/10] eventfs: moving tracing/events to eventfs

[Ajay Kaher]

> Hello,
>
> kernel test robot noticed "WARNING:possible_circular_locking_dependency_detected" on:
>
> commit: a3bb763435d444023d3bca5479da632c57724619 ("[PATCH v3 09/10] eventfs: moving tracing/events to eventfs")
> url: https://github.com/intel-lab-lkp/linux/commits/Ajay-Kaher/tracing-Require-all-trace-events-to-have-a-TRACE_SYSTEM/20230601-230657
> base: https://git.kernel.org/cgit/linux/kernel/git/shuah/linux-kselftest.git next
> patch link: 1685610013-33478-10-git-send-email-akaher@xxxxxxxxxx/">https://lore.kernel.org/all/1685610013-33478-10-git-send-email-akaher@xxxxxxxxxx/
> patch subject: [PATCH v3 09/10] eventfs: moving tracing/events to eventfs
>
> in testcase: kernel-selftests
> version: kernel-selftests-x86_64-60acb023-1_20230329
> with following parameters:
>
> group: ftrace
>
> test-description: The kernel contains a set of "self tests" under the tools/testing/selftests/ directory. These are intended to be small unit tests to exercise individual code paths in the kernel.
> test-url: https://www.kernel.org/doc/Documentation/kselftest.txt
>
>
> compiler: gcc-12
> test machine: 36 threads 1 sockets Intel(R) Core(TM) i9-10980XE CPU @ 3.00GHz (Cascade Lake) with 32G memory
>
> (please refer to attached dmesg/kmsg for entire log/backtrace)
>
>
>
> If you fix the issue in a separate patch/commit (i.e. not just a new version of
> the same patch/commit), kindly add following tags
> | Reported-by: kernel test robot <oliver.sang@xxxxxxxxx>
> | Closes: 202306102230.b5aa258d-oliver.sang@xxxxxxxxx">https://lore.kernel.org/oe-lkp/202306102230.b5aa258d-oliver.sang@xxxxxxxxx
>
>
> kern  :warn  : [  173.884312] WARNING: possible circular locking dependency detected
> kern  :warn  : [  173.884947] 6.4.0-rc1-00014-ga3bb763435d4 #1 Not tainted
> kern  :warn  : [  173.885501] ------------------------------------------------------
> kern  :warn  : [  173.886125] ftracetest/2186 is trying to acquire lock:
> kern :warn : [  173.886665] ffff88810045d368 (&sb->s_type->i_mutex_key#5){++++}-{3:3}, at: dcache_dir_open_wrapper (fs/tracefs/event_inode.c:373)
> kern  :warn  : [  173.887638]
> but task is already holding lock:
> kern :warn : [  173.888299] ffffffff84e6d640 (eventfs_rwsem/1){.+.+}-{3:3}, at: dcache_dir_open_wrapper (fs/tracefs/event_inode.c:364)
> kern  :warn  : [  173.889183]
> which lock already depends on the new lock.
>
> kern  :warn  : [  173.890101]
> the existing dependency chain (in reverse order) is:
> kern  :warn  : [  173.890898]
> -> #1 (eventfs_rwsem/1){.+.+}-{3:3}:
> kern :warn : [  173.891600] lock_acquire (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5693 kernel/locking/lockdep.c:5656)
> kern :warn : [  173.892066] down_read_nested (kernel/locking/rwsem.c:1263 kernel/locking/rwsem.c:1646)
> kern :warn : [  173.892553] eventfs_root_lookup (fs/tracefs/event_inode.c:283)
> kern :warn : [  173.893058] __lookup_slow (include/linux/dcache.h:359 include/linux/dcache.h:364 fs/namei.c:1691)
> kern :warn : [  173.893529] walk_component (include/linux/fs.h:790 fs/namei.c:1708 fs/namei.c:1998)
> kern :warn : [  173.894006] path_lookupat (fs/namei.c:2455 fs/namei.c:2479)
> kern :warn : [  173.894476] filename_lookup (fs/namei.c:2508)
> kern :warn : [  173.894974] vfs_statx (fs/stat.c:239)
> kern :warn : [  173.895410] vfs_fstatat (fs/stat.c:277)
> kern :warn : [  173.895851] __do_sys_newfstatat (fs/stat.c:447)
> kern :warn : [  173.896350] do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80)
> kern :warn : [  173.896815] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120)
> kern  :warn  : [  173.897392]
> -> #0 (&sb->s_type->i_mutex_key#5){++++}-{3:3}:
> kern :warn : [  173.898158] check_prev_add (kernel/locking/lockdep.c:3109)
> kern :warn : [  173.898643] __lock_acquire (kernel/locking/lockdep.c:3228 kernel/locking/lockdep.c:3842 kernel/locking/lockdep.c:5074)
> kern :warn : [  173.899133] lock_acquire (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5693 kernel/locking/lockdep.c:5656)
> kern :warn : [  173.899610] down_write (arch/x86/include/asm/preempt.h:80 kernel/locking/rwsem.c:1304 kernel/locking/rwsem.c:1315 kernel/locking/rwsem.c:1574)
> kern :warn : [  173.900054] dcache_dir_open_wrapper (fs/tracefs/event_inode.c:373)
> kern :warn : [  173.900603] do_dentry_open (fs/open.c:920)
> kern :warn : [  173.901081] do_open (fs/namei.c:3636)
> kern :warn : [  173.901508] path_openat (fs/namei.c:3792)
> kern :warn : [  173.901963] do_filp_open (fs/namei.c:3818)
> kern :warn : [  173.902425] do_sys_openat2 (fs/open.c:1356)
> kern :warn : [  173.902902] __x64_sys_openat (fs/open.c:1383)
> kern :warn : [  173.903408] do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80)
> kern :warn : [  173.903864] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120)
> kern  :warn  : [  173.904451]
> other info that might help us debug this:
>
> kern  :warn  : [  173.905372]  Possible unsafe locking scenario:
>
> kern  :warn  : [  173.906049]        CPU0                    CPU1
> kern  :warn  : [  173.906538]        ----                    ----
> kern  :warn  : [  173.907027]   rlock(eventfs_rwsem/1);
> kern  :warn  : [  173.907464]                                lock(&sb->s_type->i_mutex_key#5);
> kern  :warn  : [  173.908171]                                lock(eventfs_rwsem/1);
> kern  :warn  : [  173.908800]   lock(&sb->s_type->i_mutex_key#5);
> kern  :warn  : [  173.909291]
> *** DEADLOCK ***

Steve, this seems not to be a problem here as dcache_dir_open_wrapper()
and eventfs_root_lookup() both lock eventfs_rwsem as read lock, however
it’s known problem in Lockdep for rwlock:
https://lpc.events/event/2/contributions/74/
And available patchset on Lockdep not upstreamed:
https://lore.kernel.org/all/20190829083132.22394-1-duyuyang@xxxxxxxxx/

-Ajay