From 4191829c2aeaaae3898b241a319b8974f600a84c Mon Sep 17 00:00:00 2001 From: Gabriel Charette Date: Sat, 18 Apr 2020 00:02:34 +0000 Subject: [PATCH] [base] Add trace events for ::GetQueueStatus and ::PeekMessage in the Win pump. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit CPU stack sampling profiler jank analysis is hinting at these methods is this a bias or is there really jank in here? Add trace events to balance stack sampling with slow reports. Added trace events to both MessagePumpForUI::ProcessNextWindowsMessage and MessagePumpForUI::WaitForWork's lookups. The stack sampling analysis seems to be hinting more at ProcessNextWindowsMessage for now, but a lot of this gets inlined in Release builds so it's hard to tell for sure. This CL also highlights a discrepancy between the checks in ProcessNextWindowsMessage and WaitForWork. WaitForWork uses MSG msg = {0} whereas ProcessNextWindowsMessage uses an uninitialized MSG object. It doesn't seem necessary for this structure to be initialized, will make it consistent in a follow-up CL. R=fdoray@chromium.org Bug: 899897 Change-Id: Ibd8a43e0346e6eb7e09432582a76235ed350ae6f Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2153321 Commit-Queue: Gabriel Charette Auto-Submit: Gabriel Charette Reviewed-by: oysteine Reviewed-by: François Doray Cr-Commit-Position: refs/heads/master@{#760262} --- base/message_loop/message_pump_win.cc | 48 +++++++++++++++---- .../public/cpp/trace_event_args_whitelist.cc | 4 ++ 2 files changed, 42 insertions(+), 10 deletions(-) diff --git a/base/message_loop/message_pump_win.cc b/base/message_loop/message_pump_win.cc index e7405913d4b550..7b43ea45c6324f 100644 --- a/base/message_loop/message_pump_win.cc +++ b/base/message_loop/message_pump_win.cc @@ -278,12 +278,20 @@ void MessagePumpForUI::WaitForWork(Delegate::NextWorkInfo next_work_info) { // some time to process its input messages by looping back to // MsgWaitForMultipleObjectsEx above when there are no messages for the // current thread. - MSG msg = {0}; - bool has_pending_sent_message = - (HIWORD(::GetQueueStatus(QS_SENDMESSAGE)) & QS_SENDMESSAGE) != 0; - if (has_pending_sent_message || - ::PeekMessage(&msg, nullptr, 0, 0, PM_NOREMOVE)) { - return; + + { + // Trace as in ProcessNextWindowsMessage(). + TRACE_EVENT0("base", "MessagePumpForUI::WaitForWork GetQueueStatus"); + if (HIWORD(::GetQueueStatus(QS_SENDMESSAGE)) & QS_SENDMESSAGE) + return; + } + + { + MSG msg = {0}; + // Trace as in ProcessNextWindowsMessage(). + TRACE_EVENT0("base", "MessagePumpForUI::WaitForWork PeekMessage"); + if (::PeekMessage(&msg, nullptr, 0, 0, PM_NOREMOVE)) + return; } // We know there are no more messages for this thread because PeekMessage @@ -437,12 +445,32 @@ bool MessagePumpForUI::ProcessNextWindowsMessage() { // case to ensure that the message loop peeks again instead of calling // MsgWaitForMultipleObjectsEx. bool sent_messages_in_queue = false; - DWORD queue_status = ::GetQueueStatus(QS_SENDMESSAGE); - if (HIWORD(queue_status) & QS_SENDMESSAGE) - sent_messages_in_queue = true; + { + // Individually trace ::GetQueueStatus and ::PeekMessage because sampling + // profiler is hinting that we're spending a surprising amount of time with + // these on top of the stack. Tracing will be able to tell us whether this + // is a bias of sampling profiler (e.g. kernel takes ::GetQueueStatus as an + // opportunity to swap threads and is more likely to schedule the sampling + // profiler's thread while the sampled thread is swapped out on this frame). + TRACE_EVENT0("base", + "MessagePumpForUI::ProcessNextWindowsMessage GetQueueStatus"); + DWORD queue_status = ::GetQueueStatus(QS_SENDMESSAGE); + if (HIWORD(queue_status) & QS_SENDMESSAGE) + sent_messages_in_queue = true; + } MSG msg; - if (::PeekMessage(&msg, nullptr, 0, 0, PM_REMOVE) != FALSE) + bool has_msg = false; + { + // PeekMessage can run a message if |sent_messages_in_queue|, trace that and + // emit the boolean param to see if it ever janks independently (ref. + // comment on GetQueueStatus). + TRACE_EVENT1("base", + "MessagePumpForUI::ProcessNextWindowsMessage PeekMessage", + "sent_messages_in_queue", sent_messages_in_queue); + has_msg = ::PeekMessage(&msg, nullptr, 0, 0, PM_REMOVE) != FALSE; + } + if (has_msg) return ProcessMessageHelper(msg); return sent_messages_in_queue; diff --git a/services/tracing/public/cpp/trace_event_args_whitelist.cc b/services/tracing/public/cpp/trace_event_args_whitelist.cc index 380f3356d56efe..8ef4b633acdcc2 100644 --- a/services/tracing/public/cpp/trace_event_args_whitelist.cc +++ b/services/tracing/public/cpp/trace_event_args_whitelist.cc @@ -26,6 +26,8 @@ struct WhitelistEntry { const char* const kScopedBlockingCallAllowedArgs[] = {"file_name", "function_name", nullptr}; +const char* const kPeekMessageAllowedArgs[] = {"sent_messages_in_queue", + nullptr}; const char* const kFallbackFontAllowedArgs[] = {"font_name", "primary_font_name", nullptr}; const char* const kGetFallbackFontsAllowedArgs[] = {"script", nullptr}; @@ -52,6 +54,8 @@ const WhitelistEntry kEventArgsWhitelist[] = { {"__metadata", "chrome_library_module", nullptr}, {"__metadata", "stackFrames", nullptr}, {"__metadata", "typeNames", nullptr}, + {"base", "MessagePumpForUI::ProcessNextWindowsMessage PeekMessage", + kPeekMessageAllowedArgs}, {"base", "MultiSourceMemoryPressureMonitor::OnMemoryPressureLevelChanged", kMemoryPressureEventsAllowedArgs}, {"base", "ScopedAllowBaseSyncPrimitivesOutsideBlockingScope",