Debugging managed lock deadloacks in Mono
I just committed to svn a small function that can be used to
help debug deadlocks that result from the incorrect use of
managed locks.
Managed locks (implemented in the Monitor class and usually
invoked with the lock () construct in C#) are subject to the
same incorrect uses of normal locks, though they can be
safely taken recursively by the same thread.
One of the obviously incorrect way to use locks is to have
multiple locks and acquire them in different orders in
different codepaths. Here is an example:
using System;
using System.Threading;
class TestDeadlock {
static object lockA = new object ();
static object lockB = new object ();
static void normal_order () {
lock (lockA) {
Console.WriteLine ("took lock A");
// make the deadlock more likely
Thread.Sleep (500);
lock (lockB) {
Console.WriteLine ("took lock B");
}
}
}
static void reverse_order () {
lock (lockB) {
Console.WriteLine ("took lock B");
// make the deadlock more likely
Thread.Sleep (500);
lock (lockA) {
Console.WriteLine ("took lock A");
}
}
}
static void Main () {
TestDeadlock td = new TestDeadlock ();
lock (td) {
lock (td) { // twice for testing the nest level
Thread t1 = new Thread (
new ThreadStart (normal_order));
Thread t2 = new Thread (
new ThreadStart (reverse_order));
t1.Start ();
t2.Start ();
t1.Join ();
t2.Join ();
}
}
}
}
I added an explicit Sleep () call to make the race condition
happen almost every time you run such a program. The issue
with such deadlocks is that usually the race time window is
very small and it will go unnoticed during testing. The new
feature in the mono runtime is designed to help find the
issue when a process is stuck and we don't know why.
Now you can attach to the stuck process using gdb and issue
the following command:
(gdb) call mono_locks_dump (0)
which results in output like this:
Lock 0x824f108 in object 0x2ffd8 held by thread 0xb7d496c0,
nest level: 2
Lock 0x824f150 in object 0x2ffe8 held by thread 0xb7356bb0,
nest level: 1
Waiting on semaphore 0x40e: 1
Lock 0x824f1b0 in object 0x2ffe0 held by thread 0xb7255bb0,
nest level: 1
Waiting on semaphore 0x40d: 1
Total locks (in 1 array(s)): 16, used: 8, on freelist: 8, to
recycle: 0
We can see that there are three locks currently held by
three different threads. The first has been recursively
acquired 2 times. The other two are more interesting because
they each have a thread waiting on a semaphore associated
with the lock structure: they must be the ones involved in
the deadlock.
Once we know the threads that are deadlocking and the
objects that hold the lock we might have a better idea of
where exactly to look in the code for incorrect ordering of
lock statements.
In this particular case it's pretty easy since the objects
used for locking are static fields. The easy way to get the
class is to notice that the object which is locked twice
(0x2ffd8) is of the same class as the static fields:
(gdb) call mono_object_describe (0x2ffd8)
TestDeadlock object at 0x2ffd8 (klass: 0x820922c)
Now we know the class (0x820922c) and we can get a list of
the static fields and their values and correlate with the
objects locked in the mono_locks_dump () list:
(gdb) call mono_class_describe_statics (0x820922c)
At 0x26fd0 (ofs: 0) lockA: System.Object object at 0x2ffe8
(klass: 0x820beac)
At 0x26fd4 (ofs: 4) lockB: System.Object object at 0x2ffe0
(klass: 0x820beac)
Note that the lockA and lockB objects are the ones listed
above as deadlocking.
