As Mark Goldberg reported, debugview++ sometimes has large startup-delays

janwilmans commented 7 years ago

What we know so far:

I do not see it on my windows 8.1 Pro laptop
I do not see it on my windows 10 Pro laptop
Mark sees it with varying delays, from 20-40 seconds. (Win 10 Pro 1703 (Creators Update) Build 15063.413)
Mark's wife's laptop with the same windows version, but otherwise a completely different configuration, also reproduces the problem.
A few other programmers also tested on windows 10, and do not see the problem

What it looks like:

After dubble-clicking the icon, the program starts, but hangs without GUI updates for a while. This is obs

janwilmans commented 7 years ago

The delay as observed in procmon:

janwilmans commented 7 years ago

And another:

janwilmans commented 7 years ago

Traveling back in time, mark and I found that d5d247fa346e610ba869c7d7e8d3554cdb2a89f6 back on vs2010 and boost 1.59 already had the problem. So we can rule out:

the migration to vs2017
the migration from boost 1.59 -> 1.64
the migration from boost::thread -> std::thread
the migration from boost_atomics to c++14 mutexes

so quite a bit ruled out.

janwilmans commented 7 years ago

After move binary searching time travelling back through the source, we found that 489e976e93e9c616dbfdfeff50bafe47c2df7975 of 11-nov-2015 does not have the problem, but a8f66365cd8c89b4ab220fb65bd1cd341554e140 of 1-jan-2016 does!

janwilmans commented 7 years ago

later on, we discovered the problem is introduced in this change cb954a6c03b19ca75f9d72fec67f76bfa24be9be

janwilmans commented 7 years ago

This 4e918b1824ee91cfda038a05f9addab69d1fb5bf 'solved' this issue, however, it is theoretically, either wrong or irrelevant, as far as I can tell.

mriffey commented 7 years ago

I also see it on the same version Mark G sees it (Win 10 Pro 1703 Creators Update Build 15063.413), but I do not see it on Win10Pro 1607. I am exclusively using the 64 bit version of DB++ 1.7.0.64.

janwilmans commented 7 years ago

No problem on: Windows 10 version 1607 14393.1358 (from winver.exe) or run 'wmic os get Version, Caption, OSArchitecture'

Naam van besturingssysteem Microsoft Windows 10 Home Versie 10.0.14393 Build 14393 Andere beschrijving van besturingssysteem Niet beschikbaar Leverancier van besturingssysteem Microsoft Corporation Systeemnaam DESKTOP-A5US9GI Systeemfabrikant HP Systeemmodel HP Spectre x360 Convertible Systeemtype Op x64-gebaseerde PC Systeem-SKU E9M48EA#ABH Processor Intel(R) Core(TM) i7-6560U CPU @ 2.20GHz, 2208 MHz, 2 core('s), 4 logische processor(s) BIOS-versie/datum American Megatrends Inc. F.45, 4/21/2017 SMBIOS-versie 2.8 Versie van ingesloten controller 33.78 BIOS-modus UEFI Fabrikant BaseBoard HP Model BaseBoard Niet beschikbaar Naam BaseBoard Basiskaart Platformfunctie Mobiel Status beveiligd opstarten Ingeschakeld PCR7-configuratie Uitbreiding van bevoegdheden vereist om te kunnen weergeven Map met Windows C:\WINDOWS Systeemmap C:\WINDOWS\system32 Opstartapparaat \Device\HarddiskVolume1 Landinstelling Verenigde Staten HAL (Hardware Abstraction Layer) Versie = "10.0.14393.206" Gebruikersnaam DESKTOP-A5US9GI\jan Tijdzone West-Europa (zomertijd) Geïnstalleerd fysiek geheugen (RAM) 8.00 GB Totaal fysiek geheugen 7.91 GB Beschikbaar fysiek geheugen 4.25 GB Totaal virtueel geheugen 13.8 GB Beschikbaar virtueel geheugen 7.81 GB Ruimte voor wisselbestand 5.87 GB Wisselbestand C:\pagefile.sys Hyper-V - Modusextensies VM-monitor Ja Hyper-V - Extensies voor adresomzetting op tweede niveau Ja Hyper-V - Virtualisatie ingeschakeld in firmware Nee Hyper-V - Bescherming tegen gegevensuitvoering Ja

so it look like it only occurs on windows 10 creators update 1703 and not before 1607 is 2016-July -- aka Aniversary Update 1703 is 2017-March -- aka Creators Update

