[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <20171121100430.pv2hn4caddrrirqs@wfg-t540p.sh.intel.com>
Date: Tue, 21 Nov 2017 18:04:30 +0800
From: Fengguang Wu <fengguang.wu@...el.com>
To: Peter Zijlstra <peterz@...radead.org>
Cc: Ingo Molnar <mingo@...hat.com>,
Chris Wilson <chris@...is-wilson.co.uk>,
Linus Torvalds <torvalds@...ux-foundation.org>,
linux-kernel@...r.kernel.org, lkp@...org
Subject: [test_abba] WARNING: possible circular locking dependency detected
Hello,
FYI this happens in mainline kernel 4.14.0-12891-gc8a0739.
It looks like a new regression after 4.14.
It occurs in 2 out of 2 boots.
[ 1.588989] spin_lock-torture: Creating lock_torture_stats task
[ 1.589710] spin_lock-torture: lock_torture_writer task started
[ 1.590645] spin_lock-torture: lock_torture_stats task started
[ 2.100149]
[ 2.100363] ======================================================
[ 2.101009] WARNING: possible circular locking dependency detected
[ 2.101645] 4.14.0-12891-gc8a0739 #1 Not tainted
[ 2.102150] ------------------------------------------------------
[ 2.102783] kworker/0:1/14 is trying to acquire lock:
[ 2.103312] (ww_class_mutex){+.+.}, at: [<ffffffff8115fd09>] test_abba_work+0xd9/0x35e:
test_abba_work at kernel/locking/test-ww_mutex.c:179
[ 2.104009]
[ 2.104009] but now in release context of a crosslock acquired at the following:
[ 2.104009] ((completion)&abba.b_ready){+.+.}, at: [<ffffffff81160132>] test_abba+0x1a4/0x3c0:
test_abba at kernel/locking/test-ww_mutex.c:218
[ 2.104009]
[ 2.104009] which lock already depends on the new lock.
[ 2.104009]
[ 2.104009] the existing dependency chain (in reverse order) is:
[ 2.104009]
[ 2.104009] -> #1 ((completion)&abba.b_ready){+.+.}:
[ 2.104009] wait_for_completion+0x5e/0x220:
spin_lock_irq at include/linux/spinlock.h:340
(inlined by) __wait_for_common at kernel/sched/completion.c:111
(inlined by) wait_for_common at kernel/sched/completion.c:123
(inlined by) wait_for_completion at kernel/sched/completion.c:144
[ 2.104009] test_abba+0x1a4/0x3c0:
test_abba at kernel/locking/test-ww_mutex.c:218
[ 2.104009] test_ww_mutex_init+0xcc/0x3e1:
test_ww_mutex_init at kernel/locking/test-ww_mutex.c:610
[ 2.104009] do_one_initcall+0xac/0x1c7:
do_one_initcall at init/main.c:826
[ 2.104009] kernel_init_freeable+0x116/0x1db:
do_initcall_level at init/main.c:891
(inlined by) do_initcalls at init/main.c:900
(inlined by) do_basic_setup at init/main.c:918
(inlined by) kernel_init_freeable at init/main.c:1066
[ 2.104009] kernel_init+0xa/0x160:
kernel_init at init/main.c:995
[ 2.104009] ret_from_fork+0x24/0x30:
ret_from_fork at arch/x86/entry/entry_64.S:443
[ 2.104009]
[ 2.104009] -> #0 (ww_class_mutex){+.+.}:
[ 2.104009] test_abba_work+0xd9/0x35e:
test_abba_work at kernel/locking/test-ww_mutex.c:179
[ 2.104009]
[ 2.104009] other info that might help us debug this:
[ 2.104009]
[ 2.104009] Possible unsafe locking scenario by crosslock:
[ 2.104009]
[ 2.104009] CPU0 CPU1
[ 2.104009] ---- ----
[ 2.104009] lock(ww_class_mutex);
[ 2.104009] lock((completion)&abba.b_ready);
[ 2.104009] lock(ww_class_mutex);
[ 2.104009] unlock((completion)&abba.b_ready);
[ 2.104009]
[ 2.104009] *** DEADLOCK ***
[ 2.104009]
[ 2.104009] 5 locks held by kworker/0:1/14:
[ 2.104009] #0: ((wq_completion)"events"){+.+.}, at: [<ffffffff8111a46b>] process_one_work+0x32b/0xae0:
set_work_data at kernel/workqueue.c:617
(inlined by) set_work_pool_and_clear_pending at kernel/workqueue.c:645
(inlined by) process_one_work at kernel/workqueue.c:2083
[ 2.104009] #1: ((work_completion)(&abba.work)){+.+.}, at: [<ffffffff8111a46b>] process_one_work+0x32b/0xae0:
set_work_data at kernel/workqueue.c:617
(inlined by) set_work_pool_and_clear_pending at kernel/workqueue.c:645
(inlined by) process_one_work at kernel/workqueue.c:2083
[ 2.104009] #2: (ww_class_acquire){+.+.}, at: [<ffffffff8111a62c>] process_one_work+0x4ec/0xae0:
__read_once_size at include/linux/compiler.h:178
(inlined by) atomic_read at arch/x86/include/asm/atomic.h:27
(inlined by) static_key_count at include/linux/jump_label.h:191
(inlined by) static_key_false at include/linux/jump_label.h:201
(inlined by) trace_workqueue_execute_end at include/trace/events/workqueue.h:112
(inlined by) process_one_work at kernel/workqueue.c:2117
[ 2.104009] #3: (ww_class_mutex){+.+.}, at: [<ffffffff8115fd09>] test_abba_work+0xd9/0x35e:
test_abba_work at kernel/locking/test-ww_mutex.c:179
[ 2.104009] #4: (&x->wait#5){....}, at: [<ffffffff8114a538>] complete+0x18/0x70:
complete_release_commit at include/linux/completion.h:50
(inlined by) complete at kernel/sched/completion.c:40
[ 2.104009]
[ 2.104009] stack backtrace:
[ 2.104009] CPU: 0 PID: 14 Comm: kworker/0:1 Not tainted 4.14.0-12891-gc8a0739 #1
[ 2.104009] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
[ 2.104009] Workqueue: events test_abba_work
[ 2.104009] Call Trace:
[ 2.104009] print_circular_bug+0x2d8/0x2f0:
print_circular_bug at kernel/locking/lockdep.c:1274
[ 2.104009] check_prev_add+0x150/0x700:
check_prev_add at kernel/locking/lockdep.c:1914
[ 2.104009] ? zap_class+0xe0/0xe0:
copy_trace at kernel/locking/lockdep.c:4984
[ 2.104009] ? lock_commit_crosslock+0x4df/0x600:
commit_xhlock at kernel/locking/lockdep.c:5023
(inlined by) commit_xhlocks at kernel/locking/lockdep.c:5067
(inlined by) lock_commit_crosslock at kernel/locking/lockdep.c:5106
[ 2.104009] lock_commit_crosslock+0x4df/0x600:
commit_xhlock at kernel/locking/lockdep.c:5023
(inlined by) commit_xhlocks at kernel/locking/lockdep.c:5067
(inlined by) lock_commit_crosslock at kernel/locking/lockdep.c:5106
[ 2.104009] ? do_raw_spin_lock+0xbe/0x100:
debug_spin_lock_before at kernel/locking/spinlock_debug.c:85
(inlined by) do_raw_spin_lock at kernel/locking/spinlock_debug.c:112
[ 2.104009] complete+0x25/0x70:
complete at kernel/sched/completion.c:42
[ 2.104009] test_abba_work+0xe5/0x35e:
test_abba_work at kernel/locking/test-ww_mutex.c:180
[ 2.104009] ? process_one_work+0x4ec/0xae0:
__read_once_size at include/linux/compiler.h:178
(inlined by) atomic_read at arch/x86/include/asm/atomic.h:27
(inlined by) static_key_count at include/linux/jump_label.h:191
(inlined by) static_key_false at include/linux/jump_label.h:201
(inlined by) trace_workqueue_execute_end at include/trace/events/workqueue.h:112
(inlined by) process_one_work at kernel/workqueue.c:2117
[ 2.104009] process_one_work+0x4ec/0xae0:
__read_once_size at include/linux/compiler.h:178
(inlined by) atomic_read at arch/x86/include/asm/atomic.h:27
(inlined by) static_key_count at include/linux/jump_label.h:191
(inlined by) static_key_false at include/linux/jump_label.h:201
(inlined by) trace_workqueue_execute_end at include/trace/events/workqueue.h:112
(inlined by) process_one_work at kernel/workqueue.c:2117
[ 2.104009] worker_thread+0x3d8/0x6c0:
__read_once_size at include/linux/compiler.h:178
(inlined by) list_empty at include/linux/list.h:203
(inlined by) worker_thread at kernel/workqueue.c:2247
[ 2.104009] ? process_one_work+0xae0/0xae0:
worker_thread at kernel/workqueue.c:2189
[ 2.104009] kthread+0x1a1/0x1b0:
kthread at kernel/kthread.c:240
[ 2.104009] ? __kthread_bind_mask+0x40/0x40
[ 2.104009] ret_from_fork+0x24/0x30:
ret_from_fork at arch/x86/entry/entry_64.S:443
[ 2.592101] tsc: Refined TSC clocksource calibration: 2693.508 MHz
[ 2.592788] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x26d349e8249, max_idle_ns: 440795288087 ns
[ 8.156610] torture_init_begin: Refusing rcu init: spin_lock running.
[ 8.157659] torture_init_begin: One torture test at a time!
[ 8.161633] Initialise system trusted keyrings
Attached the full dmesg, kconfig and reproduce scripts.
Thanks,
Fengguang
View attachment "dmesg-vm-ivb41-yocto-ia32-10:20171120163240:x86_64-randconfig-h0-11121445:4.14.0-12891-gc8a0739:1" of type "text/plain" (59902 bytes)
View attachment ".config" of type "text/plain" (104643 bytes)
View attachment "job-script" of type "text/plain" (3786 bytes)
View attachment "reproduce-vm-ivb41-yocto-ia32-10:20171120163240:x86_64-randconfig-h0-11121445:4.14.0-12891-gc8a0739:1" of type "text/plain" (2135 bytes)
Powered by blists - more mailing lists