New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
janwilmans opened this Issue Jun 17, 2017 · 15 comments

Comments

Projects
None yet
2 participants
@janwilmans
Member

janwilmans commented Jun 17, 2017

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:

image

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

@janwilmans

This comment has been minimized.

Member

janwilmans commented Jun 17, 2017

The delay as observed in procmon:

image

@janwilmans

This comment has been minimized.

Member

janwilmans commented Jun 17, 2017

And another:
image

@janwilmans

This comment has been minimized.

Member

janwilmans commented Jun 18, 2017

Traveling back in time, mark and I found that d5d247f 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

This comment has been minimized.

Member

janwilmans commented Jun 18, 2017

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

@janwilmans

This comment has been minimized.

Member

janwilmans commented Jun 18, 2017

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

@janwilmans

This comment has been minimized.

Member

janwilmans commented Jun 18, 2017

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

@mriffey

This comment has been minimized.

mriffey commented Jun 20, 2017

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

This comment has been minimized.

Member

janwilmans commented Jun 20, 2017

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

This comment has been minimized.

@mriffey

This comment has been minimized.

mriffey commented Jun 20, 2017

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 added a commit that referenced this issue Jun 21, 2017

@janwilmans

This comment has been minimized.

Member

janwilmans commented Jun 25, 2017

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

This comment has been minimized.

Member

janwilmans commented Jun 25, 2017

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

This comment has been minimized.

Member

janwilmans commented Jun 28, 2017

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

@janwilmans janwilmans closed this Jun 28, 2017

@janwilmans

This comment has been minimized.

Member

janwilmans commented Jun 28, 2017

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

@janwilmans

This comment has been minimized.

Member

janwilmans commented Feb 20, 2018

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/

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment