detecting deadlock in a hung C# application using windbg

Question

My multithreaded app in C# 2.0 using threadpool hangs every few weeks or so in prod.

I did a syncblk

!syncblk

Index SyncBlock MonitorHeld Recursion Owning Thread Info  SyncBlock Owner
  201 05b9493c          979         1 05bc1040   bcc  45   022f3490 System.Collections.ArrayList
 2875 05b4c914            1         1 17b99e10  1af8 290   024862d8 MyProg.MyChildClass
 3045 05b4dbec            1         1 17ca7e98  1990 664   02392120 MyProg.MyChildClass
 3046 05b4dc1c            1         1 17ca8668  1038 666   02394b00 MyProg.MyChildClass
 3194 05b4f80c            3         1 05b5b638  1594  31   02537b88 MyProg.MyChildClass 
 3072 05b4e114            1         1 17d660f0  1120 848   023dd578 MyProg.MyChildClass
 3073 05b4e144            1         1 17c45c30  1884 518   023dfc2c MyProg.MyChildClass 
 3390 05b51cfc            3         1 16cefcc0  1350 102   02768868 MyProg.MyChildClass
 3072 05b4e114            1         1 17d660f0  1120 848   023dd578 MyProg.MyChildClass
 3073 05b4e144            1         1 17c45c30  1884 518   023dfc2c MyProg.MyChildClass 

I have deleted hundreds of lines that look like this:

3073 05b4e144            1         1 17c45c30  1884 518   023dfc2c MyProg.MyChildClass 

The thread holding 979 monitors is locking an arraylist but all other threads who are waiting are trying to acquire a readerlock on a different object.

I do know which lock are all reader threads trying to acquire but I do not know who is holding that lock. How do I find that out??

All threads with MonitorHeld = 1 has the similar output of clrstack and dso. Here is the dso and clrstack output for the thread holding 979 locks (id = 45) and waiting reader threads (id = 290). Similarly, when I do ~* e !clrstack all threads with Monitor.Enter have the same stack as the clrstack on the following 2 threads

0:000> ~45e !clrstack
OS Thread Id: 0xbcc (45)
ESP       EIP     
17fbe590 77d2013d [GCFrame: 17fbe590] 
17fbe6cc 77d2013d [HelperMethodFrame: 17fbe6cc] System.Threading.Monitor.Enter(System.Object)
17fbe720 00638427 MyProg.MyParentClass.ClockTimeElapsed(System.DateTime)
17fbe798 00637cf6 MyProg.MyEngine.ClockTimeElapsed(System.Object)
17fbe830 71df843f System.Threading._TimerCallback.TimerCallback_Context(System.Object)
17fbe838 71e302ff System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
17fbe850 71df83ab System.Threading._TimerCallback.PerformTimerCallback(System.Object)
17fbe9dc 74071b4c [GCFrame: 17fbe9dc] 

0:000> ~45e!dso
OS Thread Id: 0xbcc (45)
ESP/REG  Object   Name
17fbe5a8 022a2ff4 System.Globalization.DaylightTime
17fbe5ac 022a2f3c System.Int32
17fbe5c8 02537b88 MyProg.MyChildClass
17fbe738 02537b88 MyProg.MyChildClass
17fbe740 02537b88 MyProg.MyChildClass
17fbe7ac 11572f28 System.Collections.ArrayList+ArrayListEnumeratorSimple
17fbe7b0 022f3490 System.Collections.ArrayList
17fbe7b4 0231860c System.String    Error loading MyConfig.txt
17fbe7c0 022f3014 MyProg.MyEngine
17fbe84c 0231b48c System.Threading._TimerCallback
17fbe9fc 0231b48c System.Threading._TimerCallback

