1648337 - Intermittent parent process hang when dismissing WebExtension popup

Status: RESOLVED WORKSFORME

(Core :: Graphics: WebRender, defect)

Description

[James Teh [:Jamie]]

Very intermittent. I'm mostly filing this so we don't lose it, but I really don't know how we're going to debug this.

STR:

1. Install the Fast Tab Switcher add-on.
2. Press control+space.
3. Type text to search for an open tab.
4. press enter.
   • Expected: Tab switch.
   • Actual: parent process hangs forever.

I use a screen reader and originally thought this was a11y related, but I don't see any a11y calls in the stack at all. The parent process starts chewing ~10% CPU. In a debugger, the parent process stack shows it waiting on mozilla::layers::PCompositorBridgeChild::SendFlushRendering, called (indirectly; some calls are missing probably due to inlining) by nsViewManager::Refresh. The CPU usage makes me think this isn't blocked on a single call here; feels more like an infinite loop. The GPU progress seems to just be waiting for a window message/event.

In the past, we've had some deadlocks with a11y because it does some sync IPC (Windows COM, not IPDL), but I can't see any blocked a11y stuff in the content processes, nor should there be any a11y happening in the GPU process (which parent is presumably querying via IPDL) at all.

I do have WebRender enabled, as well as DComp.

Hiro noted:

The word, WebExtension popup make me think that the WebExtension code switches nsIWidget (or some such), and it's quite troublesome. (Bug 1635769)
...
And maybe, the nsIWidget just before calling the FlushRendering in question might not be the right one. https://searchfox.org/mozilla-central/rev/46e3b1ce2cc120a188f6940b5c6eab6b24530e4f/view/nsViewManage

nsViewManager::Refresh gets called due to WM_PAINT. Conversation with tnikkel suggests the widget is probably resizing, hence the sync SendFlushRendering.

tnikkel also noted:

if it's some sort of infinite loop then this field might be getting stuck in the resizing state https://searchfox.org/mozilla-central/source/widget/windows/nsWindow.h#688

Unfortunately, I can't see that variable in the debugger (memory unavailable).

Stack dump from parent process:

0:102> ~0 kp
 # Child-SP          RetAddr           Call Site
