Potential jank caused by DisableSwapUntilResize |
||||||||||
Issue descriptionWe are seeing a slow reports with long tasks on the UI thread. It seems related to MessagePumpForUI::ProcessMessageHelper call twice (recursive). see: 24834fa6886e0273 - 27 seconds The sampling profiler is pointing telling us the main thread is stalled here: ZwWaitForMultipleObjects WaitForMultipleObjectsEx WaitForMultipleObjects base::WaitableEvent::WaitMany(base::WaitableEvent * *,unsigned __int64) mojo::WaitSet::State::Wait(base::WaitableEvent * *,unsigned __int64 *,mojo::Handle *,unsigned int *,MojoHandleSignalsState *) mojo::SyncHandleRegistry::Wait(bool const * * const,unsigned __int64) mojo::SyncEventWatcher::SyncWatch(bool const * *,unsigned __int64) mojo::SequenceLocalSyncEventWatcher::SyncWatch(bool const *) mojo::InterfaceEndpointClient::AcceptWithResponder(mojo::Message *,std::unique_ptr<mojo::MessageReceiver,std::default_delete<mojo::MessageReceiver> >) viz::mojom::DisplayPrivateProxy::DisableSwapUntilResize() ui::HostContextFactoryPrivate::DisableSwapUntilResize(ui::Compositor *) ui::Compositor::DisableSwapUntilResize() views::HWNDMessageHandler::OnWindowPosChanging(tagWINDOWPOS *) views::HWNDMessageHandler::_ProcessWindowMessage(HWND__ *,unsigned int,unsigned __int64,__int64,__int64 &,unsigned long) views::HWNDMessageHandler::OnWndProc(unsigned int,unsigned __int64,__int64) base::win::WrappedWindowProc<&gfx::WindowImpl::WndProc(HWND__ *,unsigned int,unsigned __int64,__int64)>(HWND__ *,unsigned int,unsigned __int64,__int64) UserCallWinProcCheckWow DispatchClientMessage _fnINOUTLPWINDOWPOS KiUserCallbackDispatcherContinue NtUserSetWindowPos views::HWNDMessageHandler::SetBoundsInternal(gfx::Rect const &,bool) views::DesktopWindowTreeHostWin::SetBoundsInPixels(gfx::Rect const &,viz::LocalSurfaceIdAllocation const &) views::DesktopNativeWidgetAura::SetBounds(gfx::Rect const &) StatusBubbleViews::RepositionPopup() StatusBubbleViews::SetBounds(int,int,int,int) StatusBubbleViews::Reposition() views::View::BoundsChanged(gfx::Rect const &) views::View::SetBoundsRect(gfx::Rect const &) ContentsLayoutManager::Layout(views::View *) views::View::Layout() views::View::BoundsChanged(gfx::Rect const &) views::View::SetBoundsRect(gfx::Rect const &) BrowserViewLayout::LayoutContentsContainerView(int,int) BrowserViewLayout::Layout(views::View *) views::View::Layout() BrowserView::Layout() views::View::BoundsChanged(gfx::Rect const &) views::View::SetBoundsRect(gfx::Rect const &) views::NonClientView::Layout() views::View::BoundsChanged(gfx::Rect const &) views::View::SetBoundsRect(gfx::Rect const &) views::FillLayout::Layout(views::View *) views::View::Layout() views::View::BoundsChanged(gfx::Rect const &) views::View::SetBoundsRect(gfx::Rect const &) views::View::SetBounds(int,int,int,int) views::View::SetSize(gfx::Size const &) views::Widget::OnNativeWidgetSizeChanged(gfx::Size const &) views::DesktopNativeWidgetAura::OnHostResized(aura::WindowTreeHost *) aura::WindowTreeHost::OnHostResizedInPixels(gfx::Size const &,viz::LocalSurfaceIdAllocation const &) views::DesktopWindowTreeHostWin::HandleClientSizeChanged(gfx::Size const &) views::HWNDMessageHandler::ClientAreaSizeChanged() views::HWNDMessageHandler::OnWindowPosChanged(tagWINDOWPOS *) views::HWNDMessageHandler::_ProcessWindowMessage(HWND__ *,unsigned int,unsigned __int64,__int64,__int64 &,unsigned long) views::HWNDMessageHandler::OnWndProc(unsigned int,unsigned __int64,__int64) base::win::WrappedWindowProc<&gfx::WindowImpl::WndProc(HWND__ *,unsigned int,unsigned __int64,__int64)>(HWND__ *,unsigned int,unsigned __int64,__int64) UserCallWinProcCheckWow DispatchClientMessage _fnINLPWINDOWPOS KiUserCallbackDispatcherContinue NtUserMessageCall RealDefWindowProcWorker RealDefWindowProcW DoMsgDefault(_THEME_MSG const *) OnDwpSysCommand(CThemeWnd *,_THEME_MSG *) _ThemeDefWindowProc(HWND__ *,unsigned int,unsigned __int64,__int64,int) ThemeDefWindowProcW DefWindowProcW views::HWNDMessageHandler::OnSysCommand(unsigned int,gfx::Point const &) views::HWNDMessageHandler::_ProcessWindowMessage(HWND__ *,unsigned int,unsigned __int64,__int64,__int64 &,unsigned long) views::HWNDMessageHandler::OnWndProc(unsigned int,unsigned __int64,__int64) base::win::WrappedWindowProc<&gfx::WindowImpl::WndProc(HWND__ *,unsigned int,unsigned __int64,__int64)>(HWND__ *,unsigned int,unsigned __int64,__int64) UserCallWinProcCheckWow DispatchClientMessage _fnDWORD KiUserCallbackDispatcherContinue NtUserMessageCall RealDefWindowProcWorker RealDefWindowProcW DoMsgDefault(_THEME_MSG const *) OnDwpNcLButtonDown(CThemeWnd *,_THEME_MSG *) _ThemeDefWindowProc(HWND__ *,unsigned int,unsigned __int64,__int64,int) ThemeDefWindowProcW DefWindowProcW views::HWNDMessageHandler::OnWndProc(unsigned int,unsigned __int64,__int64) base::win::WrappedWindowProc<&gfx::WindowImpl::WndProc(HWND__ *,unsigned int,unsigned __int64,__int64)>(HWND__ *,unsigned int,unsigned __int64,__int64) UserCallWinProcCheckWow DispatchMessageWorker base::MessagePumpForUI::ProcessMessageHelper(tagMSG const &) base::MessagePumpForUI::ProcessMessageHelper(tagMSG const &) base::MessagePumpForUI::DoRunLoop() base::MessagePumpWin::Run(base::MessagePump::Delegate *) base::RunLoop::Run() ChromeBrowserMainParts::MainMessageLoopRun(int *) content::BrowserMainLoop::RunMainMessageLoopParts() content::BrowserMainRunnerImpl::Run() content::BrowserMain(content::MainFunctionParams const &) content::RunBrowserProcessMain(content::MainFunctionParams const &,content::ContentMainDelegate *) content::ContentMainRunnerImpl::Run(bool) service_manager::Main(service_manager::MainParams const &) content::ContentMain(content::ContentMainParams const &) ChromeMain MainDllLoader::Launch(HINSTANCE__ *,base::TimeTicks) wWinMain __scrt_common_main_seh BaseThreadInitThunk RtlUserThreadStart
,
Nov 23
Reports: 725bfb303dc5eb6e - 18 seconds 56b5982249abfb9f - 9 seconds
,
Nov 23
In the function 'ui::HostContextFactoryPrivate::DisableSwapUntilResize', there is a TODO pointing to that bug: https://bugs.chromium.org/p/chromium/issues/detail?id=859168 // Browser needs to block for Viz to receive and process this message. // Otherwise when we return from WM_WINDOWPOSCHANGING message handler and // receive a WM_WINDOWPOSCHANGED the resize is finalized and any swaps of // wrong size by Viz can cause the swapped content to get scaled. // TODO(crbug.com/859168): Investigate nonblocking ways for solving.
,
Nov 23
,
Nov 23
,
Nov 23
,
Nov 23
This reports seems to be the same bug, but not under MessagePumpForUI::ProcessMessageHelper. see: f83b27cad07a6f07 (attachment) kylechar@, can you confirm? see comment in Display::Resize(...) // Need to ensure all pending swaps have executed before the window is // resized, or D3D11 will scale the swap output. Looking to the trace: 1) The main thread is blocked for 8 seconds, after calling: content::GpuProcessTransportFactory::DisableSwapUntilResize 2) The GPU seems to run some code, and some Sleep(...) calls 3) Renderer pid=8436 is aligned with the end of the jank. Which is probably the cause of the jank on the main thread.
,
Nov 23
,
Nov 27
,
Nov 27
,
Nov 27
From the trace in comment #7: it looks like the gpu-thread is blocked on handling async-flush commands, which then causes the jank in the browser-UI thread. It seems to also block the renderers (the main-thread in renderer-12604, and a raster-thread in renderer-8436). +backer@ is it possible to get any more details about what kind of work the gpu-thread might be doing from the trace?
,
Nov 27
--enable-gpu-service-tracing will trace every GL call going through GL/ANGLE. It has severe performance penalties, but given that you are hung, it should shed some light here.
,
Nov 27
I don't think --enable-gpu-service-tracing isn't an option since these are always on traces (so they need to be lightweight) that get uploaded when jank is detected. We do have sampling profiler data for CrGpuMain in the trace for #7 though which gives a pretty good idea of what the thread is doing. There are events labelled "Sampling Profiler" right below CrGpuMain. The GPU thread is spending a lot of time in CommandBufferService:PutChanged event. It spends 20s, then 13s and a little while later 2.3s, 5.7s and 3.3s. Having the GPU thread blocked for multiple seconds seems like an issue?
,
Nov 28
I landed a CL yesterday to sample process priority. I have an hypothesis that the renderer *may* be backgrounded, which will be a direct priority inversion. I'll wait a few days to get more traces. If you have other things you want to instrument, ping me.
,
Nov 29
+geofflang/jmadill for ANGLE and sunnyps for GPU scheduler The trace in #7 has some interesting behaviour on the GPU main thread. Scheduler::RunNextTask() has a bunch of multiple second (20s, 13s, etc) long tasks. From the sampling profiler data it looks like ANGLE/DirectX is drawing things. Sample stack: "NtDelayExecution kernelbase.pdb igd10iumd64.pdb d3d11.pdb igd10iumd64.pdb igd10iumd64.pdb igd10iumd64.pdb d3d11.pdb rx::Renderer11::drawElements(gl::Context const *,gl::PrimitiveMode,int,int,unsigned int,void const *,int) rx::Context11::drawElements(gl::Context const *,gl::PrimitiveMode,int,unsigned int,void const *) gl::Context::drawElements(gl::PrimitiveMode,int,unsigned int,void const *) gl::DrawElements(unsigned int,int,unsigned int,void const *) gpu::gles2::GLES2DecoderPassthroughImpl::DoDrawElements(unsigned int,int,unsigned int,void const *) gpu::gles2::GLES2DecoderPassthroughImpl::HandleDrawElements(unsigned int,void const volatile *) gpu::gles2::GLES2DecoderPassthroughImpl::DoCommandsImpl<0>(unsigned int,void const volatile *,int,int *) gpu::gles2::GLES2DecoderPassthroughImpl::DoCommands(unsigned int,void const volatile *,int,int *) gpu::CommandBufferService::Flush(int,gpu::AsyncAPIInterface *) gpu::CommandBufferStub::OnAsyncFlush(int,unsigned int) IPC::MessageT<GpuCommandBufferMsg_AsyncFlush_Meta,std::tuple<int,unsigned int>,void>::Dispatch<gpu::CommandBufferStub,gpu::CommandBufferStub,void,void (gpu::CommandBufferStub::*)(int, unsigned int)> gpu::CommandBufferStub::OnMessageReceived(IPC::Message const &) gpu::GpuChannel::HandleMessageHelper(IPC::Message const &) gpu::GpuChannel::HandleMessage(IPC::Message const &) gpu::Scheduler::RunNextTask() base::debug::TaskAnnotator::RunTask(char const *,base::PendingTask *) base::MessageLoopImpl::RunTask(base::PendingTask *) base::MessageLoopImpl::DoWork() base::MessagePumpDefault::Run(base::MessagePump::Delegate *) base::RunLoop::Run() content::GpuMain(content::MainFunctionParams const &) content::ContentMainRunnerImpl::Run(bool) service_manager::Main(service_manager::MainParams const &) content::ContentMain(content::ContentMainParams const &) ChromeMain MainDllLoader::Launch(HINSTANCE__ *,base::TimeTicks) wWinMain __scrt_common_main_seh BaseThreadInitThunk RtlUserThreadStart Do we have any idea what's going on here from the sampling profiler and trace data? Is there a huge backlog of quads to draw that takes tens of seconds to get through, or is something else wrong here?
,
Nov 29
etienneb@ pointed out to me that NtDelayExecution at the top of the stack trace means the thread is sleeping.
,
Jan 16
(6 days ago)
From this slow-reports: c92310829c1e78ae 8 seconds jank on the main thread, mouse inputs are stalled. base::WaitableEvent::WaitMany(base::WaitableEvent * *,unsigned __int64) mojo::WaitSet::State::Wait(base::WaitableEvent * *,unsigned __int64 *,mojo::Handle *,unsigned int *,MojoHandleSignalsState *) mojo::SyncHandleRegistry::Wait(bool const * * const,unsigned __int64) mojo::SyncEventWatcher::SyncWatch(bool const * *,unsigned __int64) mojo::SequenceLocalSyncEventWatcher::SyncWatch(bool const *) mojo::InterfaceEndpointClient::AcceptWithResponder(mojo::Message *,std::unique_ptr<mojo::MessageReceiver,std::default_delete<mojo::MessageReceiver> >) viz::mojom::DisplayPrivateProxy::DisableSwapUntilResize() ui::HostContextFactoryPrivate::DisableSwapUntilResize(ui::Compositor *) ui::Compositor::DisableSwapUntilResize()
,
Jan 17
(6 days ago)
FWIW the trace in #7 uses passthrough command decoder which we haven't shipped to stable yet. Just an observation. Trace in #17 doesn't show symbols for me, and there are no GPU process traces for that time range. |
||||||||||
►
Sign in to add a comment |
||||||||||
Comment 1 by etienneb@chromium.org
, Nov 2321.1 KB
21.1 KB View Download