janwilmans commented 7 years ago

depends_with_delay_on_1703.txt

depends_without_delay_on1607.txt

mriffey commented 7 years ago

I tried to build it on vs2017 community, but it wasnt happy about that (v141 here). If you have a version of the source that 2017 can build, im happy to run the debugger and see where it hangs. That assumes you dont reproduce it after moving to 1703.

I just tested 1.7.0.70 the 32 bit version on Win 2012 R2 server. No problem there. Also no problem on Win Server 2016 1607 and 1607 with all available updates (on AWS, at least)

janwilmans commented 7 years ago

I think I have found the root cause after I was able to create a full-dump during the ui hangup using process explorer, as suggested in this MSDN article

The messageloop internally calls OutputDebugStringA for some reason, causing it to lock up for the duration of the DBWIN_BUFFER_READY timeout (10 seconds), this explains why to always seems to hang the ui for multiples of 10 seconds (I has need 20, 30 and 40 seconds)

    ntdll.dll!_NtWaitForSingleObject@12()  Unknown
    KERNELBASE.dll!WaitForSingleObjectEx()  Unknown
    KERNELBASE.dll!OutputDebugStringA() Unknown
>   KERNELBASE.dll!OutputDebugStringW() Unknown
    oleaut32.dll!wil::details::LogFailure(void *,unsigned int,char const *,char const *,char const *,void *,enum wil::FailureType,long,unsigned short const *,bool,unsigned short *,unsigned int,char *,unsigned int,struct wil::FailureInfo *) Unknown
    oleaut32.dll!wil::details::ReportFailure(void *,unsigned int,char const *,char const *,char const *,void *,enum wil::FailureType,long,unsigned short const *,enum wil::details::ReportFailureOptions)   Unknown
    oleaut32.dll!wil::details::ReportFailure_Hr(void *,unsigned int,char const *,char const *,char const *,void *,enum wil::FailureType,long)   Unknown
    oleaut32.dll!wil::details::in1diag3::Return_Hr_NoOriginate(void *,unsigned int,char const *,long)   Unknown
    oleaut32.dll!GetTypeInfoOfIIDFwd(struct _GUID const &,struct ITypeInfo * *,int) Unknown
    oleaut32.dll!CProxyWrapper::Connect(struct IRpcChannelBuffer *) Unknown
    combase.dll!CStdMarshal::ConnectProxyToChannel(tagIPIDEntry * pEntry, OXIDEntry * pOXIDEntry, const _GUID & ipid) Line 3206 C++
    [Inline Frame] combase.dll!CStdMarshal::ConnectCliIPIDEntry(tagSTDOBJREF *) Line 3055   C++
    combase.dll!CStdMarshal::MakeCliIPIDEntry(const _GUID & riid, tagSTDOBJREF * pStd, OXIDEntry * pOXIDEntry, tagIPIDEntry * * ppEntry) Line 2812  C++
    combase.dll!CStdMarshal::UnmarshalIPID(const _GUID & riid, tagSTDOBJREF * pStd, OXIDEntry * pOXIDEntry, void * * ppv) Line 2340 C++
    combase.dll!CStdMarshal::UnmarshalObjRef(tagOBJREF & objref, void * * ppv) Line 2208    C++
    combase.dll!UnmarshalSwitch(void * pv) Line 1843    C++
    combase.dll!UnmarshalObjRef(tagOBJREF & objref, EffectiveUnmarshalingPolicy policy, void * * ppv, int fBypassActLock, CStdMarshal * * ppStdMarshal) Line 1985   C++
    combase.dll!_CoUnmarshalInterface(IStream * pStm, bool bForceStrongPolicy, const _GUID & riid, void * * ppv) Line 1730  C++
    combase.dll!CoUnmarshalInterface(IStream * pStm, const _GUID & riid, void * * ppv) Line 1773    C++
    combase.dll!ActivationPropertiesOut::OutSerializer::UnmarshalAtIndex(unsigned long index, bool bIsWinRTOutofproc) Line 3139 C++
    combase.dll!ActivationPropertiesOut::GetObjectInterfaces(unsigned long cIfs, unsigned long actvflags, tagMULTI_QI * pMultiQi) Line 2746 C++
    combase.dll!ICoCreateInstanceEx(const _GUID & OriginalClsid, IUnknown * punkOuter, unsigned long dwClsCtx, _COSERVERINFO * pServerInfo, unsigned long dwCount, unsigned long dwActvFlags, tagMULTI_QI * pResults, ActivationPropertiesIn * pActIn) Line 1971    C++
    combase.dll!CComActivator::DoCreateInstance(const _GUID & Clsid, IUnknown * punkOuter, unsigned long dwClsCtx, _COSERVERINFO * pServerInfo, unsigned long dwCount, tagMULTI_QI * pResults, ActivationPropertiesIn * pActIn) Line 384    C++
    [Inline Frame] combase.dll!CoCreateInstanceEx(const _GUID &) Line 176   C++
    combase.dll!CoCreateInstance(const _GUID & rclsid, IUnknown * pUnkOuter, unsigned long dwContext, const _GUID & riid, void * * ppv) Line 120    C++
    uiautomationcore.dll!BlockingCoreDispatcher::CreateAndRegisterBlockingCore(void)    Unknown
    uiautomationcore.dll!BlockingCoreDispatcher::FinalConstruct(void)   Unknown
    uiautomationcore.dll!ATL::CComCreator<class ATL::CComObject<class CUIAutomation8> >::CreateInstance(void *,struct _GUID const &,void * *)   Unknown
    uiautomationcore.dll!ATL::CComCreator2<class ATL::CComCreator<class ATL::CComObject<class CUIAutomation8> >,class ATL::CComFailCreator<-2147221232> >::CreateInstance(void *,struct _GUID const &,void * *) Unknown
    uiautomationcore.dll!ATL::CComClassFactory::CreateInstance(struct IUnknown *,struct _GUID const &,void * *) Unknown
    combase.dll!CServerContextActivator::CreateInstance(IUnknown * pUnkOuter, IActivationPropertiesIn * pInActProperties, IActivationPropertiesOut * * ppOutActProperties) Line 872 C++
    combase.dll!ActivationPropertiesIn::DelegateCreateInstance(IUnknown * pUnkOuter, IActivationPropertiesOut * * ppActPropsOut) Line 1931  C++
    combase.dll!CApartmentActivator::CreateInstance(IUnknown * pUnkOuter, IActivationPropertiesIn * pInActProperties, IActivationPropertiesOut * * ppOutActProperties) Line 2163    C++
    combase.dll!CProcessActivator::CCICallback(unsigned long dwContext, IUnknown * pUnkOuter, ActivationPropertiesIn * pActIn, IActivationPropertiesIn * pInActProperties, IActivationPropertiesOut * * ppOutActProperties) Line 1631   C++
    combase.dll!CProcessActivator::AttemptActivation(ActivationPropertiesIn * pActIn, IUnknown * pUnkOuter, IActivationPropertiesIn * pInActProperties, IActivationPropertiesOut * * ppOutActProperties, HRESULT(__stdcallCProcessActivator::*)(unsigned long, IUnknown *, ActivationPropertiesIn *, IActivationPropertiesIn *, IActivationPropertiesOut * *) pfnCtxActCallback, unsigned long dwContext) Line 1518 C++
    combase.dll!CProcessActivator::ActivateByContext(ActivationPropertiesIn * pActIn, IUnknown * pUnkOuter, IActivationPropertiesIn * pInActProperties, IActivationPropertiesOut * * ppOutActProperties, HRESULT(__stdcallCProcessActivator::*)(unsigned long, IUnknown *, ActivationPropertiesIn *, IActivationPropertiesIn *, IActivationPropertiesOut * *) pfnCtxActCallback) Line 1384  C++
    combase.dll!CProcessActivator::CreateInstance(IUnknown * pUnkOuter, IActivationPropertiesIn * pInActProperties, IActivationPropertiesOut * * ppOutActProperties) Line 1262  C++
    combase.dll!ActivationPropertiesIn::DelegateCreateInstance(IUnknown * pUnkOuter, IActivationPropertiesOut * * ppActPropsOut) Line 1931  C++
    combase.dll!CClientContextActivator::CreateInstance(IUnknown * pUnkOuter, IActivationPropertiesIn * pInActProperties, IActivationPropertiesOut * * ppOutActProperties) Line 561 C++
    combase.dll!ActivationPropertiesIn::DelegateCreateInstance(IUnknown * pUnkOuter, IActivationPropertiesOut * * ppActPropsOut) Line 1983  C++
    combase.dll!ICoCreateInstanceEx(const _GUID & OriginalClsid, IUnknown * punkOuter, unsigned long dwClsCtx, _COSERVERINFO * pServerInfo, unsigned long dwCount, unsigned long dwActvFlags, tagMULTI_QI * pResults, ActivationPropertiesIn * pActIn) Line 1915    C++
    combase.dll!CComActivator::DoCreateInstance(const _GUID & Clsid, IUnknown * punkOuter, unsigned long dwClsCtx, _COSERVERINFO * pServerInfo, unsigned long dwCount, tagMULTI_QI * pResults, ActivationPropertiesIn * pActIn) Line 384    C++
    [Inline Frame] combase.dll!CoCreateInstanceEx(const _GUID &) Line 176   C++
    combase.dll!CoCreateInstance(const _GUID & rclsid, IUnknown * pUnkOuter, unsigned long dwContext, const _GUID & riid, void * * ppv) Line 120    C++
    tiptsf.dll!CImmersiveFocusTracker::_HandleAutomationEvent(unsigned long,struct HWND__ *,long)   Unknown
    tiptsf.dll!CImmersiveFocusTracker::HandleAutomationEvent(unsigned long,struct HWND__ *,long)    Unknown
    tiptsf.dll!TabletMsgWndProc(int,unsigned int,long)  Unknown
    user32.dll!_DispatchHookW@16() Unknown
    user32.dll!_CallHookWithSEH@16()   Unknown
    user32.dll!___fnHkINLPMSG@4()  Unknown
    ntdll.dll!_KiUserCallbackDispatcher@12()   Unknown
    DebugView++.exe!WTL::CCommandBarCtrlImpl<WTL::CCommandBarCtrl,WTL::CCommandBarCtrlBase,ATL::CWinTraits<1442840576,0> >::MessageHookProc(int nCode, unsigned int wParam, long lParam) Line 2747  C++
    user32.dll!_DispatchHookW@16() Unknown
    user32.dll!_CallHookWithSEH@16()   Unknown
    user32.dll!___fnHkINLPMSG@4()  Unknown
    ntdll.dll!_KiUserCallbackDispatcher@12()   Unknown
    DebugView++.exe!WTL::CMessageLoop::Run() Line 1292  C++
    [Inline Frame] DebugView++.exe!fusion::debugviewpp::MessageLoop::Run() Line 61  C++
    DebugView++.exe!fusion::debugviewpp::Main(HINSTANCE__ * cmdShow, HINSTANCE__ *) Line 156    C++
    DebugView++.exe!wWinMain(HINSTANCE__ * hInstance, HINSTANCE__ * hPrevInstance, wchar_t * lpstrCmdLine, int nCmdShow) Line 165   C++
    [Inline Frame] DebugView++.exe!invoke_main() Line 118   C++
    DebugView++.exe!__scrt_common_main_seh() Line 283   C++
    kernel32.dll!75848744() Unknown
    [Frames below may be incorrect and/or missing, no symbols loaded for kernel32.dll]  
    ntdll.dll!__RtlUserThreadStart()    Unknown
    ntdll.dll!__RtlUserThreadStart@8() Unknown

