Debugging lock issues in managed code using Windbg

Article
01/05/2007

Windbg can be helpful for locking lock issues in managed code that seem to only happen on client machines when the moon is full and the stars are aligned just right. Windbg is a minimal installation and with managed code doesn't require debug symbols to still be useful.

For my test scenario I have an application that hangs for 10 seconds at a time once a button is pressed so I start up windbg and break during the hang so I can inspect what's going on. First we check to see what the managed threads are currently running what:

0:000> ~*e!clrstack
OS Thread Id: 0x123c (0)
ESP EIP
0012eec8 7c82ed54 [GCFrame: 0012eec8] 0012ef98 7c82ed54 [HelperMethodFrame_1OBJ: 0012ef98]
System.Threading.Monitor.Enter(System.Object)
0012eff0 00cc0381 TestApp.Form1.button1_Click(System.Object, System.EventArgs)
0012f02c 7b060a6b System.Windows.Forms.Control.OnClick(System.EventArgs)
0012f03c 7b105379 System.Windows.Forms.Button.OnClick(System.EventArgs)
0012f048 7b10547f System.Windows.Forms.Button.OnMouseUp(System.Windows.Forms.MouseEventArgs)
0012f06c 7b0d02d2 System.Windows.Forms.Control.WmMouseUp(System.Windows.Forms.Message ByRef, System.Windows.Forms.MouseButtons, Int32)
0012f0b8 7b072c74 System.Windows.Forms.Control.WndProc(System.Windows.Forms.Message ByRef)
0012f0bc 7b0815a6 [InlinedCallFrame: 0012f0bc] 0012f158 7b0814c3 System.Windows.Forms.Button.WndProc(System.Windows.Forms.Message ByRef)
0012f160 7b07a72d System.Windows.Forms.Control+ControlNativeWindow.OnMessage(System.Windows.Forms.Message ByRef)
0012f164 7b07a706 System.Windows.Forms.Control+ControlNativeWindow.WndProc(System.Windows.Forms.Message ByRef)
0012f178 7b07a515 System.Windows.Forms.NativeWindow.Callback(IntPtr, Int32, IntPtr, IntPtr)
0012f324 0033216c [NDirectMethodFrameStandalone: 0012f324] System.Windows.Forms.UnsafeNativeMethods.DispatchMessageW(MSG ByRef)
0012f334 7b084766 System.Windows.Forms.Application+ComponentManager.System.Windows.Forms.UnsafeNativeMethods.IMsoComponentManager.FPushMessageLoop(Int32, Int32, Int32)
0012f3d4 7b08432d System.Windows.Forms.Application+ThreadContext.RunMessageLoopInner(Int32, System.Windows.Forms.ApplicationContext)
0012f440 7b08416b System.Windows.Forms.Application+ThreadContext.RunMessageLoop(Int32, System.Windows.Forms.ApplicationContext)
0012f470 7b0c69fe System.Windows.Forms.Application.Run(System.Windows.Forms.Form)
0012f480 00cc00a8 TestApp.Program.Main()
0012f69c 79e88f63 [GCFrame: 0012f69c]
OS Thread Id: 0x1408 (1)
Unable to walk the managed stack. The current thread is likely not a
managed thread. You can run !threads to get a list of managed threads in
the process
OS Thread Id: 0xb30 (2)
Failed to start stack walk: 80004005
OS Thread Id: 0x161c (3)
Unable to walk the managed stack. The current thread is likely not a
managed thread. You can run !threads to get a list of managed threads in
the process
OS Thread Id: 0x149c (4)
ESP EIP
011ef82c 7c82ed54 [HelperMethodFrame: 011ef82c] System.Threading.Thread.SleepInternal(Int32)
011ef880 793d80f5 System.Threading.Thread.Sleep(Int32)
011ef884 00cc042d TestApp.Form1.ThreadProc()
011ef8b4 793d7a7b System.Threading.ThreadHelper.ThreadStart_Context(System.Object)
011ef8bc 793683dd System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
011ef8d4 793d7b5c System.Threading.ThreadHelper.ThreadStart()
011efaf8 79e88f63 [GCFrame: 011efaf8]
OS Thread Id: 0x7e0 (5)
Unable to walk the managed stack. The current thread is likely not a
managed thread. You can run !threads to get a list of managed threads in
the process
OS Thread Id: 0xf94 (6)
Unable to walk the managed stack. The current thread is likely not a
managed thread. You can run !threads to get a list of managed threads in
the process
OS Thread Id: 0x5e4 (7)
Unable to walk the managed stack. The current thread is likely not a
managed thread. You can run !threads to get a list of managed threads in
the process

So we've got two managed threads: 0 (the message pumping thread) and 4. Thread 0 is currently in a call to System.Threading.Monitor.Enter which the lock statement wraps. Let's see what locks are held by the application.

