[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <202306102230.b5aa258d-oliver.sang@intel.com>
Date: Sat, 10 Jun 2023 23:25:27 +0800
From: kernel test robot <oliver.sang@...el.com>
To: Ajay Kaher <akaher@...are.com>
CC: <oe-lkp@...ts.linux.dev>, <lkp@...el.com>,
Steven Rostedt <rostedt@...dmis.org>,
Ching-lin Yu <chinglinyu@...gle.com>,
<linux-kernel@...r.kernel.org>,
<linux-trace-kernel@...r.kernel.org>, <mhiramat@...nel.org>,
<shuah@...nel.org>, <linux-kselftest@...r.kernel.org>,
<namit@...are.com>, <srivatsa@...il.mit.edu>,
<amakhalov@...are.com>, <vsirnapalli@...are.com>,
<tkundu@...are.com>, <er.ajay.kaher@...il.com>,
Ajay Kaher <akaher@...are.com>, <oliver.sang@...el.com>
Subject: Re: [PATCH v3 09/10] eventfs: moving tracing/events to eventfs
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: https://lore.kernel.org/all/1685610013-33478-10-git-send-email-akaher@vmware.com/
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@...el.com>
| Closes: https://lore.kernel.org/oe-lkp/202306102230.b5aa258d-oliver.sang@intel.com
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 ***
kern :warn : [ 173.910026] 1 lock held by ftracetest/2186:
kern :warn : [ 173.910488] #0: ffffffff84e6d640 (eventfs_rwsem/1){.+.+}-{3:3}, at: dcache_dir_open_wrapper (fs/tracefs/event_inode.c:364)
kern :warn : [ 173.911413]
stack backtrace:
kern :warn : [ 173.911955] CPU: 13 PID: 2186 Comm: ftracetest Not tainted 6.4.0-rc1-00014-ga3bb763435d4 #1
kern :warn : [ 173.912777] Hardware name: Gigabyte Technology Co., Ltd. X299 UD4 Pro/X299 UD4 Pro-CF, BIOS F8a 04/27/2021
kern :warn : [ 173.913694] Call Trace:
kern :warn : [ 173.914014] <TASK>
kern :warn : [ 173.914305] dump_stack_lvl (lib/dump_stack.c:108)
kern :warn : [ 173.914727] check_noncircular (kernel/locking/lockdep.c:2191)
kern :warn : [ 173.915199] ? print_circular_bug (kernel/locking/lockdep.c:2167)
kern :warn : [ 173.915676] ? mark_usage (kernel/locking/lockdep.c:4930)
kern :warn : [ 173.916100] check_prev_add (kernel/locking/lockdep.c:3109)
kern :warn : [ 173.916553] __lock_acquire (kernel/locking/lockdep.c:3228 kernel/locking/lockdep.c:3842 kernel/locking/lockdep.c:5074)
kern :warn : [ 173.917003] ? mark_usage (kernel/locking/lockdep.c:4930)
kern :warn : [ 173.917425] ? __lock_acquire (arch/x86/include/asm/bitops.h:228 arch/x86/include/asm/bitops.h:240 include/asm-generic/bitops/instrumented-non-atomic.h:142 kernel/locking/lockdep.c:228 kernel/locking/lockdep.c:3754 kernel/locking/lockdep.c:3810 kernel/locking/lockdep.c:5074)
kern :warn : [ 173.917889] lock_acquire (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5693 kernel/locking/lockdep.c:5656)
kern :warn : [ 173.918309] ? dcache_dir_open_wrapper (fs/tracefs/event_inode.c:373)
kern :warn : [ 173.918822] ? lock_sync (kernel/locking/lockdep.c:5659)
kern :warn : [ 173.919253] ? preempt_notifier_dec (kernel/sched/core.c:10108)
kern :warn : [ 173.919729] ? lock_sync (kernel/locking/lockdep.c:5659)
kern :warn : [ 173.920144] 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.920552] ? dcache_dir_open_wrapper (fs/tracefs/event_inode.c:373)
kern :warn : [ 173.921064] ? down_write_killable_nested (kernel/locking/rwsem.c:1571)
kern :warn : [ 173.921599] ? __lock_release+0x111/0x440
kern :warn : [ 173.922097] ? do_dentry_open (fs/open.c:872)
kern :warn : [ 173.922540] dcache_dir_open_wrapper (fs/tracefs/event_inode.c:373)
kern :warn : [ 173.923039] ? fsnotify_perm+0x13b/0x4a0
kern :warn : [ 173.923548] do_dentry_open (fs/open.c:920)
kern :warn : [ 173.923982] ? eventfs_create_dir (fs/tracefs/event_inode.c:349)
kern :warn : [ 173.924470] ? may_open (fs/namei.c:3265)
kern :warn : [ 173.924869] do_open (fs/namei.c:3636)
kern :warn : [ 173.925255] path_openat (fs/namei.c:3792)
kern :warn : [ 173.926598] ? path_lookupat (fs/namei.c:3773)
kern :warn : [ 173.927039] ? .slowpath (kernel/locking/qspinlock.c:317)
kern :warn : [ 173.927454] ? lock_acquire (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5693 kernel/locking/lockdep.c:5656)
kern :warn : [ 173.927889] ? __create_object (mm/kmemleak.c:678)
kern :warn : [ 173.928347] do_filp_open (fs/namei.c:3818)
kern :warn : [ 173.928768] ? may_open_dev (fs/namei.c:3812)
kern :warn : [ 173.929202] ? _raw_spin_unlock (arch/x86/include/asm/preempt.h:95 include/linux/spinlock_api_smp.h:143 kernel/locking/spinlock.c:186)
kern :warn : [ 173.929651] ? alloc_fd (fs/file.c:555 (discriminator 10))
kern :warn : [ 173.930060] ? getname_flags (fs/namei.c:206)
kern :warn : [ 173.930544] do_sys_openat2 (fs/open.c:1356)
kern :warn : [ 173.930979] ? build_open_flags (fs/open.c:1342)
kern :warn : [ 173.931460] __x64_sys_openat (fs/open.c:1383)
kern :warn : [ 173.931909] ? __ia32_compat_sys_open (fs/open.c:1383)
kern :warn : [ 173.932416] ? lockdep_hardirqs_on_prepare (kernel/locking/lockdep.c:4539)
kern :warn : [ 173.933016] ? syscall_enter_from_user_mode (arch/x86/include/asm/irqflags.h:42 arch/x86/include/asm/irqflags.h:77 kernel/entry/common.c:111)
kern :warn : [ 173.933552] do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80)
kern :warn : [ 173.933966] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120)
kern :warn : [ 173.934500] RIP: 0033:0x7fc11f551e41
kern :warn : [ 173.934913] 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
All code
========
0: 44 24 18 rex.R and $0x18,%al
3: 31 c0 xor %eax,%eax
5: 41 83 e2 40 and $0x40,%r10d
9: 75 3e jne 0x49
b: 89 f0 mov %esi,%eax
d: 25 00 00 41 00 and $0x410000,%eax
12: 3d 00 00 41 00 cmp $0x410000,%eax
17: 74 30 je 0x49
19: 89 f2 mov %esi,%edx
1b: b8 01 01 00 00 mov $0x101,%eax
20: 48 89 fe mov %rdi,%rsi
23: bf 9c ff ff ff mov $0xffffff9c,%edi
28: 0f 05 syscall
2a:* 48 3d 00 f0 ff ff cmp $0xfffffffffffff000,%rax <-- trapping instruction
30: 77 3f ja 0x71
32: 48 8b 54 24 18 mov 0x18(%rsp),%rdx
37: 64 48 2b 14 25 28 00 sub %fs:0x28,%rdx
3e: 00 00
Code starting with the faulting instruction
===========================================
0: 48 3d 00 f0 ff ff cmp $0xfffffffffffff000,%rax
6: 77 3f ja 0x47
8: 48 8b 54 24 18 mov 0x18(%rsp),%rdx
d: 64 48 2b 14 25 28 00 sub %fs:0x28,%rdx
14: 00 00
To reproduce:
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
sudo bin/lkp install job.yaml # job file is attached in this email
bin/lkp split-job --compatible job.yaml # generate the yaml file for lkp run
sudo bin/lkp run generated-yaml-file
# if come across any failure that blocks the test,
# please remove ~/.lkp and /lkp dir to run from a clean state.
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki
View attachment "config-6.4.0-rc1-00014-ga3bb763435d4" of type "text/plain" (162889 bytes)
View attachment "job-script" of type "text/plain" (6374 bytes)
Download attachment "kmsg.xz" of type "application/x-xz" (51468 bytes)
View attachment "kernel-selftests" of type "text/plain" (4118 bytes)
View attachment "job.yaml" of type "text/plain" (5067 bytes)
View attachment "reproduce" of type "text/plain" (247 bytes)
Powered by blists - more mailing lists