Chromium Code Reviews
chromiumcodereview-hr@appspot.gserviceaccount.com (chromiumcodereview-hr) | Please choose your nickname with Settings | Help | Chromium Project | Gerrit Changes | Sign out
(36)

Issues Search
    My Issues | Starred     Open | Closed | All

Issue 793893002: Instrumenting WM_ message handler to find jank (Closed)

Created:
6 years ago by vadimt
Modified:
6 years ago
Reviewers:
cpu_(ooo_6.6-7.5), sky
CC:
chromium-reviews, erikwright+watch_chromium.org, sadrul
Base URL:
https://chromium.googlesource.com/chromium/src.git@master
Project:
chromium
Visibility:
Public.

Description

Instrumenting WM_ message handler to find jank. This is a follow-up for an internal discussion about possible jank, and more generally, performance issues that potentially are not tracked by about://profiler and UMA profiler data. This CL adds instrumentation that adds tracking for all WM_ message handlers. It's enabled only in Canary, and on other channels we won't track WM_ messages. If we find it valuable and safe, we can enable this instrumentation on other channels too. BUG=440919 Committed: https://crrev.com/58954e90e4eb2c64ec8de2b2d3ae97b7d02a9328 Cr-Commit-Position: refs/heads/master@{#308001}

Patch Set 1 #

Unified diffs Side-by-side diffs Delta from patch set Stats (+6 lines, -0 lines) Patch
M base/message_loop/message_pump_win.cc View 2 chunks +6 lines, -0 lines 0 comments Download

Messages

Total messages: 18 (7 generated)
vadimt
cpu@, please review
6 years ago (2014-12-10 21:10:06 UTC) #2
cpu_(ooo_6.6-7.5)
what is the performance impact of doing this tracking? lgtm at least for some devs ...
6 years ago (2014-12-11 20:29:02 UTC) #3
vadimt
For Canary, where it's currently enabled by this CL, we'll tally a task birth/death 12% ...
6 years ago (2014-12-11 21:52:02 UTC) #4
sky
What happens if we (or windows) spawns a nested message loop during processing?
6 years ago (2014-12-11 22:09:12 UTC) #11
vadimt
I never saw ProcessNextWindowsMessage invoking a nested message loop. It's possible for a task to ...
6 years ago (2014-12-11 22:47:21 UTC) #12
commit-bot: I haz the power
CQ is trying da patch. Follow status at https://chromium-cq-status.appspot.com/patch-status/793893002/1
6 years ago (2014-12-11 23:08:50 UTC) #13
sky
I'm not sure that is always the case. What about drag and drop, or event ...
6 years ago (2014-12-12 00:05:27 UTC) #14
commit-bot: I haz the power
Committed patchset #1 (id:1)
6 years ago (2014-12-12 00:10:52 UTC) #15
commit-bot: I haz the power
Patchset 1 (id:??) landed as https://crrev.com/58954e90e4eb2c64ec8de2b2d3ae97b7d02a9328 Cr-Commit-Position: refs/heads/master@{#308001}
6 years ago (2014-12-12 00:11:30 UTC) #16
vadimt
tl;dr; All is good and correct for nested executions. Details: For the above scenarios, we ...
6 years ago (2014-12-12 02:34:52 UTC) #17
sky
6 years ago (2014-12-12 15:52:20 UTC) #18
Message was sent while issue was closed. 
Nice!

