Possible issue with commit 6f008e72cd - locking/mutex: Fix debug checks.

From: Valdis Kletnieks
Date: Thu Apr 10 2014 - 19:25:46 EST


So recent linux-next lock up on my laptop due to a third-party module.
Bisection finds this as the source of the issue:

6f008e72cd111a119b5d8de8c5438d892aae99eb is the first bad commit
commit 6f008e72cd111a119b5d8de8c5438d892aae99eb
Author: Peter Zijlstra <peterz@xxxxxxxxxxxxx>
Date: Wed Mar 12 13:24:42 2014 +0100

locking/mutex: Fix debug checks

OK, so commit:

1d8fe7dc8078 ("locking/mutexes: Unlock the mutex without the wait_lock")

generates this boot warning when CONFIG_DEBUG_MUTEXES=y:

WARNING: CPU: 0 PID: 139 at /usr/src/linux-2.6/kernel/locking/mutex-debug.

And that makes sense, because as soon as we release the lock a
new owner can come in...

One would think that !__mutex_slowpath_needs_to_unlock()
implementations suffer the same, but for DEBUG we fall back to
mutex-null.h which has an unconditional 1 for that.

The mutex debug code requires the mutex to be unlocked after
doing the debug checks, otherwise it can find inconsistent
state.

I was finally able to get netconsole to cough up what happened:

Apr 10 18:52:23 turing-police [ 768.277732] INFO: trying to register non-static key.
Apr 10 18:52:23 turing-police [ 768.277781] the code is fine but needs lockdep annotation.
Apr 10 18:52:23 turing-police [ 768.277794] turning off the locking correctness validator.
Apr 10 18:52:23 turing-police [ 768.277819] CPU: 0 PID: 1237 Comm: Xorg Tainted: G O 3.14.0-next-20140409-dirty #202
Apr 10 18:52:23 turing-police [ 768.277925] Hardware name: Dell Inc. Latitude E6530/07Y85M, BIOS A11 03/12/2013
Apr 10 18:52:23 turing-police [ 768.277938] 0000000000000000
Apr 10 18:52:23 turing-police ffff8800c65c7c60
Apr 10 18:52:23 turing-police ffffffff81668e5f
Apr 10 18:52:23 turing-police 0000000000000000
Apr 10 18:52:23 turing-police
Apr 10 18:52:23 turing-police [ 768.277989] ffff8800c65c7cd0
Apr 10 18:52:23 turing-police ffffffff8107b9c0
Apr 10 18:52:23 turing-police ffffffff822098d0
Apr 10 18:52:23 turing-police ffff8800c74cd8f8
Apr 10 18:52:23 turing-police
Apr 10 18:52:23 turing-police [ 768.278091] ffff8800c74cd0d0
Apr 10 18:52:23 turing-police 0000000000000019
Apr 10 18:52:23 turing-police 0000000000000000
Apr 10 18:52:23 turing-police ffffffff81c2d980
Apr 10 18:52:23 turing-police
Apr 10 18:52:23 turing-police [ 768.278119] Call Trace:
Apr 10 18:52:23 turing-police [ 768.278137] [<ffffffff81668e5f>] dump_stack+0x4f/0xa2
Apr 10 18:52:23 turing-police [ 768.278153] [<ffffffff8107b9c0>] register_lock_class+0x10d/0x2bf
Apr 10 18:52:23 turing-police [ 768.278166] [<ffffffff8107d26b>] __lock_acquire+0x127/0xdd7
Apr 10 18:52:23 turing-police [ 768.278182] [<ffffffff816732aa>] ? _raw_spin_unlock+0x5b/0x67
Apr 10 18:52:23 turing-police [ 768.278196] [<ffffffff8107e25e>] lock_acquire+0xc9/0x156
Apr 10 18:52:23 turing-police [ 768.278208] [<ffffffff81079e4e>] ? down+0x11/0x55
Apr 10 18:52:23 turing-police [ 768.278305] [<ffffffff8167319e>] _raw_spin_lock_irqsave+0x44/0x55
Apr 10 18:52:23 turing-police [ 768.278317] [<ffffffff81079e4e>] ? down+0x11/0x55
Apr 10 18:52:23 turing-police [ 768.278328] [<ffffffff81079e4e>] down+0x11/0x55

A down() of an un-annotated lock (which I'll have to annotate, I guess).

But then the kernel goes off into the weeds with complaints like:

Apr 10 18:53:28 turing-police [ 833.465272] INFO: rcu_preempt detected stalls on CPUs/tasks:
Apr 10 18:53:28 turing-police {
Apr 10 18:53:28 turing-police }
Apr 10 18:53:28 turing-police (detected by 3, t=65004 jiffies, g=4552, c=4551, q=287)
Apr 10 18:53:28 turing-police [ 833.465354] INFO: Stall ended before state dump start
Apr 10 18:55:34 turing-police [ 958.896736] INFO: task systemd:1 blocked for more than 120 seconds.

from all *over* the place - systemd in a poll() syscall, ext4, snd_hda, and
a few other places. All the symptoms of busted locking leaving something
with an unintended held lock. After a bit, the box doesn't even answer
ping anymore....

I can't be sure that it's the down() call - but nothing else actually gets
*logged*. But the commit obviously changes the actual semantics of
*something*. Was this intentional?



Attachment: pgpmi8kIfgwm0.pgp
Description: PGP signature