1412977 - 800ms stall within DisplayConfigGetDeviceInfo

Status: NEW

(Core :: Graphics: Color Management, enhancement, P3)

Description

[Chris H-C :chutten]

A user provided this profile showing an 800ms all-app stall in a content process asking windows for DisplayConfigGetDeviceInfo on content process init: https://perf-html.io/public/bf5aa68502d3f601fb6a63dd711b15afc6dfa14a/calltree/?hiddenThreads=&invertCallstack&thread=2&threadOrder=0-2-3-4-5-6-7-1-8&v=2

Near as I can tell this is colour management code asking for the display's colour profile.

Comment 1

[Girish Sharma [:Optimizer]]

I am that "A user". Please feel free to ask any details. Few important details:

As far as I can tell, this started happening randomly after Windows fall creators update.

I have latest drivers for both my nvidia gtx 1060 and Intel hd 630 cards. But my (latest) nightly always run using intel graphics card.

Comment 2

[Mike Conley (:mconley) (:⚙️)]

Yeah, it looks like we're waiting on the OS for something here. Hey dmajor, anything jump out at you?

Comment 3

[Mike Conley (:mconley) (:⚙️)]

The hang in the parent process is what catches my eye the most:

NtUserGetProp
nsWindow::WindowProcInternal(HWND__ *,unsigned int,unsigned __int64,__int64)
CallWindowProcCrashProtected
nsWindow::WindowProc(HWND__ *,unsigned int,unsigned __int64,__int64)
UserCallWinProcCheckWow(_ACTIVATION_CONTEXT *,__int64 (*)(tagWND *,unsigned int,unsigned __int64,__int64),HWND__ *,_WM_VALUE,unsigned __int64,__int64,void *,int)
DispatchClientMessage
_fnDWORD
KiUserCallbackDispatcherContinue
NtUserPeekMessage
PeekMessageW
CThreadInputMgr::PeekMessageW(tagMSG *,HWND__ *,unsigned int,unsigned int,unsigned int,int *)
mozilla::widget::WinUtils::PeekMessageW(tagMSG *,HWND__ *,unsigned int,unsigned int,unsigned int)
nsAppShell::ProcessNextNativeEvent(bool)
nsBaseAppShell::DoProcessNextNativeEvent(bool)
nsBaseAppShell::OnProcessNextEvent(nsIThreadInternal *,bool)
nsThread::ProcessNextEvent(bool,bool *)
NS_ProcessNextEvent(nsIThread *,bool)
mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate *)
MessageLoop::RunHandler()
MessageLoop::Run()
nsBaseAppShell::Run()
nsAppShell::Run()
nsAppStartup::Run()
XREMain::XRE_mainRun()
XREMain::XRE_main(int,char * * const,mozilla::BootstrapConfig const &)
XREMain::XRE_main
mozilla::BootstrapImpl::XRE_main(int,char * * const,mozilla::BootstrapConfig const &)
NS_internal_main(int,char * *,char * *)
wmain
__scrt_common_main_seh
BaseThreadInitThunk
RtlUserThreadStart
(root)

I think the OS is just not giving us some value that we're waiting on.

Comment 4

[Milan Sreckovic [:milan] (needinfo for best results)]

Mike, should we raise this on the microsoft mailing list?

Comment 5

[Mike Conley (:mconley) (:⚙️)]

(In reply to Milan Sreckovic [:milan] from comment #4)
> Mike, should we raise this on the microsoft mailing list?

I'm not sure - I'm a bit out of my depth here. Let's wait to see what dmajor (or anyone else who knows the Windows OS internals more than I do) weighs in with.

Comment 6

[(Away)]

It's not present in the stack but I believe this is the inlined function:

nsWindow*
WinUtils::GetNSWindowPtr(HWND aWnd)
{
  return static_cast<nsWindow*>(::GetPropW(aWnd, GetNSWindowPropName()));
}

I don't have any experience with GetPropW or related APIs to know whether there are any perf gotchas. Jim, do you?

Comment 7

[Jim Mathies [:jimm]]

We use GetProp a lot since it allows you to attach arbitrary data to a window resource. Generally I've never experienced overhead associated with the call.

Looks like the content process is querying display settings, I'd bet that action is placing a lock on something that's holding up the GetProp call in the other process.

Also, looks like there's fileio[1] in here that probably fails due to the sandbox. I'll poke at that myself.

[1] http://searchfox.org/mozilla-central/source/gfx/qcms/iccread.c#1292

Comment 8

[Jim Mathies [:jimm]]

Note when we get all this GDI code out of content this will go away. But that work is one to two years out.

Comment 9

[Girish Sharma [:Optimizer]]

Just for some additional info, this has been happening only since a windows update to Fall creator update (build 1709). I have also tried doing a fresh install of 1709. Although, I might not be able to go back to 1706 (creators update) to validate whether this happens for me before the update as well.

In general, wrt build 1709, there have been quite a few complaints about driver issues and color profile settings getting messed up (while trying to see if others were also facing similar, stumbled upon a few blogs/reddits).

Comment 10

[Kevin Folz]

I believe I am experiencing the same issue, mouse "hangs" for ~1s as per https://mozilla.logbot.info/perf/20171030 but without the use of Firefox.
Using GPUView you can observe the OS stops Vsync flips for ~1s https://graphics.stanford.edu/~mdfisher/GPUView.html
https://imgur.com/a/5pSfe is a trace I generated.
Its related to the second GPU coming out of deep sleep. In your case, Intel + Nvidia in hybrid graphics.
 
My System setup: AMD APU w/ onboard graphics + AMD dedicated graphics, Windows 10 RS3 (16299.125)
 
Steps to repro:
Setup Microsoft hybrid graphics system with latest drivers
Connect WinDBG kernel debugging
Add the following breakpoint (need private symbols)
bm dxgkrnl!xxxREDACTEDxxxDeviceInfo ".frame; gc"
Wait for ~5s for the second GPU to go to sleep
Ask for GPU info in your program of choice "trigger"
Windows attempts to query DeviceInfo for both GPUs
Observe 300+ calls to DeviceInfo, until finally the second GPU comes out of sleep.
For a single GPU system I only observe about 50 calls from my trigger.
 
Looks like Windows continuously tries to get DeviceInfo until successful, which causes the display to hang.
 
Does that correlate to what your seeing? Can you verify with GPUView / UIforETW that the display stops flipping in your case?

Comment 11

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage/Projects/Bug_Handling/Bug_Husbandry#Move_fix-optionals