00 00000083`1a7fd658 00007fff`e21d4f71 ntdll!NtWaitForAlertByThreadId+0x14
01 00000083`1a7fd660 00007fff`dfd3ab69 ntdll!RtlSleepConditionVariableSRW+0x131
02 00000083`1a7fd6e0 00007fff`cbc1f442 KERNELBASE!SleepConditionVariableSRW+0x29
*** WARNING: Unable to verify checksum for xul.dll
03 00000083`1a7fd720 00007fff`70057d9c mozglue!mozilla::detail::ConditionVariableImpl::wait_for(class mozilla::detail::MutexImpl * lock = <Value unavailable error>, class mozilla::BaseTimeDuration<mozilla::TimeDurationValueCalculator> * rel_time = <Value unavailable error>)+0x92 [/builds/worker/checkouts/gecko/mozglue/misc/ConditionVariable_windows.cpp @ 84] 
04 (Inline Function) --------`-------- xul!mozilla::OffTheBooksCondVar::Wait+0x1e [/builds/worker/workspace/obj-build/dist/include/mozilla/CondVar.h @ 64] 
05 (Inline Function) --------`-------- xul!mozilla::Monitor::Wait+0x1e [/builds/worker/workspace/obj-build/dist/include/mozilla/Monitor.h @ 36] 
06 00000083`1a7fd750 00007fff`70be181c xul!mozilla::ipc::MessageChannel::WaitForSyncNotify(bool aHandleWindowsMessages = true)+0x9c [/builds/worker/checkouts/gecko/ipc/glue/WindowsMessageLoop.cpp @ 948] 
07 00000083`1a7fd940 00007fff`700553f5 xul!mozilla::ipc::MessageChannel::Send(class mozilla::UniquePtr<IPC::Message,mozilla::DefaultDelete<IPC::Message> > aMsg = class mozilla::UniquePtr<IPC::Message,mozilla::DefaultDelete<IPC::Message> >, class IPC::Message * aReply = 0x00000083`1a7fdb68)+0x47c [/builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp @ 1539] 
08 00000083`1a7fdb00 00007fff`70c50195 xul!mozilla::ipc::IProtocol::ChannelSend(class IPC::Message * aMsg = <Value unavailable error>, class IPC::Message * aReply = <Value unavailable error>)+0x35 [/builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp @ 477] 
09 00000083`1a7fdb40 00007fff`729c6b7d xul!mozilla::layers::PCompositorBridgeChild::SendFlushRendering(void)+0xc5 [/builds/worker/workspace/obj-build/ipc/ipdl/PCompositorBridgeChild.cpp @ 1235] 
0a 00000083`1a7fdc20 00007fff`729c6447 xul!nsViewManager::Refresh(class nsView * aView = 0x00000205`c3f1ea00, class mozilla::gfx::IntRegionTyped<mozilla::LayoutDevicePixel> * aRegion = <Value unavailable error>)+0x11d [/builds/worker/checkouts/gecko/view/nsViewManager.cpp @ 344] 
0b 00000083`1a7fdc90 00007fff`729c621b xul!nsViewManager::PaintWindow(class nsIWidget * aWidget = <Value unavailable error>, class mozilla::gfx::IntRegionTyped<mozilla::LayoutDevicePixel> * aRegion = <Value unavailable error>)+0x47 [/builds/worker/checkouts/gecko/view/nsViewManager.cpp @ 695] 
0c 00000083`1a7fdcd0 00007fff`72a9af16 xul!nsView::PaintWindow(class nsIWidget * aWidget = <Value unavailable error>, class mozilla::gfx::IntRegionTyped<mozilla::LayoutDevicePixel> * aRegion = 0x00007fff`75c45240)+0x2b [/builds/worker/checkouts/gecko/view/nsView.cpp @ 1055] 
0d 00000083`1a7fdd30 00007fff`72a9b774 xul!nsWindow::OnPaint(struct HDC__ * aDC = <Value unavailable error>, unsigned int aNestingLevel = 1)+0x3c6 [/builds/worker/checkouts/gecko/widget/windows/nsWindowGfx.cpp @ 387] 
0e 00000083`1a7fdff0 00007fff`72a917ce xul!nsWindow::OnPaint(struct HDC__ * aDC = <Value unavailable error>, unsigned int aNestingLevel = 0)+0xc24 [/builds/worker/checkouts/gecko/widget/windows/nsWindowGfx.cpp @ 431] 
0f 00000083`1a7fe2b0 00007fff`72a907fb xul!nsWindow::ProcessMessage(unsigned int msg = 0xf, unsigned int64 * wParam = 0x00000083`1a7fe528, int64 * lParam = 0x00000083`1a7fe530, int64 * aRetValue = 0x00000083`1a7fe500)+0x64e [/builds/worker/checkouts/gecko/widget/windows/nsWindow.cpp @ 5491] 
10 00000083`1a7fe4d0 00007fff`7067054f xul!nsWindow::WindowProcInternal(struct HWND__ * hWnd = <Value unavailable error>, unsigned int msg = 0xf, unsigned int64 wParam = 0, int64 lParam = 0n0)+0xfb [/builds/worker/checkouts/gecko/widget/windows/nsWindow.cpp @ 4982] 
11 00000083`1a7fe570 00007fff`72a880d5 xul!CallWindowProcCrashProtected(<function> * aWndProc = <Value unavailable error>, struct HWND__ * aHWnd = <Value unavailable error>, unsigned int aMsg = <Value unavailable error>, unsigned int64 aWParam = <Value unavailable error>, int64 aLParam = 0n0)+0x1f [/builds/worker/checkouts/gecko/xpcom/base/nsCrashOnException.cpp @ 32] 
12 00000083`1a7fe5a0 00007fff`e1b2e338 xul!nsWindow::WindowProc(struct HWND__ * hWnd = 0x00000000`00130400, unsigned int msg = 0xf, unsigned int64 wParam = 0, int64 lParam = 0n0)+0x65 [/builds/worker/checkouts/gecko/widget/windows/nsWindow.cpp @ 4935] 
13 00000083`1a7fe610 00007fff`e1b2debc user32!UserCallWinProcCheckWow+0x2f8
14 00000083`1a7fe7a0 00007fff`e1b406a3 user32!DispatchClientMessage+0x9c
15 00000083`1a7fe800 00007fff`e220ebc4 user32!_fnDWORD+0x33
16 00000083`1a7fe860 00007fff`e01b1704 ntdll!KiUserCallbackDispatcherContinue
17 00000083`1a7fe8e8 00007fff`e1b2ddca win32u!NtUserDispatchMessage+0x14
18 00000083`1a7fe8f0 00007fff`72a650bb user32!DispatchMessageWorker+0x29a
19 00000083`1a7fe970 00007fff`729f1852 xul!nsAppShell::ProcessNextNativeEvent(bool mayWait = <Value unavailable error>)+0x1ab [/builds/worker/checkouts/gecko/widget/windows/nsAppShell.cpp @ 577] 
1a (Inline Function) --------`-------- xul!nsBaseAppShell::DoProcessNextNativeEvent+0x26 [/builds/worker/checkouts/gecko/widget/nsBaseAppShell.cpp @ 120] 
1b 00000083`1a7fea90 00007fff`6fdb3185 xul!nsBaseAppShell::OnProcessNextEvent(class nsIThreadInternal * thr = 0x00000205`9e373500, bool mayWait = false)+0xb2 [/builds/worker/checkouts/gecko/widget/nsBaseAppShell.cpp @ 242] 
1c 00000083`1a7feb10 00007fff`6fdb2f35 xul!nsThread::ProcessNextEvent(bool aMayWait = false, bool * aResult = 0x00000083`1a7ff13f)+0x135 [/builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp @ 1129] 
1d 00000083`1a7ff110 00007fff`70be69ca xul!NS_ProcessNextEvent(class nsIThread * aThread = 0x00000205`9e373500, bool aMayWait = false)+0x45 [/builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp @ 501] 
1e 00000083`1a7ff160 00007fff`70bbe9a8 xul!mozilla::ipc::MessagePump::Run(class base::MessagePump::Delegate * aDelegate = 0x00000205`9e30cac0)+0xfa [/builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp @ 87] 
1f (Inline Function) --------`-------- xul!MessageLoop::RunInternal+0xf [/builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc @ 315] 
20 00000083`1a7ff1e0 00007fff`6fd8b441 xul!MessageLoop::RunHandler(void)+0x28 [/builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc @ 309] 
21 00000083`1a7ff230 00007fff`6ff5f014 xul!MessageLoop::Run(void)+0x51 [/builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc @ 291] 
22 00000083`1a7ff280 00007fff`6ff5e616 xul!nsBaseAppShell::Run(void)+0x34 [/builds/worker/checkouts/gecko/widget/nsBaseAppShell.cpp @ 139] 
23 00000083`1a7ff2c0 00007fff`738e1b42 xul!nsAppShell::Run(void)+0xb6 [/builds/worker/checkouts/gecko/widget/windows/nsAppShell.cpp @ 430] 
24 00000083`1a7ff310 00007fff`7399199d xul!nsAppStartup::Run(void)+0x32 [/builds/worker/checkouts/gecko/toolkit/components/startup/nsAppStartup.cpp @ 272] 
25 00000083`1a7ff360 00007fff`73992ba3 xul!XREMain::XRE_mainRun(void)+0x8ad [/builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp @ 4709] 
26 00000083`1a7ff5e0 00007fff`73992fcc xul!XREMain::XRE_main(int argc = <Value unavailable error>, char ** argv = <Value unavailable error>, struct mozilla::BootstrapConfig * aConfig = 0x00000083`1a7ff890)+0x393 [/builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp @ 4856] 
*** WARNING: Unable to verify timestamp for firefox.exe
27 00000083`1a7ff6a0 00007ff6`49ca14ba xul!XRE_main(int argc = <Value unavailable error>, char ** argv = <Value unavailable error>, struct mozilla::BootstrapConfig * aConfig = <Value unavailable error>)+0x9c [/builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp @ 4910] 
28 (Inline Function) --------`-------- firefox!do_main+0xe0 [/builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp @ 217] 
29 00000083`1a7ff800 00000205`9e30a080 firefox!NS_internal_main(int argc = <Value unavailable error>, char ** argv = <Value unavailable error>, char ** envp = <Value unavailable error>)+0x23a [/builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp @ 331] 
2a 00000083`1a7ff808 00000205`9e200000 0x00000205`9e30a080
2b 00000083`1a7ff810 00000205`9e3021c0 0x00000205`9e200000
2c 00000083`1a7ff818 00000205`9e200000 0x00000205`9e3021c0
2d 00000083`1a7ff820 00000205`9df68f60 0x00000205`9e200000
2e 00000083`1a7ff828 00000000`00000000 0x00000205`9df68f60