janwilmans commented 7 years ago

In retrospect, we could have known this, because if you start a second instance of debugview++ the messages coming from the first instance can be observed:

9   1.580143    11576   DebugView++.exe mincore\com\oleaut32\dispatch\ups.cpp(2128)\OLEAUT32.dll!75685072: (caller: 7568FE4F) ReturnHr(1) tid(213c) 8002801D DLL-bestand is niet geregistreerd.
10  1.581557    11576   DebugView++.exe mincore\com\oleaut32\dispatch\ups.cpp(2128)\OLEAUT32.dll!75685072: (caller: 7568FE4F) ReturnHr(2) tid(213c) 8002801D DLL-bestand is niet geregistreerd.

btw, i'm testing on a dutch windows version, 'DLL-bestand is niet geregistreerd.' means 'DLL not registered'. Apparently, its trying to load some dll that is not present, but also not critical, because it seems to continue just fine afterwards.

janwilmans commented 7 years ago

In 0bd78c311f2222664f25a5a5aab691c4a73f5503 I have redesigned the incoming message interactions in a way that it nolonger matters if OutputDebugString is triggered internally.

janwilmans commented 7 years ago

Mark Goldberg and Mark Riffey both confirmed they are not experiencing the problem anymore.

janwilmans commented 6 years ago

At Mark Goldberg's request, I've written a small blog post on the root cause of this problem. http://nullptr.nl/2018/02/outputdebugstring-and-windows-10/

CobaltFusion / DebugViewPP

As Mark Goldberg reported, debugview++ sometimes has large startup-delays #277