[<prev] [next>] [<thread-prev] [day] [month] [year] [list]
Message-ID: <20200810025441.GF1538@shao2-debian>
Date: Mon, 10 Aug 2020 10:54:41 +0800
From: kernel test robot <rong.a.chen@...el.com>
To: Chengming Zhou <zhouchengming@...edance.com>
Cc: rostedt@...dmis.org, mingo@...hat.com,
linux-kernel@...r.kernel.org, songmuchun@...edance.com,
zhouchengming@...edance.com, 0day robot <lkp@...el.com>,
lkp@...ts.01.org
Subject: [ftrace] a89282bc45:
WARNING:possible_circular_locking_dependency_detected
Greeting,
FYI, we noticed the following commit (built with gcc-9):
commit: a89282bc45c4e3e2a4862567d260ae3a7c6fdbf2 ("[PATCH 1/2] ftrace: clear module from hash of all ftrace ops")
url: https://github.com/0day-ci/linux/commits/Chengming-Zhou/ftrace-clear-module-from-hash-of-all-ftrace-ops/20200728-182938
base: https://git.kernel.org/cgit/linux/kernel/git/tip/tip.git 2ac5413e5edca6910d2ae157187a889e94be2b62
in testcase: kernel-selftests
with following parameters:
group: kselftests-livepatch
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
on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
+-------------------------------------------------------+------------+------------+
| | 2ac5413e5e | a89282bc45 |
+-------------------------------------------------------+------------+------------+
| boot_successes | 2 | 0 |
| boot_failures | 1 | 6 |
| BUG:kernel_hang_in_boot_stage | 1 | |
| WARNING:possible_circular_locking_dependency_detected | 0 | 6 |
+-------------------------------------------------------+------------+------------+
If you fix the issue, kindly add following tag
Reported-by: kernel test robot <rong.a.chen@...el.com>
[ 81.533423] WARNING: possible circular locking dependency detected
[ 81.535989] 5.8.0-rc3-00047-ga89282bc45c4e #1 Tainted: G K
[ 81.538713] ------------------------------------------------------
[ 81.541327] rmmod/1712 is trying to acquire lock:
[ 81.543596] ffff933df5fa82c0 (&ops->local_hash.regex_lock){+.+.}-{3:3}, at: ftrace_release_mod+0x1c6/0x290
[ 81.546808]
[ 81.546808] but task is already holding lock:
[ 81.550614] ffffffffb0f789c8 (ftrace_lock){+.+.}-{3:3}, at: ftrace_release_mod+0x19f/0x290
[ 81.553589]
[ 81.553589] which lock already depends on the new lock.
[ 81.553589]
[ 81.559012]
[ 81.559012] the existing dependency chain (in reverse order) is:
[ 81.562896]
[ 81.562896] -> #1 (ftrace_lock){+.+.}-{3:3}:
[ 81.566410] __lock_acquire+0x538/0xa90
[ 81.568490] lock_acquire+0xab/0x390
[ 81.570405] __mutex_lock+0xac/0x9c0
[ 81.572381] ftrace_set_hash+0x118/0x1e0
[ 81.574520] ftrace_set_filter_ip+0x2a/0x70
[ 81.576614] klp_patch_object+0x19f/0x200
[ 81.578729] klp_enable_patch.cold+0x144/0x181
[ 81.580847] do_one_initcall+0x5d/0x330
[ 81.582658] do_init_module+0x5c/0x230
[ 81.584635] load_module+0x1430/0x1660
[ 81.586593] __do_sys_finit_module+0xaa/0x110
[ 81.588669] do_syscall_64+0x52/0xb0
[ 81.590589] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 81.592745]
[ 81.592745] -> #0 (&ops->local_hash.regex_lock){+.+.}-{3:3}:
[ 81.596284] check_prev_add+0x8e/0x9f0
[ 81.598198] validate_chain+0x79b/0x1080
[ 81.600083] __lock_acquire+0x538/0xa90
[ 81.601946] lock_acquire+0xab/0x390
[ 81.603769] __mutex_lock+0xac/0x9c0
[ 81.605534] ftrace_release_mod+0x1c6/0x290
[ 81.607424] __x64_sys_delete_module+0x166/0x230
[ 81.609346] do_syscall_64+0x52/0xb0
[ 81.611043] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 81.612974]
[ 81.612974] other info that might help us debug this:
[ 81.612974]
[ 81.617122] Possible unsafe locking scenario:
[ 81.617122]
[ 81.619926] CPU0 CPU1
[ 81.621603] ---- ----
[ 81.623216] lock(ftrace_lock);
[ 81.624584] lock(&ops->local_hash.regex_lock);
[ 81.626661] lock(ftrace_lock);
[ 81.628481] lock(&ops->local_hash.regex_lock);
[ 81.630122]
[ 81.630122] *** DEADLOCK ***
[ 81.630122]
[ 81.633369] 1 lock held by rmmod/1712:
[ 81.634761] #0: ffffffffb0f789c8 (ftrace_lock){+.+.}-{3:3}, at: ftrace_release_mod+0x19f/0x290
[ 81.637075]
[ 81.637075] stack backtrace:
[ 81.639253] CPU: 1 PID: 1712 Comm: rmmod Tainted: G K 5.8.0-rc3-00047-ga89282bc45c4e #1
[ 81.641666] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
[ 81.644040] Call Trace:
[ 81.645269] dump_stack+0x96/0xd0
[ 81.646633] check_noncircular+0x162/0x180
[ 81.648140] check_prev_add+0x8e/0x9f0
[ 81.649577] validate_chain+0x79b/0x1080
[ 81.651054] ? _raw_write_unlock_irqrestore+0x62/0x70
[ 81.652723] __lock_acquire+0x538/0xa90
[ 81.654236] lock_acquire+0xab/0x390
[ 81.655673] ? ftrace_release_mod+0x1c6/0x290
[ 81.657236] __mutex_lock+0xac/0x9c0
[ 81.658650] ? ftrace_release_mod+0x1c6/0x290
[ 81.660169] ? find_held_lock+0x2b/0x80
[ 81.661638] ? ftrace_release_mod+0x179/0x290
[ 81.663199] ? mark_held_locks+0x2d/0x80
[ 81.664694] ? ftrace_release_mod+0x1c6/0x290
[ 81.666315] ? __mutex_unlock_slowpath+0x45/0x2a0
[ 81.667893] ? ftrace_release_mod+0x1c6/0x290
[ 81.669351] ftrace_release_mod+0x1c6/0x290
[ 81.670823] __x64_sys_delete_module+0x166/0x230
[ 81.672432] ? lockdep_hardirqs_on_prepare+0xcf/0x170
[ 81.674137] ? do_syscall_64+0x12/0xb0
[ 81.675598] do_syscall_64+0x52/0xb0
[ 81.677033] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 81.678726] RIP: 0033:0x7fce1d96add7
[ 81.680096] Code: Bad RIP value.
[ 81.681444] RSP: 002b:00007ffc7b434f08 EFLAGS: 00000206 ORIG_RAX: 00000000000000b0
[ 81.683602] RAX: ffffffffffffffda RBX: 0000556d1708b900 RCX: 00007fce1d96add7
[ 81.685691] RDX: 000000000000000a RSI: 0000000000000800 RDI: 0000556d1708b968
[ 81.687769] RBP: 0000000000000000 R08: 00007ffc7b433e81 R09: 0000000000000000
[ 81.689860] R10: 00007fce1d9dcae0 R11: 0000000000000206 R12: 00007ffc7b435130
[ 81.691947] R13: 00007ffc7b435815 R14: 0000556d1708b260 R15: 0000556d1708b900
[ 81.777997] % echo 0 > /sys/kernel/livepatch/test_klp_callbacks_demo/enabled
[ 81.781319] livepatch: 'test_klp_callbacks_demo': initializing unpatching transition
[ 81.784430] test_klp_callbacks_demo: pre_unpatch_callback: vmlinux
[ 81.788458] test_klp_callbacks_demo: pre_unpatch_callback: test_klp_callbacks_busy -> [MODULE_STATE_LIVE] Normal state
[ 81.793297] livepatch: 'test_klp_callbacks_demo': starting unpatching transition
[ 81.799542] livepatch: 'test_klp_callbacks_demo': completing unpatching transition
[ 81.820610] test_klp_callbacks_demo: post_unpatch_callback: vmlinux
[ 81.823773] test_klp_callbacks_demo: post_unpatch_callback: test_klp_callbacks_busy -> [MODULE_STATE_LIVE] Normal state
[ 81.827764] livepatch: 'test_klp_callbacks_demo': unpatching complete
[ 81.836393] % rmmod test_klp_callbacks_demo
[ 81.865481] % rmmod test_klp_callbacks_busy
To reproduce:
# build kernel
cd linux
cp config-5.8.0-rc3-00047-ga89282bc45c4e .config
make HOSTCC=gcc-9 CC=gcc-9 ARCH=x86_64 olddefconfig prepare modules_prepare bzImage
git clone https://github.com/intel/lkp-tests.git
cd lkp-tests
bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email
Thanks,
Rong Chen
View attachment "config-5.8.0-rc3-00047-ga89282bc45c4e" of type "text/plain" (209046 bytes)
View attachment "job-script" of type "text/plain" (5695 bytes)
Download attachment "dmesg.xz" of type "application/x-xz" (20552 bytes)
View attachment "kernel-selftests" of type "text/plain" (1971 bytes)
Powered by blists - more mailing lists