Skip to contentSkip to conversation

improve spinlock debugging

PATCH In review Manfred Spraul 7 participants 18 messages Dec 4, 2001 – Dec 20, 2001

Subsystems (2)
lore
Share & tools
lore
#0 lore raw

PATCH 1/1 improve spinlock debugging

CONFIG_DEBUG_SPINLOCK only adds spinlock tests for SMP builds. The attached patch adds runtime checks for uniprocessor builds.

Tested on i386/UP, but it should work on all platforms. It contains runtime checks for:

- missing initialization
- recursive lock
- double unlock
- incorrect use of spin_is_locked() or spin_trylock() [both function do not work as expected on uniprocessor builds]
The next step are checks for spinlock ordering mismatches.

Which other runtime checks are possible?
Tests for correct _irq usage are not possible, several drivers use disable_irq().

--
Manfred

// $Header$
// Kernel Version:

//  VERSION = 2
//  PATCHLEVEL = 5
//  SUBLEVEL = 1
//  EXTRAVERSION =-pre5
include/linux/spinlock.h +93 -13
@@ -37,12 +37,13 @@
 
 #ifdef CONFIG_SMP
 #include <asm/spinlock.h>
+#else
 
-#elif !defined(spin_lock_init) /* !SMP and spin_lock_init not previously
-                                  defined (e.g. by including asm/spinlock.h */
-
-#define DEBUG_SPINLOCKS	0	/* 0 == no debugging, 1 == maintain lock state, 2 == full debug */
-
+#ifdef CONFIG_DEBUG_SPINLOCK
+#define DEBUG_SPINLOCKS	2	/* 0 == no debugging, 1 == maintain lock state, 2 == full debug */
+#else
+#define DEBUG_SPINLOCKS	0
+#endif
 #if (DEBUG_SPINLOCKS < 1)
 
 #define atomic_dec_and_lock(atomic,lock) atomic_dec_and_test(atomic)
@@ -85,22 +86,101 @@
 
 #else /* (DEBUG_SPINLOCKS >= 2) */
 
+#define SPINLOCK_MAGIC	0x1D244B3C
 typedef struct {
+	unsigned long magic;
 	volatile unsigned long lock;
 	volatile unsigned int babble;
 	const char *module;
+	char *owner;
+	int oline;
 } spinlock_t;
-#define SPIN_LOCK_UNLOCKED (spinlock_t) { 0, 25, __BASE_FILE__ }
+#define SPIN_LOCK_UNLOCKED (spinlock_t) { SPINLOCK_MAGIC, 0, 10, __FILE__ , NULL, 0}
 
 #include <linux/kernel.h>
 
-#define spin_lock_init(x)	do { (x)->lock = 0; } while (0)
-#define spin_is_locked(lock)	(test_bit(0,(lock)))
-#define spin_trylock(lock)	(!test_and_set_bit(0,(lock)))
-
-#define spin_lock(x)		do {unsigned long __spinflags; save_flags(__spinflags); cli(); if ((x)->lock&&(x)->babble) {printk("%s:%d: spin_lock(%s:%p) already locked\n", __BASE_FILE__,__LINE__, (x)->module, (x));(x)->babble--;} (x)->lock = 1; restore_flags(__spinflags);} while (0)
-#define spin_unlock_wait(x)	do {unsigned long __spinflags; save_flags(__spinflags); cli(); if ((x)->lock&&(x)->babble) {printk("%s:%d: spin_unlock_wait(%s:%p) deadlock\n", __BASE_FILE__,__LINE__, (x)->module, (x));(x)->babble--;} restore_flags(__spinflags);} while (0)
-#define spin_unlock(x)		do {unsigned long __spinflags; save_flags(__spinflags); cli(); if (!(x)->lock&&(x)->babble) {printk("%s:%d: spin_unlock(%s:%p) not locked\n", __BASE_FILE__,__LINE__, (x)->module, (x));(x)->babble--;} (x)->lock = 0; restore_flags(__spinflags);} while (0)
+#define spin_lock_init(x) \
+	do { \
+		(x)->magic = SPINLOCK_MAGIC; \
+		(x)->lock = 0; \
+		(x)->babble = 5; \
+		(x)->module = __FILE__; \
+		(x)->owner = NULL; \
+		(x)->oline = 0; \
+	} while (0)
+#define CHECK_LOCK(x) \
+	do { \
+	 	if ((x)->magic != SPINLOCK_MAGIC) { \
+			printk(KERN_ERR "%s:%d: spin_is_locked on uninitialized spinlock %p.\n", \
+					__FILE__, __LINE__, (x)); \
+		} \
+	} while(0)
+/* without debugging, spin_is_locked on UP always says
+ * FALSE. --> printk if already locked. */
+#define spin_is_locked(x) \
+	({ \
+	 	CHECK_LOCK(x); \
+		if ((x)->lock&&(x)->babble) { \
+			printk("%s:%d: spin_is_locked(%s:%p) already locked by %s/%d\n", \
+					__FILE__,__LINE__, (x)->module, \
+					(x), (x)->owner, (x)->oline); \
+			(x)->babble--; \
+		} \
+		0; \
+	})
+
+/* without debugging, spin_trylock on UP always says
+ * TRUE. --> printk if already locked. */
+#define spin_trylock(x) \
+	({ \
+	 	CHECK_LOCK(x); \
+		if ((x)->lock&&(x)->babble) { \
+			printk("%s:%d: spin_trylock(%s:%p) already locked by %s/%d\n", \
+					__FILE__,__LINE__, (x)->module, \
+					(x), (x)->owner, (x)->oline); \
+			(x)->babble--; \
+		} \
+		(x)->lock = 1; \
+		(x)->owner = __FILE__; \
+		(x)->oline = __LINE__; \
+		1; \
+	})
+
+#define spin_lock(x)		\
+	do { \
+	 	CHECK_LOCK(x); \
+		if ((x)->lock&&(x)->babble) { \
+			printk("%s:%d: spin_lock(%s:%p) already locked by %s/%d\n", \
+					__FILE__,__LINE__, (x)->module, \
+					(x), (x)->owner, (x)->oline); \
+			(x)->babble--; \
+		} \
+		(x)->lock = 1; \
+		(x)->owner = __FILE__; \
+		(x)->oline = __LINE__; \
+	} while (0)
+
+#define spin_unlock_wait(x)	\
+	do { \
+	 	CHECK_LOCK(x); \
+		if ((x)->lock&&(x)->babble) { \
+			printk("%s:%d: spin_unlock_wait(%s:%p) owned by %s/%d\n", \
+					__FILE__,__LINE__, (x)->module, (x), \
+					(x)->owner, (x)->oline); \
+			(x)->babble--; \
+		}\
+	} while (0)
+
+#define spin_unlock(x) \
+	do { \
+	 	CHECK_LOCK(x); \
+		if (!(x)->lock&&(x)->babble) { \
+			printk("%s:%d: spin_unlock(%s:%p) not locked\n", \
+					__FILE__,__LINE__, (x)->module, (x));\
+			(x)->babble--; \
+		} \
+		(x)->lock = 0; \
+	} while (0)
 
 #endif	/* DEBUG_SPINLOCKS */
 
kernel/ksyms.c +1 -1
@@ -381,10 +381,10 @@
 EXPORT_SYMBOL(tq_timer);
 EXPORT_SYMBOL(tq_immediate);
 
-#ifdef CONFIG_SMP
 /* Various random spinlocks we want to export */
 EXPORT_SYMBOL(tqueue_lock);
 
+#ifdef CONFIG_SMP
 /* Big-Reader lock implementation */
 EXPORT_SYMBOL(__brlock_array);
 #ifndef __BRLOCK_USE_ATOMICS
Documentation/Configure.help +4 -2
@@ -23565,8 +23565,10 @@
 
 Spinlock debugging
 CONFIG_DEBUG_SPINLOCK
-  Say Y here and build SMP to catch missing spinlock initialization
-  and certain other kinds of spinlock errors commonly made.  This is
+  Say Y here to add additional runtime checks into the spinlock
+  functions. On UP it detects missing initializations and simple
+  deadlocks. On SMP it finds missing initializations and certain other
+  kinds of spinlock errors commonly made, excluding deadlocks. This is
   best used in conjunction with the NMI watchdog so that spinlock
   deadlocks are also debuggable.
 
#1 lore raw

From: Manfred Spraul <[email protected]>
Date: Mon, 03 Dec 2001 21:10:27 +0100

Which other runtime checks are possible?
Tests for correct _irq usage are not possible, several drivers use disable_irq().

Keep track of how many locks are being held at once, and check if it is zero at switch_to() time. You can also do this to measure things like max number of locks held at once and other statistics.

I added the first bit to sparc64 while hunting down a bug.

#2 lore raw
Quoted 5 lines · David S. Miller

Keep track of how many locks are being held at once, and check if it is zero at switch_to() time. You can also do this to measure things like max number of locks held at once and other statistics.

I added the first bit to sparc64 while hunting down a bug.

Another interesting idea is see if a lock is held during a call to udelay.

Once you get a lock count, a lot is possible. I have looked into doing some of these tests with the preemptible kernel patch. Since the preemption count is essential the lock depth, we have quick access to all this data.

Robert Love

#3 lore raw
In reply to Manfred Spraul
Quoted 7 lines · Manfred Spraul

CONFIG_DEBUG_SPINLOCK only adds spinlock tests for SMP builds. The attached patch adds runtime checks for uniprocessor builds.

Tested on i386/UP, but it should work on all platforms. It contains runtime checks for:

Quoted 6 lines

- missing initialization
- recursive lock
- double unlock
- incorrect use of spin_is_locked() or spin_trylock() [both function do not work as expected on uniprocessor builds]
The next step are checks for spinlock ordering mismatches.

What do you consider an order mismatch? I would like to see this:

spin_lockirq

spin_unlock

restore_irq

go away. I.e. xx_lockirq should be paired with xx_unlockirq. If exceptions are needed, we should provide macros that explicitly do this such as:

spin_unlock_leaveirq_off

or some such.

Of course, all this is predicated on using the lock macros in a different way than intended. For example, preemption currently counts up on spin_lock and disable irq, counting the spin_lockirq twice. In fact, it need only count it once, if the locks are properly paired. It might also be nice to have a set of lock routines that make explicit the assumptions made. For example:

read_lock_irq_assumed_off or read_lockirq_assumed_on (used instead of saveirq based on the assumption)

These locks could then have optional debug code that tested the assumption.

If we got all of this clean enough, we would know when we were locking with irq off and the preemption patch, for example, would not need to count the spinlock at all, but just the irq. (Oh, and since the irq inhibits preemption all by itself, we don't need to count it either.)

Quoted 4 lines

Which other runtime checks are possible?
Tests for correct _irq usage are not possible, several drivers use disable_irq().

Run time checks for xxx_irq when irq is already off seem reasonable. The implication is that the xxx_unlockirq will then turn it on, which most likely is an error. Also, see above about rolling assumptions in to the macro name.

Quoted 4 lines

--
Manfred

Signature · 3 lines
George           [email protected]
High-res-timers: http://sourceforge.net/projects/high-res-timers/
Real time sched: http://sourceforge.net/projects/rtsched/
#4 lore raw
Quoted 5 lines · george anzinger

spin_lockirq

spin_unlock

restore_irq

Given this order, couldn't we _always_ not touch the preempt count since irq's are off?

Further, since I doubt we ever see:

spin_lock_irq
restore_irq
spin_unlock

and the common use is:

spin_lock_irq
spin_unlock_irq

Isn't it safe to have spin_lock_irq *never* touch the preempt count?

Robert Love

#5 lore raw
Quoted 10 lines · Robert Love
Quoted 5 lines · george anzinger

spin_lockirq

spin_unlock

restore_irq

Given this order, couldn't we _always_ not touch the preempt count since irq's are off?

Not with the current spinlock usage in the kernel. spin_lock/spin_unlock are used both nested when interrupts are known to be disabled (as above) or, more commonly,

spin_lock_irqsave(a, flags)

spin_lock(b)

spin_unlock(b)

spin_unlock_irqrestore(a, flags)

and when interrupts are enabled:

spin_lock(c)

spin_unlock(c)

We don't need to preempt count the former but we do the latter, but there's no way to tell the difference without a runtime check for interrupt state.

In IRIX we changed the name of the former, nested versions to:

spin_lock_irqsave(a, flags)

nested_spin_lock(b)

nested_spin_unlock(b)

spin_unlock_irqrestore(a, flags)

The nested version contained an assertion that interrupts were disabled in DEBUG kernels. We wouldn't need to count the nested_spin_lock versions.

Quoted 5 lines

Further, since I doubt we ever see:

spin_lock_irq
restore_irq
spin_unlock

I hope not, since that would be a bug.

Quoted 6 lines

and the common use is:

spin_lock_irq
spin_unlock_irq

Isn't it safe to have spin_lock_irq *never* touch the preempt count?

No, because of

Quoted 5 lines
Quoted 5 lines

spin_lockirq

spin_unlock

restore_irq

(which does occasionally occur in the kernel). The spin_unlock is going to decrement the count, so the spin_lock_irqsave must increment it. If we had, and used, a nested_spin_unlock, we could then have spin_lock_irq never touch the preempt count.

[And if we could guarantee that all spinlocks we held for only a few 10s of microseconds at the most (a big "if"), we could make them all into spin_lock_irqs and then we wouldn't need the preempt count at all. This is how REAL/IX and IRIX implemented kernel preemption.]

Nigel Gamble [email protected]
Mountain View, CA, USA. http://www.nrg.org/

#6 lore raw
Quoted 13 lines · Nigel Gamble
Quoted 2 lines

Given this order, couldn't we _always_ not touch the preempt count since irq's are off?

Not with the current spinlock usage in the kernel. spin_lock/spin_unlock are used both nested when interrupts are known to be disabled (as above) or, more commonly,

spin_lock_irqsave(a, flags)

spin_lock(b)

spin_unlock(b)

Quoted 7 lines

spin_unlock_irqrestore(a, flags)

and when interrupts are enabled:

spin_lock(c)

spin_unlock(c)

Right, I meant just the spin_lock_irq case, which would be fine except for the case where:

spin_lock_irq
spin_unlock
restore_irq

to solve this, we need a spin_unlock_irq_on macro that didn't touch the preemption count.

Quoted 10 lines

We don't need to preempt count the former but we do the latter, but there's no way to tell the difference without a runtime check for interrupt state.

In IRIX we changed the name of the former, nested versions to:

spin_lock_irqsave(a, flags)

nested_spin_lock(b)

Quoted 7 lines

nested_spin_unlock(b)

spin_unlock_irqrestore(a, flags)

The nested version contained an assertion that interrupts were disabled in DEBUG kernels. We wouldn't need to count the nested_spin_lock versions.

Ah, another optimization wrt preempt count. This goes further than just making spin_lock_irqsave not touch the preempt count, in that it also let's us say (this lock is _always_ nested inside another, we don't need to touch the preempt count).

It would apply anywhere we grab multiple locks and drop the first one last.

Quoted 19 lines
Quoted 5 lines

Further, since I doubt we ever see:

spin_lock_irq
restore_irq
spin_unlock

I hope not, since that would be a bug.

Quoted 6 lines

and the common use is:

spin_lock_irq
spin_unlock_irq

Isn't it safe to have spin_lock_irq *never* touch the preempt count?

No, because of

Quoted 2 lines
Quoted 2 lines

spin_lockirq

Quoted 8 lines
Quoted 3 lines
Quoted 3 lines

spin_unlock

restore_irq

(which does occasionally occur in the kernel). The spin_unlock is going to decrement the count, so the spin_lock_irqsave must increment it. If we had, and used, a nested_spin_unlock, we could then have spin_lock_irq never touch the preempt count.

Right.

Quoted 4 lines

[And if we could guarantee that all spinlocks we held for only a few 10s of microseconds at the most (a big "if"), we could make them all into spin_lock_irqs and then we wouldn't need the preempt count at all. This is how REAL/IX and IRIX implemented kernel preemption.]

I offered that idea and George convinced me otherwise :)

Robert Love

#7 lore raw
In reply to Nigel Gamble

Hi,

Quoted 9 lines · Robert Love

Right, I meant just the spin_lock_irq case, which would be fine except for the case where:

spin_lock_irq
spin_unlock
restore_irq

to solve this, we need a spin_unlock_irq_on macro that didn't touch the preemption count.

Has someone a real example of something like this?
I'd suspect someone is trying a (questionable) micro optimization or is holding the lock for too long anyway. Instead of adding more macros, maybe it's better to look closely whether something needs fixing.

bye, Roman

#8 lore raw
In reply to Nigel Gamble
Quoted 12 lines · Roman Zippel

Hi,

Quoted 7 lines · Robert Love

Right, I meant just the spin_lock_irq case, which would be fine except for the case where:

spin_lock_irq
spin_unlock
restore_irq

Quoted 8 lines
Quoted 2 lines

to solve this, we need a spin_unlock_irq_on macro that didn't touch the preemption count.

Has someone a real example of something like this?
I'd suspect someone is trying a (questionable) micro optimization or is holding the lock for too long anyway. Instead of adding more macros, maybe it's better to look closely whether something needs fixing.

Oh it is in there somewhere. I tried to do the indicated thing for preemption and ran aground on it. Grep drivers for spin_lock_irq (or irq save). I don't remember which, but there is more than one.

Signature · 3 lines
George           [email protected]
High-res-timers: http://sourceforge.net/projects/high-res-timers/
Real time sched: http://sourceforge.net/projects/rtsched/
#9 lore raw
In reply to george anzinger
Quoted 2 lines · george anzinger

For example, preemption currently counts
up on spin_lock and disable irq, counting the spin_lockirq twice. In

That's not correct: we don't count it twice because we don't count local_irq_disable etc., only the spin locks. Because...

Quoted 2 lines

(Oh, and since the irq
inhibits preemption all by itself, we don't need to count it either.)

...so we don't.

Nigel Gamble [email protected]
Mountain View, CA, USA. http://www.nrg.org/

#10 lore raw
Quoted 5 lines · Nigel Gamble
Quoted 2 lines · george anzinger

For example, preemption currently counts
up on spin_lock and disable irq, counting the spin_lockirq twice. In

Quoted 7 lines

That's not correct: we don't count it twice because we don't count local_irq_disable etc., only the spin locks. Because...

Quoted 2 lines

(Oh, and since the irq
inhibits preemption all by itself, we don't need to count it either.)

...so we don't.

Right, but we do count spin_lockirq (just once). See other email, this time.

Signature · 3 lines
George           [email protected]
High-res-timers: http://sourceforge.net/projects/high-res-timers/
Real time sched: http://sourceforge.net/projects/rtsched/
#11 lore raw
In reply to Manfred Spraul
Quoted 18 lines · Robert Love
Quoted 5 lines · george anzinger

spin_lockirq

spin_unlock

restore_irq

Given this order, couldn't we _always_ not touch the preempt count since irq's are off?

Further, since I doubt we ever see:

spin_lock_irq
restore_irq
spin_unlock

Quoted 7 lines

and the common use is:

spin_lock_irq
spin_unlock_irq

Isn't it safe to have spin_lock_irq *never* touch the preempt count?

NO. The problem is the first example above. The spin_unlock will down count, but the spin_lockirq did NOT do the paired up count (been there, done that). This is where we need the spin_unlock_no_irq_restore.

Signature · 3 lines
George           [email protected]
High-res-timers: http://sourceforge.net/projects/high-res-timers/
Real time sched: http://sourceforge.net/projects/rtsched/
#12 lore raw
Quoted 3 lines · george anzinger

NO. The problem is the first example above. The spin_unlock will down count, but the spin_lockirq did NOT do the paired up count (been there, done that). This is where we need the spin_unlock_no_irq_restore.

Your right, I thought too fast. Then we need the proper macros ...

Robert Love

#13 lore raw
In reply to Manfred Spraul
Quoted 9 lines · george anzinger
Quoted 7 lines · Manfred Spraul

CONFIG_DEBUG_SPINLOCK only adds spinlock tests for SMP builds. The attached patch adds runtime checks for uniprocessor builds.

Tested on i386/UP, but it should work on all platforms. It contains runtime checks for:

Quoted 9 lines
Quoted 6 lines

- missing initialization
- recursive lock
- double unlock
- incorrect use of spin_is_locked() or spin_trylock() [both function do not work as expected on uniprocessor builds]
The next step are checks for spinlock ordering mismatches.

What do you consider an order mismatch? I would like to see this:

	spin_lock(a);
	spin_lock(b);

and somewhere else

	spin_lock(b);
	spin_lock(a);
Quoted 6 lines

Run time checks for xxx_irq when irq is already off seem reasonable. The implication is that the xxx_unlockirq will then turn it on, which most likely is an error. Also, see above about rolling assumptions in to the macro name.

Unfortuantely there are still a few special cases where spin_lock_irq() with already disabled interrupts is both intentional and correct^wnot buggy (search for sleep_on and cli() through the lkml archives).

And there are optimizations such as

	spin_lock_bh(a);
	spin_unlock(b);
	spin_lock(b);
	spin_unlock_bh(b);

--
Manfred

#14 lore raw
In reply to Manfred Spraul
Quoted 37 lines · Manfred Spraul
Quoted 9 lines · george anzinger
Quoted 7 lines · Manfred Spraul

CONFIG_DEBUG_SPINLOCK only adds spinlock tests for SMP builds. The attached patch adds runtime checks for uniprocessor builds.

Tested on i386/UP, but it should work on all platforms. It contains runtime checks for:

Quoted 9 lines
Quoted 6 lines

- missing initialization
- recursive lock
- double unlock
- incorrect use of spin_is_locked() or spin_trylock() [both function do not work as expected on uniprocessor builds]
The next step are checks for spinlock ordering mismatches.

What do you consider an order mismatch? I would like to see this:

        spin_lock(a);
        spin_lock(b);

and somewhere else

        spin_lock(b);
        spin_lock(a);
Quoted 6 lines

Run time checks for xxx_irq when irq is already off seem reasonable. The implication is that the xxx_unlockirq will then turn it on, which most likely is an error. Also, see above about rolling assumptions in to the macro name.

Unfortuantely there are still a few special cases where spin_lock_irq() with already disabled interrupts is both intentional and correct^wnot buggy (search for sleep_on and cli() through the lkml archives).

Quoted 6 lines

And there are optimizations such as

        spin_lock_bh(a);
        spin_unlock(b);
        spin_lock(b);
        spin_unlock_bh(b);

Dam the special case! Full speed ahead!

But really, there will always be exceptions, but they should be noted (and commented upon). To hide them in obscurity, and worst yet, allow them to dictate that we can not do better is a crime. There are tricks that can be used to help us in these cases, if we just set our collective minds to it.

Signature · 3 lines
George           [email protected]
High-res-timers: http://sourceforge.net/projects/high-res-timers/
Real time sched: http://sourceforge.net/projects/rtsched/
#15 lore raw
In reply to Manfred Spraul
Quoted 4 lines

Tested on i386/UP, but it should work on all platforms. It contains runtime checks for:

Quoted 8 lines

- missing initialization
- recursive lock
- double unlock
- incorrect use of spin_is_locked() or spin_trylock() [both function do not work as expected on uniprocessor builds]
The next step are checks for spinlock ordering mismatches.

Which other runtime checks are possible?

It's very useful to log when a lock(irq) is held more than xx ms and who is the caller. Is it possible ?

Bye.

#16 lore raw
Quoted 4 lines · Giuliano Pochini

It's very useful to log when a lock(irq) is held more than xx ms and who is the caller. Is it possible ?

Have you looked at SGI's lockmeter patch?
It's very good to check performance numbers of spinlocks.

Signature · 1 line
   Manfred
#17 lore raw
In reply to Manfred Spraul
Quoted 5 lines · Anton Blanchard

What do you think of the idea below? We create arch specific spinlock functions as __foo and wrap the debugging bits around them as foo. This should also allow us to unify the UP and SMP spinlock debugging somewhat.

I tried to create a minimal patch, to reduce the probability of patch conflicts with earlier/future kernels.

I agree that your solutition is better if the patch is included in Linus/Marcelo's tree.
Have you asked Linus about it? I love runtime checks, but IIRC the majority of the kernel maintainers disagrees.

--
Manfred