On Thu, Dec 11, 2014 at 6:34 PM, Vadim Tryshev <vadimt@chromium.org> wrote:
> tl;dr; All is good and correct for nested executions.
>
> Details:
> For the above scenarios, we still don't get a recursion.
>
> I managed to repro a recursion, though, by clicking at the sandwich menu
> (stack below).
>
> In this case, for one outer execution of ProcessNextWindowsMessage, we
> record N+1 executions of "440919
> <<MessagePumpForUI::ProcessNextWindowsMessage>>" task, where N is the number
> of the nested ones, and 1 is the outer one.
>
> The time that we spent in the nested loop will be subtracted from the outer
> task's execution (that's why we have TaskStopwatch in RunLoop::Run that sits
> between the nested calls on the stack).
>
> Stack:
>
> ====base::MessagePumpForUI::ProcessNextWindowsMessage() C++
>   base::MessagePumpForUI::DoRunLoop() C++
>   base::MessagePumpWin::RunWithDispatcher() C++
>   base::MessageLoop::RunHandler() C++
>   base::RunLoop::Run() C++
>   base::internal::RunnableAdapter<void (__thiscall
> base::RunLoop::*)(void)>::Run() C++
>   base::internal::InvokeHelper<0,void,base::internal::RunnableAdapter<void
> (__thiscall base::RunLoop::*)(void)>,void __cdecl(base::RunLoop
> *)>::MakeItSo() C++
>
>
base::internal::Invoker<1,base::internal::BindState<base::internal::RunnableAdapter<void
> (__thiscall base::RunLoop::*)(void)>,void __cdecl(base::RunLoop *),void
> __cdecl(base::internal::OwnedWrapper<base::RunLoop>)>,void
> __cdecl(base::RunLoop *)>::Run() C++
>   base::Callback<void __cdecl(void)>::Run() C++
>   aura::client::DispatcherRunLoop::Run() C++
>   views::MenuMessageLoopAura::Run() C++
>   views::MenuController::RunMessageLoop() C++
>   views::MenuController::Run() C++
>   views::internal::MenuRunnerImpl::RunMenuAt() C++
>   views::MenuRunner::RunMenuAt() C++
>   WrenchMenu::RunMenu() C++
>   ToolbarView::ShowAppMenu() C++
>   ToolbarView::OnMenuButtonClicked() C++
>   views::MenuButton::Activate() C++
>   views::MenuButton::OnMousePressed() C++
>   views::View::ProcessMousePressed() C++
>   views::View::OnMouseEvent() C++
>   ui::EventHandler::OnEvent() C++
>   ui::EventTarget::OnEvent() C++
>   ui::EventDispatcher::DispatchEvent() C++
>   ui::EventDispatcher::ProcessEvent() C++
>   ui::EventDispatcherDelegate::DispatchEventToTarget() C++
>   ui::EventDispatcherDelegate::DispatchEvent() C++
>   views::internal::RootView::OnMousePressed() C++
>   views::Widget::OnMouseEvent() C++
>   views::DesktopNativeWidgetAura::OnMouseEvent() C++
>   ui::EventHandler::OnEvent() C++
>   ui::EventTarget::OnEvent() C++
>   ui::EventDispatcher::DispatchEvent() C++
>   ui::EventDispatcher::ProcessEvent() C++
>   ui::EventDispatcherDelegate::DispatchEventToTarget() C++
>   ui::EventDispatcherDelegate::DispatchEvent() C++
>   ui::EventProcessor::OnEventFromSource() C++
>   ui::EventSource::DeliverEventToProcessor() C++
>   ui::EventSource::SendEventToProcessor() C++
>   views::DesktopWindowTreeHostWin::HandleMouseEvent() C++
>   views::HWNDMessageHandler::HandleMouseEventInternal() C++
>   views::HWNDMessageHandler::OnMouseRange() C++
>   views::HWNDMessageHandler::_ProcessWindowMessage() C++
>   views::HWNDMessageHandler::OnWndProc() C++
>   gfx::WindowImpl::WndProc() C++
>   base::win::WrappedWindowProc<&gfx::WindowImpl::WndProc>() C++
>   _InternalCallWinProc@20()
>   _UserCallWinProcCheckWow@32()
>   _DispatchMessageWorker@8()
>   _DispatchMessageW@4()
>   base::MessagePumpForUI::ProcessMessageHelper() C++
> ====base::MessagePumpForUI::ProcessNextWindowsMessage() C++
>   base::MessagePumpForUI::DoRunLoop() C++
>   base::MessagePumpWin::RunWithDispatcher() C++
>   base::MessagePumpWin::Run() C++
>   base::MessageLoop::RunHandler() C++
>   base::RunLoop::Run() C++
>   ChromeBrowserMainParts::MainMessageLoopRun() C++
>   content::BrowserMainLoop::RunMainMessageLoopParts() C++
>   content::BrowserMainRunnerImpl::Run() C++
>   content::BrowserMain() C++
>   content::RunNamedProcessTypeMain() C++
>   content::ContentMainRunnerImpl::Run() C++
>   content::ContentMain() C++
>   ChromeMain() C++
>   MainDllLoader::Launch() C++
>   wWinMain() C++
>   __tmainCRTStartup() C
>
>
> On Thu, Dec 11, 2014 at 4:05 PM, Scott Violet <sky@chromium.org> wrote:
>>
>> I'm not sure that is always the case. What about drag and drop, or
>> event dragging a window around? What about showing a system menu
>> (right click on the tabstrip).
>>
>> On Thu, Dec 11, 2014 at 2:47 PM, Vadim Tryshev <vadimt@chromium.org>
>> wrote:
>> > I never saw ProcessNextWindowsMessage invoking a nested message loop.
>> >
>> > It's possible for a task to invoke a nested message loop though, but
>> > tasks
>> > are started outside of ProcessNextWindowsMessage.
>> >
>> > I.e. the stack for starting a task looks like:
>> >> base::MessageLoop::RunTask() C++
>> >   base::MessageLoop::DeferOrRunPendingTask() C++
>> >   base::MessageLoop::DoDelayedWork() C++
>> >   base::MessagePumpForUI::DoRunLoop() C++
>> >
>> > and a stack that invokes ProcessNextWindowsMessage looks like:
>> >> base::MessagePumpForUI::ProcessNextWindowsMessage() C++
>> >   base::MessagePumpForUI::DoRunLoop() C++
>> >
>> >
>> > For your entertainment, I'm including an example of a stack with a
>> > nested
>> > loop:
>> >
>> >> compositor.dll!ui::Compositor::Draw() C++
>> >
>> > compositor.dll!base::internal::RunnableAdapter<void (__thiscall
>> > ui::Compositor::*)(void)>::Run(ui::Compositor *) C++
>> >
>> >
>> >
compositor.dll!base::internal::InvokeHelper<1,void,base::internal::RunnableAdapter<void
>> > (__thiscall ui::Compositor::*)(void)>,void
>> > __cdecl(base::WeakPtr<ui::Compositor> const
>> > &)>::MakeItSo(base::internal::RunnableAdapter<void (__thiscall
>> > ui::Compositor::*)(void)>, const base::WeakPtr<ui::Compositor> &) C++
>> >
>> >
>> >
compositor.dll!base::internal::Invoker<1,base::internal::BindState<base::internal::RunnableAdapter<void
>> > (__thiscall ui::Compositor::*)(void)>,void __cdecl(ui::Compositor
>> > *),void
>> > __cdecl(base::WeakPtr<ui::Compositor>)>,void __cdecl(ui::Compositor
>> > *)>::Run(base::internal::BindStateBase *) C++
>> >
>> > base.dll!base::Callback<void __cdecl(void)>::Run() C++
>> >
>> > base.dll!base::MessageLoop::RunTask(const base::PendingTask &) C++
>> >
>> > base.dll!base::MessageLoop::DeferOrRunPendingTask(const
>> > base::PendingTask &)
>> > C++
>> >
>> > base.dll!base::MessageLoop::DoWork() C++
>> >
>> > base.dll!base::MessagePumpForUI::DoRunLoop() C++
>> >
>> >
>> >
base.dll!base::MessagePumpWin::RunWithDispatcher(base::MessagePump::Delegate
>> > *, base::MessagePumpDispatcher *) C++
>> >
>> > base.dll!base::MessageLoop::RunHandler() C++
>> >
>> > base.dll!base::RunLoop::Run() C++
>> >
>> >
>> >
views.dll!views::DesktopDispatcherClient::RunWithDispatcher(base::MessagePumpDispatcher
>> > *) C++
>> >
>> > views.dll!views::MenuMessageLoopAura::Run(views::MenuController *,
>> > views::Widget *, bool) C++
>> >
>> > views.dll!views::MenuController::RunMessageLoop(bool) C++
>> >
>> > views.dll!views::MenuController::Run(views::Widget *, views::MenuButton
>> > *,
>> > views::MenuItemView *, const gfx::Rect &, views::MenuAnchorPosition,
>> > bool,
>> > int *) C++
>> >
>> > views.dll!views::internal::MenuRunnerImpl::RunMenuAt(views::Widget *,
>> > views::MenuButton *, const gfx::Rect &, views::MenuAnchorPosition, int)
>> > C++
>> >
>> > views.dll!views::MenuRunner::RunMenuAt(views::Widget *,
>> > views::MenuButton *,
>> > const gfx::Rect &, views::MenuAnchorPosition, ui::MenuSourceType, int)
>> > C++
>> >
>> > chrome.dll!RenderViewContextMenuViews::RunMenuAt(views::Widget *, const
>> > gfx::Point &, ui::MenuSourceType) C++
>> >
>> >
>> >
chrome.dll!ChromeWebContentsViewDelegateViews::ShowMenu(scoped_ptr<RenderViewContextMenu,base::DefaultDeleter<RenderViewContextMenu>
>> >>) C++
>> >
>> >
>> >
chrome.dll!ChromeWebContentsViewDelegateViews::ShowContextMenu(content::RenderFrameHost
>> > *, const content::ContextMenuParams &) C++
>> >
>> >
>> >
content.dll!content::WebContentsViewAura::ShowContextMenu(content::RenderFrameHost
>> > *, const content::ContextMenuParams &) C++
>> >
>> >
>> >
content.dll!content::WebContentsImpl::ShowContextMenu(content::RenderFrameHost
>> > *, const content::ContextMenuParams &) C++
>> >
>> > content.dll!content::RenderFrameHostImpl::OnContextMenu(const
>> > content::ContextMenuParams &) C++
>> >
>> > content.dll!DispatchToMethod<content::RenderFrameHostImpl,void
>> > (__thiscall
>> > content::RenderFrameHostImpl::*)(content::ContextMenuParams const
>> > &),content::ContextMenuParams>(content::RenderFrameHostImpl *, void
>> > (const
>> > content::ContextMenuParams &)*, const Tuple1<content::ContextMenuParams>
>> > &)
>> > C++
>> >
>> >
>> >
content.dll!FrameHostMsg_ContextMenu::Dispatch<content::RenderFrameHostImpl,content::RenderFrameHostImpl,void,void
>> > (__thiscall content::RenderFrameHostImpl::*)(content::ContextMenuParams
>> > const &)>(const IPC::Message *, content::RenderFrameHostImpl *,
>> > content::RenderFrameHostImpl *, void *, void (const
>> > content::ContextMenuParams &)*) C++
>> >
>> > content.dll!content::RenderFrameHostImpl::OnMessageReceived(const
>> > IPC::Message &) C++
>> >
>> > content.dll!content::RenderProcessHostImpl::OnMessageReceived(const
>> > IPC::Message &) C++
>> >
>> > ipc.dll!IPC::ChannelProxy::Context::OnDispatchMessage(const IPC::Message
>> > &)
>> > C++
>> >
>> > ipc.dll!base::internal::RunnableAdapter<void (__thiscall
>> > IPC::ChannelProxy::Context::*)(IPC::Message const
>> > &)>::Run(IPC::ChannelProxy::Context *, const IPC::Message &) C++
>> >
>> >
>> >
ipc.dll!base::internal::InvokeHelper<0,void,base::internal::RunnableAdapter<void
>> > (__thiscall IPC::ChannelProxy::Context::*)(IPC::Message const &)>,void
>> > __cdecl(IPC::ChannelProxy::Context * const &,IPC::Message const
>> > &)>::MakeItSo(base::internal::RunnableAdapter<void (__thiscall
>> > IPC::ChannelProxy::Context::*)(IPC::Message const &)>,
>> > IPC::ChannelProxy::Context * const &, const IPC::Message &) C++
>> >
>> >
>> >
ipc.dll!base::internal::Invoker<2,base::internal::BindState<base::internal::RunnableAdapter<void
>> > (__thiscall IPC::ChannelProxy::Context::*)(IPC::Message const &)>,void
>> > __cdecl(IPC::ChannelProxy::Context *,IPC::Message const &),void
>> > __cdecl(IPC::ChannelProxy::Context *,IPC::Message)>,void
>> > __cdecl(IPC::ChannelProxy::Context *,IPC::Message const
>> > &)>::Run(base::internal::BindStateBase *) C++
>> >
>> > base.dll!base::Callback<void __cdecl(void)>::Run() C++
>> >
>> > base.dll!base::MessageLoop::RunTask(const base::PendingTask &) C++
>> >
>> > base.dll!base::MessageLoop::DeferOrRunPendingTask(const
>> > base::PendingTask &)
>> > C++
>> >
>> > base.dll!base::MessageLoop::DoWork() C++
>> >
>> > base.dll!base::MessagePumpForUI::DoRunLoop() C++
>> >
>> >
>> >
base.dll!base::MessagePumpWin::RunWithDispatcher(base::MessagePump::Delegate
>> > *, base::MessagePumpDispatcher *) C++
>> >
>> > base.dll!base::MessagePumpWin::Run(base::MessagePump::Delegate *) C++
>> >
>> > base.dll!base::MessageLoop::RunHandler() C++
>> >
>> > base.dll!base::RunLoop::Run() C++
>> >
>> > chrome.dll!ChromeBrowserMainParts::MainMessageLoopRun(int *) C++
>> >
>> > content.dll!content::BrowserMainLoop::RunMainMessageLoopParts() C++
>> >
>> > content.dll!content::BrowserMainRunnerImpl::Run() C++
>> >
>> > content.dll!content::BrowserMain(const content::MainFunctionParams &)
>> > C++
>> >
>> > content.dll!content::RunNamedProcessTypeMain(const
>> > std::basic_string<char,std::char_traits<char>,std::allocator<char> > &,
>> > const content::MainFunctionParams &, content::ContentMainDelegate *) C++
>> >
>> > content.dll!content::ContentMainRunnerImpl::Run() C++
>> >
>> > content.dll!content::ContentMain(const content::ContentMainParams &) C++
>> >
>> > chrome.dll!ChromeMain(HINSTANCE__ *, sandbox::SandboxInterfaceInfo *)
>> > C++
>> >
>> > chrome.exe!MainDllLoader::Launch(HINSTANCE__ *) C++
>> >
>> > chrome.exe!wWinMain(HINSTANCE__ *, HINSTANCE__ *, wchar_t *, wchar_t *)
>> > C++
>> >
>> > chrome.exe!__tmainCRTStartup() C
>> >
>> > chrome.exe!wWinMainCRTStartup() C
>> >
>> > kernel32.dll!@BaseThreadInitThunk@12()
>> >
>> > ntdll.dll!___RtlUserThreadStart@8()
>> >
>> > ntdll.dll!__RtlUserThreadStart@8()
>> >
>> >
>> > On Thu, Dec 11, 2014 at 1:52 PM, Vadim Tryshev <vadimt@chromium.org>
>> > wrote:
>> >>
>> >> For Canary, where it's currently enabled by this CL, we'll tally a task
>> >> birth/death 12% more times. Given the efficiency of task tracking,
>> >> should be
>> >> acceptable. This also adds 3 tracked objects to ~2000 that are sent via
>> >> UMA.
>> >>
>> >> For other channels, we just execute trivial constructor/destructor of
>> >> ScopedTracker, so the effect should be negligible.
>> >>
>> >> On Thu, Dec 11, 2014 at 12:29 PM, <cpu@chromium.org> wrote:
>> >>>
>> >>> what is the performance impact of doing this tracking?
>> >>>
>> >>> lgtm at least for some devs and canary. I am unsure about this being
>> >>> in
>> >>> stable.
>> >>>
>> >>>
>> >>> https://codereview.chromium.org/793893002/

To unsubscribe from this group and stop receiving emails from it, send an email
to chromium-reviews+unsubscribe@chromium.org.

Powered by Google App Engine
This is Rietveld 408576698