0:000> !syncblk
Index SyncBlock MonitorHeld Recursion Owning Thread Info SyncBlock Owner
11 001b415c 3 1 001be180 149c 4 012cfdfc TestApp.Form1
-----------------------------
Total 11
CCW 0
RCW 0
ComClassFactory 0
Free 0

So thread 4 (which is currently sleeping) holds a lock on the object at address 012cfdfc. Let's see what type of object this is:

0:000> !DumpObj -nofields 012cfdfc
Name: TestApp.Form1
MethodTable: 008f5ac4
EEClass: 008f165c
Size: 332(0x14c) bytes
(C:\Testing\WindowsApplication17\WindowsApplication17\bin\Debug\WindowsApplication17.exe)

Thread 4 has a lock on the Form. Looking at the stack objects for thread 0 we can see the Form object right before a synchronization context.

0:000> !dso
OS Thread Id: 0x123c (0)
ESP/REG Object Name
0012edd0 012d05f4 System.Windows.Forms.WindowsFormsSynchronizationContext
0012ef00 012cfdfc TestApp.Form1
0012ef54 012f9f1c System.Threading.ThreadStart
0012ef58 012f9f3c System.Threading.Thread
0012ef64 012f9f1c System.Threading.ThreadStart
0012ef6c 012f9f3c System.Threading.Thread
0012efac 012cff60 Microsoft.Win32.SafeHandles.SafeWaitHandle
0012efd4 012cfdfc TestApp.Form1
0012eff0 012cfdfc TestApp.Form1
0012eff4 012f9f3c System.Threading.Thread
0012eff8 012cfdfc TestApp.Form1
0012effc 012ea688 System.Windows.Forms.Button
-------------- snip -----------------------
0012f46c 012ec1e0 System.Windows.Forms.ApplicationContext
0012f474 012cfdfc TestApp.Form1

We can confirm this by looking at the IL code for TestApp.Form1.button1_Click.

0:000> !dumpmt -md 008f5ac4
EEClass: 008f165c
Module: 008f2d5c
Name: TestApp.Form1
mdToken: 02000003
(C:\Testing\WindowsApplication17\WindowsApplication17\bin\Debug\WindowsApplication17.exe)
BaseSize: 0x14c
ComponentSize: 0x0
Number of IFaces in IFaceMap: 15
Slots in VTable: 376
--------------------------------------
MethodDesc Table
Entry MethodDesc JIT Name
7b05c298 7b4a5518 PreJIT System.Windows.Forms.Form.ToString()
793539c0 7913bd50 PreJIT System.Object.Equals(System.Object)
793539b0 7913bd68 PreJIT System.Object.GetHashCode()
7a4a6510 7a75bf58 PreJIT System.ComponentModel.Component.Finalize()
79361e50 7913dbd8 PreJIT System.MarshalByRefObject.GetLifetimeService()
7b0662a4 7b4a5530 PreJIT System.Windows.Forms.Form.OnResizeEnd(System.EventArgs)
------------------ snip -----------------
008f61d4 008f5a68 JIT TestApp.Form1.InitializeComponent()
008f61b0 008f5a70 JIT TestApp.Form1..ctor()
008f6cfc 008f5a78 JIT TestApp.Form1.ThreadProc()
008f6a54 008f5a80 JIT TestApp.Form1.button1_Click(System.Object, System.EventArgs)
0:000> !dumpil 008f5a80
ilAddr = 00402274
IL_0000: nop
IL_0001: ldarg.0
IL_0002: ldftn TestApp.Form1::ThreadProc
IL_0008: newobj System.Threading.ThreadStart::.ctor
IL_000d: newobj System.Threading.Thread::.ctor
IL_0012: stloc.0
IL_0013: ldloc.0
IL_0014: callvirt System.Threading.Thread::Start
IL_0019: nop
IL_001a: ldarg.0
IL_001b: ldfld TestApp.Form1::threadStarted
IL_0020: callvirt System.Threading.WaitHandle::WaitOne
IL_0025: pop
IL_0026: ldarg.0
IL_0027: dup
IL_0028: stloc.1
IL_0029: call System.Threading.Monitor::Enter
IL_002e: nop
.try
{
IL_002f: nop
IL_0030: nop
IL_0031: leave.s IL_003b
} // end .try
.finally
{
IL_0033: ldloc.1
IL_0034: call System.Threading.Monitor::Exit
IL_0039: nop
IL_003a: endfinally
} // end .finally
IL_003b: nop
IL_003c: ldloc.0
IL_003d: callvirt System.Threading.Thread::Join
IL_0042: nop
IL_0043: ret

Sure enough Form1 is passing itself to System.Threading.Monitor.Enter.

Debugging lock issues in managed code using Windbg

Additional resources