[<prev] [next>] [thread-next>] [day] [month] [year] [list]
Message-ID: <5c81f407.dqtEdGUmHMiobjjO%lkp@intel.com>
Date: Fri, 08 Mar 2019 12:48:07 +0800
From: kernel test robot <lkp@...el.com>
To: Bart Van Assche <bvanassche@....org>
Cc: LKP <lkp@...org>, linux-kernel@...r.kernel.org,
"Peter Zijlstra (Intel)" <peterz@...radead.org>,
Ingo Molnar <mingo@...nel.org>
Subject: 669de8bda8 ("kernel/workqueue: Use dynamic lockdep keys for .."): WARNING: CPU: 0 PID: 1 at kernel/locking/lockdep.c:995 lockdep_register_key
Greetings,
0day kernel testing robot got the below dmesg and the first bad commit is
https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master
commit 669de8bda87b92ab9a2fc663b3f5743c2ad1ae9f
Author: Bart Van Assche <bvanassche@....org>
AuthorDate: Thu Feb 14 15:00:54 2019 -0800
Commit: Ingo Molnar <mingo@...nel.org>
CommitDate: Thu Feb 28 07:55:47 2019 +0100
kernel/workqueue: Use dynamic lockdep keys for workqueues
The following 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 patch
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
Signed-off-by: Bart Van Assche <bvanassche@....org>
Signed-off-by: Peter Zijlstra (Intel) <peterz@...radead.org>
Cc: Andrew Morton <akpm@...ux-foundation.org>
Cc: Johannes Berg <johannes.berg@...el.com>
Cc: Linus Torvalds <torvalds@...ux-foundation.org>
Cc: Paul E. McKenney <paulmck@...ux.vnet.ibm.com>
Cc: Peter Zijlstra <peterz@...radead.org>
Cc: Tejun Heo <tj@...nel.org>
Cc: Thomas Gleixner <tglx@...utronix.de>
Cc: Waiman Long <longman@...hat.com>
Cc: Will Deacon <will.deacon@....com>
Link: https://lkml.kernel.org/r/20190214230058.196511-20-bvanassche@acm.org
[ Reworked the changelog a bit. ]
Signed-off-by: Ingo Molnar <mingo@...nel.org>
108c14858b locking/lockdep: Add support for dynamic keys
669de8bda8 kernel/workqueue: Use dynamic lockdep keys for workqueues
f90d64483e Merge tag 'usb-5.1-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb
cf08baa296 Add linux-next specific files for 20190306
+--------------------------------------------------------------+------------+------------+------------+---------------+
| | 108c14858b | 669de8bda8 | f90d64483e | next-20190306 |
+--------------------------------------------------------------+------------+------------+------------+---------------+
| boot_successes | 2811 | 2636 | 865 | 73 |
| boot_failures | 15 | 31 | 8 | 1 |
| INFO:task_blocked_for_more_than#seconds | 10 | | | |
| Kernel_panic-not_syncing:hung_task:blocked_tasks | 10 | | | |
| invoked_oom-killer:gfp_mask=0x | 5 | 1 | 3 | |
| Mem-Info | 5 | 1 | 3 | |
| WARNING:at_kernel/locking/lockdep.c:#lockdep_register_key/0x | 0 | 30 | 5 | 1 |
| EIP:lockdep_register_key | 0 | 30 | 5 | 1 |
| EIP:__get_user_4 | 0 | 1 | | |
| Out_of_memory:Kill_process | 0 | 1 | | |
+--------------------------------------------------------------+------------+------------+------------+---------------+
[ 1.855169] spin_lock-torture: lock_torture_stats task started
[ 2.565387] workingset: timestamp_bits=14 max_order=17 bucket_order=3
[ 2.567522] NFS: Registering the id_resolver key type
[ 2.568478] Key type id_resolver registered
[ 2.569072] Key type id_legacy registered
[ 2.570808] WARNING: CPU: 0 PID: 1 at kernel/locking/lockdep.c:995 lockdep_register_key+0x37/0x386
[ 2.571658] CPU: 0 PID: 1 Comm: swapper Not tainted 5.0.0-rc8-00054-g669de8b #496
[ 2.571658] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 2.571658] EIP: lockdep_register_key+0x37/0x386
[ 2.571658] Code: 20 45 65 94 01 83 15 24 45 65 94 00 81 fe 00 00 80 92 72 2e 81 fe 00 d0 88 95 73 26 83 05 40 45 65 94 01 83 15 44 45 65 94 00 <0f> 0b 83 05 48 45 65 94 01 83 15 4c 45 65 94 00 83 c4 1c 5b 5e 5f
[ 2.571658] EAX: 9586d254 EBX: 9586d1c0 ECX: 944f9cd8 EDX: 00000000
[ 2.571658] ESI: 9586d254 EDI: 9586d274 EBP: 975a9ee4 ESP: 975a9ebc
[ 2.571658] DS: 007b ES: 007b FS: 0000 GS: 0000 SS: 0068 EFLAGS: 00210246
[ 2.571658] CR0: 80050033 CR2: 00000000 CR3: 1c4a5000 CR4: 00340690
[ 2.571658] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 2.571658] DR6: fffe0ff0 DR7: 00000400
[ 2.571658] Call Trace:
[ 2.571658] ? debug_mutex_init+0x4b/0x63
[ 2.571658] ? __mutex_init+0x59/0x6c
[ 2.571658] alloc_workqueue+0x227/0x84e
[ 2.571658] ? proc_create+0x3e/0x52
[ 2.571658] ? trace_event_define_fields_smb3_rw_err_class+0x1b9/0x1b9
[ 2.571658] init_cifs+0x159/0x72f
[ 2.571658] do_one_initcall+0x2c4/0x6bf
[ 2.571658] kernel_init_freeable+0x6ef/0x841
[ 2.571658] ? rest_init+0x473/0x473
[ 2.571658] kernel_init+0x1e/0x26b
[ 2.571658] ? schedule_tail_wrapper+0x9/0xc
[ 2.571658] ret_from_fork+0x1e/0x28
[ 2.571658] irq event stamp: 410062
[ 2.571658] hardirqs last enabled at (410061): [<93a2ac73>] _raw_spin_unlock_irqrestore+0x133/0x17e
[ 2.571658] hardirqs last disabled at (410062): [<92801bca>] trace_hardirqs_off_thunk+0xc/0x10
[ 2.571658] softirqs last enabled at (409970): [<93a2da14>] __do_softirq+0x904/0xa1d
[ 2.571658] softirqs last disabled at (409965): [<92813eb9>] do_softirq_own_stack+0x3d/0x51
[ 2.571658] ---[ end trace c4eabde80fbbdbf0 ]---
[ 3.753943] String selftests succeeded
# HH:MM RESULT GOOD BAD GOOD_BUT_DIRTY DIRTY_NOT_BAD
git bisect start f32e0bde8ff712363cbfb98e9d2f90cfe98b208e 1c163f4c7b3f621efff9b28a47abb36f7378d783 --
git bisect bad 086da5d945417d7f23267ba57285baf5f28db938 # 11:42 B 869 9 0 34 Merge 'linux-review/David-Ahern/selftests-rtnetlink-use-internal-netns-switch-for-ip-commands/20190301-033905' into devel-hourly-2019030702
git bisect good 41d8a6d69a8b740e03d7bf2bb8335da4da5fdba5 # 12:30 G 900 0 35 51 Merge 'linux-review/UPDATE-20190303-105904/Jan-Stancek/mm-memory-c-do_fault-avoid-usage-of-stale-vm_area_struct/20190303-093100' into devel-hourly-2019030702
git bisect bad b9a411fadefdb5d73d8eea17ce986179ad71840d # 12:50 B 148 1 10 10 Merge 'linux-review/Felix-Fietkau/mt76-rewrite-dma-descriptor-base-and-ring-size-on-queue-reset/20190302-050418' into devel-hourly-2019030702
git bisect bad 0a6be0079c3c20149485bc92250e45d84d075541 # 13:06 B 57 1 7 7 Merge 'linux-review/Heiner-Kallweit/net-dsa-mv8e6xxx-fix-number-of-internal-PHYs-for-88E6x90-family/20190302-202650' into devel-hourly-2019030702
git bisect good 821ec529ff50b8937708f47f094287f6e2b49e16 # 13:52 G 909 0 50 50 Merge 'linux-review/Chao-Yu/f2fs-fix-to-do-sanity-check-with-inode-i_inline_xattr_size/20190304-203228' into devel-hourly-2019030702
git bisect good 67af7dacace3a333b1d881b95dc689a2dd9e2589 # 14:30 G 905 0 52 52 Merge 'linux-review/Kimberly-Brown/Drivers-hv-vmbus-Expose-monitor-data-only-when-monitor-pages-are-used/20190302-231508' into devel-hourly-2019030702
git bisect good 46f2ee728daf6a85ca1e353d4fafd9be2ce7ddfd # 15:28 G 901 0 49 53 Merge 'linux-review/Yue-Haibing/net-sysfs-Fix-mem-leak-in-netdev_register_kobject/20190302-220141' into devel-hourly-2019030702
git bisect good 3f1a8f0976fe16a388c23feeb38a860caf826fa0 # 16:26 G 901 0 52 58 Merge 'linux-review/Yufen-Yu/hugetlbfs-fix-memory-leak-for-resv_map/20190302-214353' into devel-hourly-2019030702
git bisect good 8d8ae51f4bf9515ed07cb438037a129a0851bc60 # 17:22 G 901 0 49 58 Merge 'linux-review/Govind-Singh/ath10k-Modify-CE4-src-buffer-entries-to-2048-for-WCN3990/20190302-210221' into devel-hourly-2019030702
git bisect bad 36d329873d82094062917361129c8ef95addbb65 # 17:45 B 73 1 6 6 Merge 'peterz-queue/locking/core' into devel-hourly-2019030702
git bisect good 0614621d89c43ea5b28456c2baf6b0c0e00ca81e # 18:36 G 905 0 46 60 Merge branch 'linus' into locking/core, to pick up fixes
git bisect good a0b0fd53e1e67639b303b15939b9c653dbe7a8c4 # 19:32 G 900 0 50 63 locking/lockdep: Free lock classes that are no longer in use
git bisect good 108c14858b9ea224686e476c8f5ec345a0df9e27 # 20:31 G 908 0 43 53 locking/lockdep: Add support for dynamic keys
git bisect bad f214737b75b0ee79763b5c058b9d5e83d711348d # 21:06 B 101 1 11 19 lockdep/lib/tests: Test dynamic key registration
git bisect bad d93ac78bf7b37db36fa00225f8e9a14c7ed1b2ba # 21:53 B 44 1 3 3 lockdep/lib/tests: Fix run_tests.sh
git bisect bad 669de8bda87b92ab9a2fc663b3f5743c2ad1ae9f # 22:31 B 155 3 12 28 kernel/workqueue: Use dynamic lockdep keys for workqueues
# first bad commit: [669de8bda87b92ab9a2fc663b3f5743c2ad1ae9f] kernel/workqueue: Use dynamic lockdep keys for workqueues
git bisect good 108c14858b9ea224686e476c8f5ec345a0df9e27 # 23:11 G 1002 0 9 62 locking/lockdep: Add support for dynamic keys
# extra tests on HEAD of linux-devel/devel-hourly-2019030702
git bisect bad f32e0bde8ff712363cbfb98e9d2f90cfe98b208e # 23:11 B 10 2 0 1 0day head guard for 'devel-hourly-2019030702'
# extra tests on tree/branch linus/master
git bisect bad f90d64483ebd394958841f67f8794ab203b319a7 # 23:53 B 468 1 22 22 Merge tag 'usb-5.1-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb
# extra tests with first bad commit reverted
git bisect good f2abe7f085951f49dc69a634d74a4d027d77c9f7 # 12:42 G 907 0 55 55 Revert "kernel/workqueue: Use dynamic lockdep keys for workqueues"
# extra tests on tree/branch linux-next/master
git bisect bad cf08baa29613dd899954089e7cc7dba1d478b365 # 12:46 B 11 1 0 0 Add linux-next specific files for 20190306
---
0-DAY kernel test infrastructure Open Source Technology Center
https://lists.01.org/pipermail/lkp Intel Corporation
Download attachment "dmesg-openwrt-vm-openwrt-111:20190307222808:i386-randconfig-s1-201909:5.0.0-rc8-00054-g669de8b:496.gz" of type "application/gzip" (13512 bytes)
Download attachment "dmesg-openwrt-vm-openwrt-216:20190307195050:i386-randconfig-s1-201909:5.0.0-rc8-00053-g108c148:480.gz" of type "application/gzip" (14298 bytes)
View attachment "reproduce-openwrt-vm-openwrt-111:20190307222808:i386-randconfig-s1-201909:5.0.0-rc8-00054-g669de8b:496" of type "text/plain" (912 bytes)
View attachment "config-5.0.0-rc8-00054-g669de8b" of type "text/plain" (99920 bytes)
Powered by blists - more mailing lists