{"id":43773,"date":"2014-10-24T07:00:00","date_gmt":"2014-10-24T07:00:00","guid":{"rendered":"https:\/\/blogs.msdn.microsoft.com\/oldnewthing\/2014\/10\/24\/debugging-a-hang-chasing-the-wait-chain-inside-a-process\/"},"modified":"2014-10-24T07:00:00","modified_gmt":"2014-10-24T07:00:00","slug":"debugging-a-hang-chasing-the-wait-chain-inside-a-process","status":"publish","type":"post","link":"https:\/\/devblogs.microsoft.com\/oldnewthing\/20141024-00\/?p=43773","title":{"rendered":"Debugging a hang: Chasing the wait chain inside a process"},"content":{"rendered":"

\nToday we’re going to debug a hang.\nHere are some of the (redacted) stacks of the process.\nI left some red herrings and other frustrations.\n<\/p>\n

\n0: kd> !process ffffe000045ef940 7\nPROCESS ffffe000045ef940\n    SessionId: 1  Cid: 0a50    Peb: 7ff6b661f000  ParentCid: 0a0c\n    DirBase: 12e5c6000  ObjectTable: ffffc0000288ae80  HandleCount: 1742.\n    Image: contoso.exe\n        THREAD ffffe000018d68c0  Cid 0a50.0a54  Teb: 00007ff6b661d000 Win32Thread: fffff90143635a90 WAIT: (WrUserRequest) UserMode Non-Alertable\n            ffffe000046192c0  SynchronizationEvent\n        nt!KiSwapContext+0x76\n        nt!KiSwapThread+0x14c\n        nt!KiCommitThreadWait+0x126\n        nt!KeWaitForSingleObject+0x1cc\n        nt!KeWaitForMultipleObjects+0x44e\n        0xfffff960`0038bed0\n        0x1\n        0xffffd000`24257b80\n        0xfffff901`43635a90\n        0xd\n        0xffffe000`00000001\n        0xfffff803`ffffff00\n        THREAD ffffe000045f88c0  Cid 0a50.0a8c  Teb: 00007ff6b64ea000 Win32Thread: 0000000000000000 WAIT: (UserRequest) UserMode Non-Alertable\n            ffffe000041c1830  SynchronizationEvent\n        nt!KiSwapContext+0x76\n        nt!KiSwapThread+0x14c\n        nt!KiCommitThreadWait+0x126\n        nt!KeWaitForSingleObject+0x1cc\n        nt!NtWaitForSingleObject+0xb1\n        nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ ffffd000`248ebc40)\n        ntdll!ZwWaitForSingleObject+0xa\n        ntdll!RtlpWaitOnCriticalSection+0xe1\n        ntdll!RtlEnterCriticalSection+0x94\n        ntdll!LdrpAcquireLoaderLock+0x2c\n        ntdll!LdrShutdownThread+0x64\n        ntdll!RtlExitUserThread+0x3e\n        KERNELBASE!FreeLibraryAndExitThread+0x4c\n        combase!CRpcThreadCache::RpcWorkerThreadEntry+0x62\n        KERNEL32!BaseThreadInitThunk+0x30\n        ntdll!RtlUserThreadStart+0x42\n        THREAD ffffe00003c46080  Cid 0a50.0a9c  Teb: 00007ff6b64e6000 Win32Thread: fffff90143713a90 WAIT: (UserRequest) UserMode Non-Alertable\n            ffffe000041c1830  SynchronizationEvent\n        nt!KiSwapContext+0x76\n        nt!KiSwapThread+0x14c\n        nt!KiCommitThreadWait+0x126\n        nt!KeWaitForSingleObject+0x1cc\n        nt!NtWaitForSingleObject+0xb1\n        nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ ffffd000`367ece40)\n        ntdll!ZwWaitForSingleObject+0xa\n        ntdll!RtlpWaitOnCriticalSection+0xe1\n        ntdll!RtlEnterCriticalSection+0x94\n        ntdll!LdrpAcquireLoaderLock+0x4c\n        ntdll!LdrpFindOrMapDll+0x75d\n        ntdll!LdrpLoadDll+0x394\n        ntdll!LdrLoadDll+0xc6\n        kernelbase!LoadLibraryExW+0x142\n        kernelbase!LoadLibraryExA+0x26\n        contoso!__delayLoadHelper2+0x2b\n        contoso!_tailMerge_Winmm_dll+0x3f\n        contoso!PolarityReverser::OnCompleted+0x28\n        contoso!PolarityReverser::Reverse+0xf4\n        contoso!ListItem::ReversePolarity+0x7e\n        contoso!View::OnContextMenu+0x8\n        contoso!View::WndProc+0x25e\n        user32!UserCallWinProcCheckWow+0x13a\n        user32!DispatchClientMessage+0xf8\n        user32!__fnEMPTY+0x2d\n        ntdll!KiUserCallbackDispatcherContinue\n        user32!ZwUserMessageCall+0xa\n        user32!RealDefWindowProcWorker+0x1e2\n        user32!RealDefWindowProcW+0x52\n        uxtheme!_ThemeDefWindowProc+0x33e\n        uxtheme!ThemeDefWindowProcW+0x11\n        user32!DefWindowProcW+0x1b6\n        comctl32!CListView::WndProc+0x25e\n        comctl32!CListView::s_WndProc+0x52\n        user32!UserCallWinProcCheckWow+0x13a\n        user32!SendMessageWorker+0xa72\n        user32!SendMessageW+0x10a\n        comctl32!CLVMouseManager::HandleMouse+0xd10\n        comctl32!CLVMouseManager::OnButtonDown+0x27\n        comctl32!CListView::WndProc+0x1a4186\n        comctl32!CListView::s_WndProc+0x52\n        user32!UserCallWinProcCheckWow+0x13a\n        user32!DispatchMessageWorker+0x1a7\n        THREAD ffffe0000462b8c0  Cid 0a50.0ac0  Teb: 00007ff6b64dc000 Win32Thread: 0000000000000000 WAIT: (UserRequest) UserMode Non-Alertable\n            ffffe0000462c980  NotificationEvent\n        nt!KiSwapContext+0x76\n        nt!KiSwapThread+0x14c\n        nt!KiCommitThreadWait+0x126\n        nt!KeWaitForSingleObject+0x1cc\n        nt!NtWaitForSingleObject+0xb1\n        nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ ffffd000`201e9c40)\n        ntdll!ZwWaitForSingleObject+0xa\n        KERNELBASE!WaitForSingleObjectEx+0xa5\n        contoso!CNetworkManager::ThreadProc+0x94\n        KERNEL32!BaseThreadInitThunk+0x30\n        ntdll!RtlUserThreadStart+0x42\n        THREAD ffffe000046ad340  Cid 0a50.0b38  Teb: 00007ff6b64b6000 Win32Thread: 0000000000000000 WAIT: (UserRequest) UserMode Non-Alertable\n            ffffe000049108c0  Thread\n        nt!KiSwapContext+0x76\n        nt!KiSwapThread+0x14c\n        nt!KiCommitThreadWait+0x126\n        nt!KeWaitForSingleObject+0x1cc\n        nt!NtWaitForSingleObject+0xb1\n        nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ ffffd000`2563bc40)\n        ntdll!ZwWaitForSingleObject+0xa\n        KERNELBASE!WaitForSingleObjectEx+0xa5\n        litware!CDiscovery::Uninitialize+0x8c\n        litware!CApiInstance::~CApiInstance+0x48\n        litware!CApiInstance::`scalar deleting destructor'+0x14\n        litware!std::tr1::_Ref_count_obj<CApiInstance>::_Destroy+0x31\n        litware!std::tr1::_Ref_count_base::_Decref+0x1b\n        litware!std::tr1::_Ptr_base<CApiInstance>::_Decref+0x20\n        litware!std::tr1::shared_ptr<CApiInstance>::{dtor}+0x20\n        litware!std::tr1::shared_ptr<CApiInstance>::reset+0x3c\n        litware!CSingleton<CApiInstance>::ReleaseRef+0x97\n        litware!LitWareUninitialize+0xed\n        fabrikam!CDoodadHelper::~CDoodadHelper+0x67\n        fabrikam!_CRT_INIT+0xda\n        fabrikam!__DllMainCRTStartup+0x1e5\n        ntdll!LdrpCallInitRoutine+0x57\n        ntdll!LdrpProcessDetachNode+0xfe\n        ntdll!LdrpUnloadNode+0x77\n        ntdll!LdrpDecrementNodeLoadCount+0xd0\n        ntdll!LdrUnloadDll+0x34\n        KERNELBASE!FreeLibrary+0x22\n        combase!CClassCache::CDllPathEntry::CFinishObject::Finish+0x28\n        combase!CClassCache::CFinishComposite::Finish+0x80\n        combase!CClassCache::FreeUnused+0xda\n        combase!CoFreeUnusedLibrariesEx+0x2c\n        combase!CDllHost::MTAWorkerLoop+0x7d\n        combase!CDllHost::WorkerThread+0x122\n        combase!CRpcThread::WorkerLoop+0x4e\n        combase!CRpcThreadCache::RpcWorkerThreadEntry+0x46\n        KERNEL32!BaseThreadInitThunk+0x30\n        ntdll!RtlUserThreadStart+0x42\n        THREAD ffffe000046db8c0  Cid 0a50.0b50  Teb: 00007ff6b64aa000 Win32Thread: fffff9014370da90 WAIT: (UserRequest) UserMode Non-Alertable\n            ffffe000046dcae0  NotificationEvent\n            ffffe000046dd3c0  SynchronizationEvent\n        nt!KiSwapContext+0x76\n        nt!KiSwapThread+0x14c\n        nt!KiCommitThreadWait+0x126\n        nt!KeWaitForMultipleObjects+0x22b\n        nt!ObWaitForMultipleObjects+0x1f8\n        nt!NtWaitForMultipleObjects+0xde\n        nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ ffffd000`21801c40)\n        ntdll!ZwWaitForMultipleObjects+0xa\n        KERNELBASE!WaitForMultipleObjectsEx+0xe1\n        USER32!MsgWaitForMultipleObjectsEx+0x14e\n        contoso!EventManagerImpl::MessageLoop+0x32\n        contoso!EventManagerImpl::BackgroundProcessing+0x134\n        ntdll!TppWorkpExecuteCallback+0x2eb\n        ntdll!TppWorkerThread+0xa12\n        KERNEL32!BaseThreadInitThunk+0x30\n        ntdll!RtlUserThreadStart+0x42\n        THREAD ffffe000049108c0  Cid 0a50.06cc  Teb: 00007ff6b6470000 Win32Thread: 0000000000000000 WAIT: (UserRequest) UserMode Non-Alertable\n            ffffe000041c1830  SynchronizationEvent\n        nt!KiSwapContext+0x76\n        nt!KiSwapThread+0x14c\n        nt!KiCommitThreadWait+0x126\n        nt!KeWaitForSingleObject+0x1cc\n        nt!NtWaitForSingleObject+0xb1\n        nt!KiSystemServiceCopyEnd+0x13\n        ntdll!ZwWaitForSingleObject+0xa\n        ntdll!RtlpWaitOnCriticalSection+0xe1\n        ntdll!RtlEnterCriticalSectionContended+0x94\n        ntdll!LdrpAcquireLoaderLock+0x2c\n        ntdll!LdrShutdownThread+0x64\n        ntdll!RtlExitUserThread+0x3e\n        KERNEL32!BaseThreadInitThunk+0x38\n        ntdll!RtlUserThreadStart+0x42\n<\/pre>\n
\nSince debugging is an exercise in optimism,\nlet’s ignore the stacks that didn’t come out properly.\nIf we can’t make any headway, we can try to fix them,\nbut let’s be hopeful that the stacks that are good\nwill provide enough information.\n<\/p>\n
\nGenerally speaking, the deeper the stack,\nthe more interesting it is,\nbecause uninteresting threads tend to be hanging\nout in their message loop or event loop,\nwhereas interesting threads are busy doing something\nand have a complex stack trace to show for it.\n<\/p>\n
\nIndeed, one of the deep stacks belongs to thread\n0a9c<\/code>,\nand it also has a very telling section:\n<\/p>\n
\n        ntdll!RtlpWaitOnCriticalSection+0xe1\n        ntdll!RtlEnterCriticalSection+0x94\n        ntdll!LdrpAcquireLoaderLock+0x4c\n        ntdll!LdrpFindOrMapDll+0x75d\n        ntdll!LdrpLoadDll+0x394\n        ntdll!LdrLoadDll+0xc6\n        kernelbase!LoadLibraryExW+0x142\n        kernelbase!LoadLibraryExA+0x26\n        contoso!__delayLoadHelper2+0x2b\n        contoso!_tailMerge_Winmm_dll+0x3f\n<\/pre>\n
\nThe polarity reverser’s completion handler is trying to\nload winmm<\/code> via delay-load.\nThat load request is waiting on a critical section,\nand it should be clear both from the scenario and the function names\nthat the critical section it is trying to claim is the loader lock.\nIn real life, I just proceeded with that conclusion, but\nbut just for demonstration purposes, here’s how we can double-check:\n<\/p>\n
\n0: kd> .thread ffffe00003c46080\n0: kd> kn\n  *** Stack trace for last set context - .thread\/.cxr resets it\n # Call Site\n00 nt!KiSwapContext+0x76\n01 nt!KiSwapThread+0x14c\n02 nt!KiCommitThreadWait+0x126\n03 nt!KeWaitForSingleObject+0x1cc\n04 nt!NtWaitForSingleObject+0xb1\n05 nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ ffffd000`367ece40)\n06 ntdll!ZwWaitForSingleObject+0xa\n07 ntdll!RtlpWaitOnCriticalSection+0xe1\n08 ntdll!RtlEnterCriticalSection+0x94\n09 ntdll!LdrpAcquireLoaderLock+0x4c\n0a ntdll!LdrpFindOrMapDll+0x75d\n0b ntdll!LdrpLoadDll+0x394\n0c ntdll!LdrLoadDll+0xc6\n0d kernelbase!LoadLibraryExW+0x142\n0e kernelbase!LoadLibraryExA+0x26\n0f contoso!__delayLoadHelper2+0x2b\n10 contoso!_tailMerge_Winmm_dll+0x3f\n<\/pre>\n
\nWe need to grab the critical section passed to\nRtl­Enter­Critical­Section<\/code>,\nbut since this is an x64 machine, the parameter was passed\nin registers, not on the stack, so we need to figure out where\nthe rcx<\/code> register got stashed.\n<\/p>\n
\nI’m going to assume that the same critical section is\nthe first (only?) parameter to\nRtlp­Wait­On­CriticalSection<\/code>.\nI don’t know this for a fact, but it seems like a reasonable guess.\nThe guess might be wrong; we’ll see.\n<\/p>\n
\nWe disassemble the function look to see where it stashes rcx<\/code>.\n<\/p>\n
\n0: kd> u ntdll!RtlpWaitOnCriticalSection\n    mov     qword ptr [rsp+18h],rbx\n    push    rbp\n    push    rsi\n    push    rdi\n    push    r12\n    push    r13\n    push    r14\n    push    r15\n    mov     rax,qword ptr [ntdll!__security_cookie (000007ff`3099d020)]\n    xor     rax,rsp\n    mov     qword ptr [rsp+80h],rax\n    mov   r14,qword ptr gs:[30h]\n    xor     r12d,r12d\n    lea     rax,[ntdll!LdrpLoaderLock (00007fff`d4f51cb8)]\n    mov     r15d,r12d\n    cmp     rcx,rax\n    mov     ebp,edx\n    sete    r15b\n    mov     rbx,rcx<\/font> \/\/ ⇐ Bingo\n<\/pre>\n
\nAwesome, we can suck rbx<\/code> out of the trap frame.\n<\/p>\n
\n0: kd> .trap ffffd000`367ece40\nrax=0000000000000000 rbx=00007fffd4f51cb8<\/font> rcx=000007f8136f2c2a\nrdx=0000000000000000 rsi=00000000000001e8 rdi=0000000000000000\nrip=000007f8136f2c2a rsp=000000000cf7f798 rbp=0000000000000000\n r8=000000000cf7f798  r9=0000000000000000 r10=0000000000000000\nr11=0000000000000344 r12=0000000000000000 r13=0000000000000000\nr14=000007f696870000 r15=000000007ffe0382\niopl=0         nv up ei pl zr na po nc\ncs=0033  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246\nntdll!ZwWaitForSingleObject+0xa:\n000007f8`136f2c2a c3              ret\n<\/pre>\n
\nOkay, let’s see if that value in rbx<\/code> pans out.\n<\/p>\n
\n0: kd> !cs 0x00007fff`d4f51cb8\n-----------------------------------------\nCritical section   = 0x00007fffd4f51cb8 (ntdll!LdrpLoaderLock+0x0)\nDebugInfo          = 0x00007fffd4f55228\nLOCKED\nLockCount          = 0x8\nWaiterWoken        = No\nOwningThread       = 0x0000000000000b38\nRecursionCount     = 0x1\nLockSemaphore      = 0x1A8\nSpinCount          = 0x0000000004000000\n<\/pre>\n
\nHooray, we confirmed that this is indeed the loader lock.\nI would have been surprised if it had been anything else!\n(If you had been paying attention, you would have noticed\nthe lea rax,[ntdll!LdrpLoaderLock (00007fff`d4f51cb8)]<\/code>\nin the disassembly which already confirms the value.)\n<\/p>\n
\nWe also see that the owning thread is 0xb38.\nHere’s its stack again:<\/p>\n
\n        nt!KiSwapContext+0x76\n        nt!KiSwapThread+0x14c\n        nt!KiCommitThreadWait+0x126\n        nt!KeWaitForSingleObject+0x1cc\n        nt!NtWaitForSingleObject+0xb1\n        nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ ffffd000`2563bc40)\n        ntdll!ZwWaitForSingleObject+0xa\n        KERNELBASE!WaitForSingleObjectEx+0xa5\n        litware!CDiscovery::Uninitialize+0x8c\n        litware!CApiInstance::~CApiInstance+0x48\n        litware!CApiInstance::`scalar deleting destructor'+0x14\n        litware!std::tr1::_Ref_count_obj<CApiInstance>::_Destroy+0x31\n        litware!std::tr1::_Ref_count_base::_Decref+0x1b\n        litware!std::tr1::_Ptr_base<CApiInstance>::_Decref+0x20\n        litware!std::tr1::shared_ptr<CApiInstance>::{dtor}+0x20\n        litware!std::tr1::shared_ptr<CApiInstance>::reset+0x3c\n        litware!CSingleton<CApiInstance>::ReleaseRef+0x97\n        litware!LitWareUninitialize+0xed\n        fabrikam!CDoodadHelper::~CDoodadHelper+0x67\n        fabrikam!_CRT_INIT+0xda\n        fabrikam!__DllMainCRTStartup+0x1e5\n        ntdll!LdrpCallInitRoutine+0x57\n        ntdll!LdrpProcessDetachNode+0xfe\n        ntdll!LdrpUnloadNode+0x77\n        ntdll!LdrpDecrementNodeLoadCount+0xd0\n        ntdll!LdrUnloadDll+0x34\n        KERNELBASE!FreeLibrary+0x22\n        combase!CClassCache::CDllPathEntry::CFinishObject::Finish+0x28\n        combase!CClassCache::CFinishComposite::Finish+0x80\n        combase!CClassCache::FreeUnused+0xda\n        combase!CoFreeUnusedLibrariesEx+0x2c\n        combase!CDllHost::MTAWorkerLoop+0x7d\n        combase!CDllHost::WorkerThread+0x122\n        combase!CRpcThread::WorkerLoop+0x4e\n        combase!CRpcThreadCache::RpcWorkerThreadEntry+0x46\n        KERNEL32!BaseThreadInitThunk+0x30\n        ntdll!RtlUserThreadStart+0x42\n<\/pre>\n
\nReading from the bottom up, we see that this thread is doing\nsome work on behalf of COM;\nspecifically, it is freeing unused libraries.\nThe fabrikam<\/code> library presumably responded\nS_OK<\/code> to\nDll­Can­Unload­Now<\/code>,\nso COM says,\n“Okay, then out you go.”\n<\/p>\n
\n\nAs part of\nDLL_PROCESS_DETACH<\/code> processing,\nthe C++ runtime library runs global destructors<\/a>.\nThe\nCDoodadHelper<\/code> destructor calls into\nthe Lit­Ware­Uninitialize<\/code> function in\nlitware.dll<\/code>.\nThat function decrements a reference count, and it appears\nthat the reference count went to zero because it’s destructing\nthe CApi­Instance<\/code> object.\nThe destructor for that function calls\nCDiscovery::Uninitialize<\/code>,\nand that function waits on a kernel object.\n<\/p>\n
\nThe debugger was kind enough to tell us what the object is:<\/p>\n
\n        THREAD ffffe000046ad340  Cid 0a50.0b38  Teb: 00007ff6b64b6000 Win32Thread: 0000000000000000 WAIT: (UserRequest) UserMode Non-Alertable\n            ffffe000049108c0  Thread\n<\/pre>\n
\nIt’s a thread.\n<\/p>\n
<!–<\/p>\n
\nBut in case we didn’t know that,\nhere’s how we could have figured it out anyway:\nLook at the handle that was passed to\nWait­For­Single­Object<\/code>:\n<\/p>\n
\n0: kd> kn\n  *** Stack trace for last set context - .thread\/.cxr resets it\n # Call Site\n00 nt!KiSwapContext+0x76\n01 nt!KiSwapThread+0x14c\n02 nt!KiCommitThreadWait+0x126\n03 nt!KeWaitForSingleObject+0x1cc\n04 nt!NtWaitForSingleObject+0xb1\n05 nt!KiSystemServiceCopyEnd+0x13 (TrapFrame @ ffffd000`2563bc40)\n06 ntdll!ZwWaitForSingleObject+0xa\n07 KERNELBASE!WaitForSingleObjectEx+0xa5\n08 litware!CDiscovery::Uninitialize+0x8c\n0: kd> .frame 7\n07 KERNELBASE!WaitForSingleObjectEx+0xa5\n0: kd> dv\n        hHandle = 0x00000000`000016e8\n dwMilliseconds = 0xffffffff\n     bAlertable = 0n0\n...\n<\/pre>\n
\nThe code is waiting infinitely (0xffffffff<\/code>)\nfor handle 0x16e8<\/code>.\nLet’s see what that handle refers to.\n<\/p>\n
\n0: kd> !handle 16e8 f\nPROCESS ffffe000045ef940\n    SessionId: 1  Cid: 0a50    Peb: 7ff6b661f000  ParentCid: 0a0c\n    DirBase: 12e5c6000  ObjectTable: ffffc0000288ae80  HandleCount: 1742.\n    Image: contoso.exe\nHandle table at ffffc0000288ae80 with 1742 entries in use\n16e8: Object: ffffe000049108c0  GrantedAccess: 001fffff (Protected) Entry: ffffc00002b8aba0\nObject: ffffe000049108c0  Type: (ffffe000001fff20) Thread\n    ObjectHeader: ffffe00004910890 (new version)\n        HandleCount: 2  PointerCount: 32770\n<\/pre>\n
\nThat value ffffe000049108c0<\/code>\nmatches the value reported by the\nthread dump at the start.\n<\/p>\n
–><\/p>\n
\nGoing back to the thread dump at the start, we also can see what thread\nffffe000049108c0<\/code> is doing.\nHere it is again:\n<\/p>\n
\n        nt!KiSwapContext+0x76\n        nt!KiSwapThread+0x14c\n        nt!KiCommitThreadWait+0x126\n        nt!KeWaitForSingleObject+0x1cc\n        nt!NtWaitForSingleObject+0xb1\n        nt!KiSystemServiceCopyEnd+0x13\n        ntdll!ZwWaitForSingleObject+0xa\n        ntdll!RtlpWaitOnCriticalSection+0xe1\n        ntdll!RtlEnterCriticalSectionContended+0x94\n        ntdll!LdrpAcquireLoaderLock+0x2c\n        ntdll!LdrShutdownThread+0x64\n        ntdll!RtlExitUserThread+0x3e\n        KERNEL32!BaseThreadInitThunk+0x38\n        ntdll!RtlUserThreadStart+0x42\n<\/pre>\n
\nThat thread is trying to acquire the loader lock so it can\nsend DLL_THREAD_DETACH<\/code> notifications.\nBut the loader lock is held by the\nFree­Library<\/code>.\nResult: Deadlock, as the two threads are waiting for each other.\n(You can also see that thread 0xa8c<\/code> is stuck\nin the same place because it too is trying to exit.)\n<\/p>\n
\nThe underlying problem is that the\nFabrikam DLL is waiting on a thread (indirectly via LitWare)\nwhile inside its own Dll­Main<\/code>.\n<\/p>\n
\nThe Fabrikam code could avoid this problem by calling\nLit­Ware­Uninitialize<\/code>\nwhen its last object is destroyed\nrather than when the DLL is unloaded.\n(Of course, it also has to remember to call\nLit­Ware­Initialize<\/code> when its first\nobject is created.)<\/p>\n","protected":false},"excerpt":{"rendered":"
Today we’re going to debug a hang. Here are some of the (redacted) stacks of the process. I left some red herrings and other frustrations. 0: kd> !process ffffe000045ef940 7 PROCESS ffffe000045ef940 SessionId: 1 Cid: 0a50 Peb: 7ff6b661f000 ParentCid: 0a0c DirBase: 12e5c6000 ObjectTable: ffffc0000288ae80 HandleCount: 1742. Image: contoso.exe THREAD ffffe000018d68c0 Cid 0a50.0a54 Teb: 00007ff6b661d000 Win32Thread: […]<\/p>\n","protected":false},"author":1069,"featured_media":111744,"comment_status":"open","ping_status":"closed","sticky":false,"template":"","format":"standard","meta":{"_acf_changed":false,"footnotes":""},"categories":[1],"tags":[25],"class_list":["post-43773","post","type-post","status-publish","format-standard","has-post-thumbnail","hentry","category-oldnewthing","tag-code"],"acf":[],"blog_post_summary":"
Today we’re going to debug a hang. Here are some of the (redacted) stacks of the process. I left some red herrings and other frustrations. 0: kd> !process ffffe000045ef940 7 PROCESS ffffe000045ef940 SessionId: 1 Cid: 0a50 Peb: 7ff6b661f000 ParentCid: 0a0c DirBase: 12e5c6000 ObjectTable: ffffc0000288ae80 HandleCount: 1742. Image: contoso.exe THREAD ffffe000018d68c0 Cid 0a50.0a54 Teb: 00007ff6b661d000 Win32Thread: […]<\/p>\n","_links":{"self":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/43773","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/users\/1069"}],"replies":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/comments?post=43773"}],"version-history":[{"count":0,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/posts\/43773\/revisions"}],"wp:featuredmedia":[{"embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/media\/111744"}],"wp:attachment":[{"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/media?parent=43773"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/categories?post=43773"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/devblogs.microsoft.com\/oldnewthing\/wp-json\/wp\/v2\/tags?post=43773"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}