Case of deadlock in FileSystemWatcher

Recently I got relatively simple deadlock case, but I found quite interesting things during investigation. Our application hangs when user tries to quit it. I got dump file for this case and started investigation.

Call stack for main thread looks like this:

...
clr!JITutil_MonContention+0x115
System_ni!System.ComponentModel.Component.Dispose(Boolean)$##60031F8+0x40
System_ni!System.IO.FileSystemWatcher.Dispose(Boolean)$##600266D+0xd7
System_ni!System.IO.FileSystemWatcher.Dispose(Boolean)$##600266D+0xa6
System_ni!System.ComponentModel.Component.Dispose()$##60031F7+0x1a
...

As you clearly see, application waiting in FileSystemWatcher’s  System.ComponentModel.Component.Dispose. If you go to https://sourceof.net and paste name of the method there to see source code, you will see that there is lock(this) and it looks like some other thread obtained lock before us. Obviously, I went over other 168 threads and found 2 similar call stacks. First thread was executing event from first FileSystemWatcher and attempted to dispose second FileSystemWatcher. Second thread has FileSystemWatcher that was executing event and was trying to dispose first FileSystemWatcher. As result we have classical deadlock.

So far nothing interesting and quite boring and long investigation. But during investigation I found interesting extension called sosex. You can download it here: http://www.stevestechspot.com. After download, execute following command:

.load X:\SomePath\sosex.dll

Obviously, you should use real path. Then execute best command in this extension:

!dlk

And then you will see something like this:

...
*DEADLOCK DETECTED*
CLR thread 0x47 holds the lock on SyncBlock 00000001d9c2b4f8 OBJ:00000001219c4a88[System.IO.FileSystemWatcher]
...and is waiting for the lock on SyncBlock 00000001d9c7e558 OBJ:00000001219c5278[System.IO.FileSystemWatcher]
CLR thread 0x86 holds the lock on SyncBlock 00000001d9c7e558 OBJ:00000001219c5278[System.IO.FileSystemWatcher]
...and is waiting for the lock on SyncBlock 00000001d9c2b4f8 OBJ:00000001219c4a88[System.IO.FileSystemWatcher]
CLR Thread 0x47 is waiting at System.ComponentModel.Component.Dispose(Boolean)(+0x7 IL,+0x40 Native)
CLR Thread 0x86 is waiting at System.ComponentModel.Component.Dispose(Boolean)(+0x7 IL,+0x40 Native)
...

And you immediately see where deadlock is. You can actually click on address after OBJ and it will display this object. All threads and objects that are part of deadlock are clearly visible. But keep in mind that 0x47 and 0x86 are id's of managed threads. Execute this command to see all managed threads:

!threads

You will get something like this:

...
98   71  710 00000001135a8030  a029220 Preemptive  0000000000000000:0000000000000000 00000001134b2fa0 1     MTA (Threadpool Completion Port) 
...
97  134 2698 00000001bc7810f0  a029220 Preemptive  0000000000000000:0000000000000000 00000001134b2fa0 1     MTA (Threadpool Completion Port) 
...

And then search for 71 (decimal for 0x47) and 134 (decimal for 0x86). Corresponding thread ids are: 710 and 2698. Then execute following command to switch current thread in WinDbg:

~~[710]s

And WinDbg will change current thread to thread id 710 and then you can use !clrstack command to display call stack or you can use !mk command from sosex that will display managed and unmanaged cal lstacks combined. I know that it is possible to use !DumpStack command from regular sos extension, but output is quite noisy. !mk command provides much clearer output and I like it more.

I hope it helps someone.