Stack dump from GPU process:

0:036> ~0 kp
 # Child-SP          RetAddr           Call Site
00 00000070`06bfeb78 00007fff`e1b4026e win32u!NtUserMsgWaitForMultipleObjectsEx+0x14
*** WARNING: Unable to verify checksum for xul.dll
01 00000070`06bfeb80 00007fff`72a6530d user32!RealMsgWaitForMultipleObjectsEx+0x1e
02 (Inline Function) --------`-------- xul!mozilla::widget::WinUtils::WaitForMessage+0x92 [/builds/worker/checkouts/gecko/widget/windows/WinUtils.cpp @ 750] 
03 00000070`06bfebc0 00007fff`729f18d9 xul!nsAppShell::ProcessNextNativeEvent(bool mayWait = true)+0x3fd [/builds/worker/checkouts/gecko/widget/windows/nsAppShell.cpp @ 570] 
04 (Inline Function) --------`-------- xul!nsBaseAppShell::DoProcessNextNativeEvent+0x23 [/builds/worker/checkouts/gecko/widget/nsBaseAppShell.cpp @ 120] 
05 00000070`06bfece0 00007fff`6fdb3185 xul!nsBaseAppShell::OnProcessNextEvent(class nsIThreadInternal * thr = 0x00000236`1c14f180, bool mayWait = <Value unavailable error>)+0x139 [/builds/worker/checkouts/gecko/widget/nsBaseAppShell.cpp @ 259] 
06 00000070`06bfed60 00007fff`6fdb2f35 xul!nsThread::ProcessNextEvent(bool aMayWait = true, bool * aResult = 0x00000070`06bff38f)+0x135 [/builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp @ 1129] 
07 00000070`06bff360 00007fff`70be6a5f xul!NS_ProcessNextEvent(class nsIThread * aThread = 0x00000236`1c14f180, bool aMayWait = true)+0x45 [/builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp @ 501] 
08 00000070`06bff3b0 00007fff`70bbe9a8 xul!mozilla::ipc::MessagePump::Run(class base::MessagePump::Delegate * aDelegate = 0x00000070`06bff690)+0x18f [/builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp @ 109] 
09 (Inline Function) --------`-------- xul!MessageLoop::RunInternal+0xf [/builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc @ 315] 
0a 00000070`06bff430 00007fff`6fd8b441 xul!MessageLoop::RunHandler(void)+0x28 [/builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc @ 309] 
0b 00000070`06bff480 00007fff`6ff5f014 xul!MessageLoop::Run(void)+0x51 [/builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc @ 291] 
0c 00000070`06bff4d0 00007fff`6ff5e616 xul!nsBaseAppShell::Run(void)+0x34 [/builds/worker/checkouts/gecko/widget/nsBaseAppShell.cpp @ 139] 
0d 00000070`06bff510 00007fff`6ff5d045 xul!nsAppShell::Run(void)+0xb6 [/builds/worker/checkouts/gecko/widget/windows/nsAppShell.cpp @ 430] 
0e 00000070`06bff560 00007fff`70bbe9a8 xul!XRE_RunAppShell(void)+0x45 [/builds/worker/checkouts/gecko/toolkit/xre/nsEmbedFunctions.cpp @ 913] 
0f (Inline Function) --------`-------- xul!MessageLoop::RunInternal+0xf [/builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc @ 315] 
10 00000070`06bff5a0 00007fff`6fd8b441 xul!MessageLoop::RunHandler(void)+0x28 [/builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc @ 309] 
11 00000070`06bff5f0 00007fff`6fd83da7 xul!MessageLoop::Run(void)+0x51 [/builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc @ 291] 
*** WARNING: Unable to verify timestamp for firefox.exe
12 00000070`06bff640 00007ff6`49ca16f2 xul!XRE_InitChildProcess(int aArgc = 0n15, char ** aArgv = 0x00000236`1c10bc90, struct XREChildData * aChildData = 0x00000070`06bff8b0)+0x347 [/builds/worker/checkouts/gecko/toolkit/xre/nsEmbedFunctions.cpp @ 748] 
13 00000070`06bff890 00000000`00000000 firefox!content_process_main(class mozilla::Bootstrap * bootstrap = 0x00000236`1c102160, int argc = 0n19, char ** argv = 0x00000236`1c10bc90)+0x72 [/builds/worker/checkouts/gecko/browser/app/../../ipc/contentproc/plugin-container.cpp @ 56] 

Comment 1

[James Teh [:Jamie]]

I started using Fast Tab Switcher again regularly a few days ago and I haven't seen this. I'm hoping it's gone, but I'll reopen if it resurfaces.