[<prev] [next>] [thread-next>] [day] [month] [year] [list]
Message-ID: <5c17230f.mbgTPR4404Mp8abU%lkp@intel.com>
Date: Mon, 17 Dec 2018 12:16:15 +0800
From: kernel test robot <lkp@...el.com>
To: Bart Van Assche <bvanassche@....org>
Cc: LKP <lkp@...org>, linux-kernel@...r.kernel.org
Subject: cdbeb78c7a ("kernel/workqueue: Use dynamic lockdep keys for .."): WARNING: CPU: 0 PID: 0 at kernel/locking/lockdep.c:1002 lockdep_register_key
Greetings,
0day kernel testing robot got the below dmesg and the first bad commit is
https://github.com/bvanassche/linux for-next
commit cdbeb78c7a2e34af6d6cc5d3570a585a23eea8e9
Author: Bart Van Assche <bvanassche@....org>
AuthorDate: Fri Nov 9 09:53:31 2018 -0800
Commit: Bart Van Assche <bvanassche@....org>
CommitDate: Fri Dec 14 11:24:37 2018 -0800
kernel/workqueue: Use dynamic lockdep keys for workqueues
Commit 87915adc3f0a ("workqueue: re-add lockdep dependencies for flushing")
improved deadlock checking in the workqueue implementation. Unfortunately
that patch also introduced a few false positive lockdep complaints. This
patch suppresses these false positives by allocating the workqueue mutex
lockdep key dynamically. An example of a false positive lockdep complaint
suppressed by this report can be found below. The root cause of the
lockdep complaint shown below is that the direct I/O code can call
alloc_workqueue() from inside a work item created by another
alloc_workqueue() call and that both workqueues share the same lockdep
key. This patch avoids that that lockdep complaint is triggered by
allocating the work queue lockdep keys dynamically. In other words, this
patch guarantees that a unique lockdep key is associated with each work
queue mutex.
======================================================
WARNING: possible circular locking dependency detected
4.19.0-dbg+ #1 Not tainted
------------------------------------------------------
fio/4129 is trying to acquire lock:
00000000a01cfe1a ((wq_completion)"dio/%s"sb->s_id){+.+.}, at: flush_workqueue+0xd0/0x970
but task is already holding lock:
00000000a0acecf9 (&sb->s_type->i_mutex_key#14){+.+.}, at: ext4_file_write_iter+0x154/0x710
which lock already depends on the new lock.
the existing dependency chain (in reverse order) is:
-> #2 (&sb->s_type->i_mutex_key#14){+.+.}:
down_write+0x3d/0x80
__generic_file_fsync+0x77/0xf0
ext4_sync_file+0x3c9/0x780
vfs_fsync_range+0x66/0x100
dio_complete+0x2f5/0x360
dio_aio_complete_work+0x1c/0x20
process_one_work+0x481/0x9f0
worker_thread+0x63/0x5a0
kthread+0x1cf/0x1f0
ret_from_fork+0x24/0x30
-> #1 ((work_completion)(&dio->complete_work)){+.+.}:
process_one_work+0x447/0x9f0
worker_thread+0x63/0x5a0
kthread+0x1cf/0x1f0
ret_from_fork+0x24/0x30
-> #0 ((wq_completion)"dio/%s"sb->s_id){+.+.}:
lock_acquire+0xc5/0x200
flush_workqueue+0xf3/0x970
drain_workqueue+0xec/0x220
destroy_workqueue+0x23/0x350
sb_init_dio_done_wq+0x6a/0x80
do_blockdev_direct_IO+0x1f33/0x4be0
__blockdev_direct_IO+0x79/0x86
ext4_direct_IO+0x5df/0xbb0
generic_file_direct_write+0x119/0x220
__generic_file_write_iter+0x131/0x2d0
ext4_file_write_iter+0x3fa/0x710
aio_write+0x235/0x330
io_submit_one+0x510/0xeb0
__x64_sys_io_submit+0x122/0x340
do_syscall_64+0x71/0x220
entry_SYSCALL_64_after_hwframe+0x49/0xbe
other info that might help us debug this:
Chain exists of:
(wq_completion)"dio/%s"sb->s_id --> (work_completion)(&dio->complete_work) --> &sb->s_type->i_mutex_key#14
Possible unsafe locking scenario:
CPU0 CPU1
---- ----
lock(&sb->s_type->i_mutex_key#14);
lock((work_completion)(&dio->complete_work));
lock(&sb->s_type->i_mutex_key#14);
lock((wq_completion)"dio/%s"sb->s_id);
*** DEADLOCK ***
1 lock held by fio/4129:
#0: 00000000a0acecf9 (&sb->s_type->i_mutex_key#14){+.+.}, at: ext4_file_write_iter+0x154/0x710
stack backtrace:
CPU: 3 PID: 4129 Comm: fio Not tainted 4.19.0-dbg+ #1
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
Call Trace:
dump_stack+0x86/0xc5
print_circular_bug.isra.32+0x20a/0x218
__lock_acquire+0x1c68/0x1cf0
lock_acquire+0xc5/0x200
flush_workqueue+0xf3/0x970
drain_workqueue+0xec/0x220
destroy_workqueue+0x23/0x350
sb_init_dio_done_wq+0x6a/0x80
do_blockdev_direct_IO+0x1f33/0x4be0
__blockdev_direct_IO+0x79/0x86
ext4_direct_IO+0x5df/0xbb0
generic_file_direct_write+0x119/0x220
__generic_file_write_iter+0x131/0x2d0
ext4_file_write_iter+0x3fa/0x710
aio_write+0x235/0x330
io_submit_one+0x510/0xeb0
__x64_sys_io_submit+0x122/0x340
do_syscall_64+0x71/0x220
entry_SYSCALL_64_after_hwframe+0x49/0xbe
Cc: Ingo Molnar <mingo@...hat.com>
Cc: Peter Zijlstra <peterz@...radead.org>
Cc: Will Deacon <will.deacon@....com>
Cc: Tejun Heo <tj@...nel.org>
Cc: Waiman Long <longman@...hat.com>
Cc: Johannes Berg <johannes.berg@...el.com>
Signed-off-by: Bart Van Assche <bvanassche@....org>
60e521015c locking/lockdep: Add support for dynamic keys
cdbeb78c7a kernel/workqueue: Use dynamic lockdep keys for workqueues
9294000d6d IB/srp: Drain the send queue before destroying a QP
+-----------------------------------------------------------+------------+------------+---------------------+
| | 60e521015c | cdbeb78c7a | bvanassche/for-next |
+-----------------------------------------------------------+------------+------------+---------------------+
| boot_successes | 915 | 305 | 0 |
| boot_failures | 1 | 7 | 310 |
| INFO:rcu_preempt_self-detected_stall_on_CPU | 1 | | |
| EIP:smp_call_function_single | 1 | | |
| BUG:kernel_hang_in_boot-around-mounting-root_stage | 1 | | |
| WARNING:at_kernel/locking/lockdep.c:#lockdep_register_key | 0 | 7 | |
| EIP:lockdep_register_key | 0 | 7 | |
| WARNING:kernel_stack | 0 | 0 | 310 |
+-----------------------------------------------------------+------------+------------+---------------------+
[ 0.255225] .init : 0x5cafd000 - 0x5cc21000 (1168 kB)
[ 0.255225] .data : 0x5bcd26bd - 0x5cae3a40 (14404 kB)
[ 0.255225] .text : 0x5a600000 - 0x5bcd26bd (23369 kB)
[ 0.255616] Checking if this processor honours the WP bit even in supervisor mode...Ok.
[ 0.263302] SLUB: HWalign=128, Order=0-3, MinObjects=0, CPUs=2, Nodes=1
[ 0.267586] WARNING: CPU: 0 PID: 0 at kernel/locking/lockdep.c:1002 lockdep_register_key+0x3b/0x161
[ 0.267680] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.20.0-rc6-00030-gcdbeb78 #1
[ 0.267748] EIP: lockdep_register_key+0x3b/0x161
[ 0.267837] Code: 57 56 53 89 c3 e8 9a e2 ff ff 83 05 28 fd e3 5c 01 83 15 2c fd e3 5c 00 85 c0 74 23 83 05 30 fd e3 5c 01 83 15 34 fd e3 5c 00 <0f> 0b 83 05 38 fd e3 5c 01 83 15 3c fd e3 5c 00 e9 0c 01 00 00 83
[ 0.267901] EAX: 00000001 EBX: 5dc08098 ECX: 5cc9001c EDX: 00000000
[ 0.267944] ESI: 5dc08000 EDI: 5dc080b8 EBP: 5c661f28 ESP: 5c661f1c
[ 0.268007] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068 EFLAGS: 00210046
[ 0.268069] CR0: 80050033 CR2: ffc6f000 CR3: 1cc2b000 CR4: 00000690
[ 0.268137] Call Trace:
[ 0.268229] ? alloc_workqueue+0x1dd/0x63e
[ 0.268356] ? workqueue_init_early+0x302/0x522
[ 0.268487] ? start_kernel+0x60c/0xb08
[ 0.268554] ? i386_start_kernel+0x1b7/0x1c9
[ 0.268620] ? startup_32_smp+0x15f/0x164
[ 0.268745] random: get_random_bytes called from init_oops_id+0x31/0x65 with crng_init=0
[ 0.268815] ---[ end trace 358134c881f779eb ]---
[ 0.270375] rcu: Preemptible hierarchical RCU implementation.
# HH:MM RESULT GOOD BAD GOOD_BUT_DIRTY DIRTY_NOT_BAD
git bisect start 76aaa5f181905fb71f79065478e486d3422338db 40e020c129cfc991e8ab4736d2665351ffd1468d --
git bisect bad 4fafdd784cbe99b4b0f5e2c87f0849ea09a1e4dd # 09:18 B 60 1 0 0 Merge 'dm/for-next' into devel-hourly-2018121509
git bisect good 66b85b30a8df43a5f3fe2871e2ee3c0d89f41fd1 # 11:03 G 236 0 0 0 Merge 'tty/tty-next' into devel-hourly-2018121509
git bisect good fe5dae5296a75d4f4f835b214da08f72e068a196 # 12:33 G 230 0 0 0 Merge 'tyhicks/apparmor/keyring' into devel-hourly-2018121509
git bisect good 0ed6b133563af0f842b98b811b6da1ede7cb18e9 # 13:29 G 237 0 0 0 Merge 'linux-review/Corentin-Labbe/sparc-Set-ARCH-sunxx-information-on-the-same-line/20181212-023207' into devel-hourly-2018121509
git bisect good 56bd71423bc2445a4fd3398e89611cad8bb54136 # 15:01 G 237 0 0 0 Merge 'rockchip/v4.21-armsoc/dts64' into devel-hourly-2018121509
git bisect good 10a3445ab315460e1cf2de1b14cf90619240f94e # 15:29 G 237 0 0 0 Merge 'renesas/arm-dt-for-v4.22' into devel-hourly-2018121509
git bisect bad a9419ab759baadf463d3ca44fc11ee4be433ac23 # 16:32 B 85 1 0 0 Merge 'arm-soc/amlogic/dt-2' into devel-hourly-2018121509
git bisect bad afed425871d7a58095c1a7839ac088174fa57e13 # 19:06 B 129 1 0 0 Merge 'bvanassche/for-next' into devel-hourly-2018121509
git bisect good d39bbfc24d2040a2b1a9566fcf791fb00975c970 # 21:21 G 309 0 0 0 locking/lockdep: Make zap_class() remove all matching lock order entries
git bisect good ceefdaeedc43d36722fa200e998157985dc7e844 # 23:04 G 308 0 0 0 locking/lockdep: Check data structure consistency
git bisect bad 826fc6028e1f5cc294fb39e26c96a4d88aeec379 # 00:06 B 26 1 0 0 tools-kernel
git bisect good 60e521015cc2a5532604c325d7a86f905706738e # 00:38 G 303 0 0 0 locking/lockdep: Add support for dynamic keys
git bisect bad 302d55b825c68479e0221425056bf753fe9d19c4 # 01:15 B 81 1 0 0 lockdep tests: Test dynamic key registration
git bisect bad cdbeb78c7a2e34af6d6cc5d3570a585a23eea8e9 # 02:19 B 90 1 0 0 kernel/workqueue: Use dynamic lockdep keys for workqueues
# first bad commit: [cdbeb78c7a2e34af6d6cc5d3570a585a23eea8e9] kernel/workqueue: Use dynamic lockdep keys for workqueues
git bisect good 60e521015cc2a5532604c325d7a86f905706738e # 02:44 G 908 0 0 0 locking/lockdep: Add support for dynamic keys
# extra tests with debug options
git bisect bad cdbeb78c7a2e34af6d6cc5d3570a585a23eea8e9 # 04:01 B 22 1 0 0 kernel/workqueue: Use dynamic lockdep keys for workqueues
# extra tests on HEAD of linux-devel/devel-hourly-2018121509
git bisect bad 76aaa5f181905fb71f79065478e486d3422338db # 04:01 B 88 2 0 0 0day head guard for 'devel-hourly-2018121509'
# extra tests on tree/branch bvanassche/for-next
git bisect good 9294000d6d895ad609f3cc4aff98c9c6175b466f # 10:51 G 308 0 308 308 IB/srp: Drain the send queue before destroying a QP
# extra tests with first bad commit reverted
git bisect good 322ac97e8b243ba9a707575087b7f97878e97db2 # 12:14 G 310 0 0 0 Revert "kernel/workqueue: Use dynamic lockdep keys for workqueues"
---
0-DAY kernel test infrastructure Open Source Technology Center
https://lists.01.org/pipermail/lkp Intel Corporation
Download attachment "dmesg-quantal-vm-quantal-239:20181217022531:i386-randconfig-x0-12151238:4.20.0-rc6-00030-gcdbeb78:1.gz" of type "application/gzip" (23968 bytes)
Download attachment "dmesg-quantal-vm-quantal-238:20181217024430:i386-randconfig-x0-12151238:4.20.0-rc6-00029-g60e5210:1.gz" of type "application/gzip" (10157 bytes)
View attachment "reproduce-quantal-vm-quantal-239:20181217022531:i386-randconfig-x0-12151238:4.20.0-rc6-00030-gcdbeb78:1" of type "text/plain" (910 bytes)
View attachment "config-4.20.0-rc6-00030-gcdbeb78" of type "text/plain" (115615 bytes)
Powered by blists - more mailing lists