[base] Add trace events for ::GetQueueStatus and ::PeekMessage in the…

… Win pump.

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 <gab@chromium.org>
Auto-Submit: Gabriel Charette <gab@chromium.org>
Reviewed-by: oysteine <oysteine@chromium.org>
Reviewed-by: François Doray <fdoray@chromium.org>
Cr-Commit-Position: refs/heads/master@{#760262}

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;

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",