0:000> ~290e !clrstack
OS Thread Id: 0x1af8 (290)
ESP       EIP     
2e77f39c 77d2013d [HelperMethodFrame_1OBJ: 2e77f39c] System.Threading.ReaderWriterLock.AcquireReaderLockInternal(Int32)
2e77f3f8 0c3630d4 MyProg.MyEngine.GetBuyValue()
2e77f424 076fd4ad MyProg.MyParentClass.Execute(System.Object)
2e77f474 71e19fcf System.Threading._ThreadPoolWaitCallback.WaitCallback_Context(System.Object)
2e77f47c 71e302ff System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
2e77f494 71e1a533 System.Threading._ThreadPoolWaitCallback.PerformWaitCallbackInternal(System.Threading._ThreadPoolWaitCallback)
2e77f4a8 71e1a3c9 System.Threading._ThreadPoolWaitCallback.PerformWaitCallback(System.Object)
2e77f638 74071b4c [GCFrame: 2e77f638] 

0:000> ~290e!dso
OS Thread Id: 0x1af8 (290)
ESP/REG  Object   Name
2e77f35c 022f3014 MyProg.MyEngine
2e77f360 02369b98 System.Threading.ContextCallback
2e77f378 02369b98 System.Threading.ContextCallback
2e77f3dc 023188f8 System.Threading.ReaderWriterLock
2e77f400 024862d8 MyProg.MyChildClass
2e77f410 02369b98 System.Threading.ContextCallback
2e77f430 024862d8 MyProg.MyChildClass
2e77f43c 024862d8 MyProg.MyChildClass
2e77f460 02369b98 System.Threading.ContextCallback
2e77f490 1156dd74 System.Threading._ThreadPoolWaitCallback

Vigesimal

sorry, but the formatting just went out...how do I post with proper formatting of command outputs? – Vigesimal

Suggestion: try to modify code so it provokes the error more frequently. You won't be able to do anything here unless you try to understand WHY it happens. – Disentangle

I'm guessing 'cause I do not see the code but...just to be sure, do you have any (A,B) (B,A) locking? – Lakshmi

Have you tried !dlk from SOSEX: stevestechspot.com it may help – Pumping

Actually he has a new command !mlocks which lists all locks, critical sections and their owners in managed and unmanaged code – Pumping

Ed, ran !mlocks. A basic question, but what does syncblock mean versus RWLock? SyncBlock means the lock() in C#? – Vigesimal

Answer 1

I think you should try the extension dll SOSEX written by this guy http://stevestechspot.com/, there is a !dlk command which tries to find deadlocks and he recently added some new commands which will be of interest for you:

!mlocks – Lists all managed locks and unmanaged CriticalSections, along with their owner thread ID. !mwaits – Lists all waiting threads and, if it can be determined, the lock objects they are waiting on.

Pumping

It does not always detect a deadlock. I also tried that and that did not find the deadlock for me. Another related command is !analyze -v -hang. This takes a bit longer to run, so dont windbg has frozen – Vigesimal

@Vigesimal try !locks but it will run for a very long time so make a brew :) – Pumping

Ed, the thing is, from synblk output in my original post, I can already see there is a writer lock on arraylist and there are over 450 reader threads waiting on it. When I look up outputs of other commands, the readers are not really trying to acquire the lock the writer is holding.. – Vigesimal

When I run clrstck on the thread holding the writer lock, it shows me these functions System.Threading.Monitor.Enter(System.Object) 17fbe720 00638427 MyProg.MyParentClass.ClockTimeElapsed(System.DateTime) – Vigesimal

!clrstck on the thread holding the writer lock shows this System.Threading.Monitor.Enter(System.Object) MyProg.MyParentClass.ClockTimeElapsed(System.DateTime) Here it is acquiring writer lock on arraylist but when I do clrstack on reader threads System.Threading.ReaderWriterLock.AcquireReaderLockInternal(Int32) 2e77f3f8 0c3630d4 MyProg.MyEngine.GetBuyValue() , the GetBuyValue() is trying to acquire reader lock on some other object. I want to know, who is holding the lock that all these readers are trying to acquire a reader lock on. – Vigesimal

Sorry it should've said !handle XXXX, !handle should list the ownder thread id. – Pumping