Bug 1841871: Rename PrintEvent to NativeEventLogger and add profiler markers r=gstoll

Differential Revision: https://phabricator.services.mozilla.com/D182818

widget/windows/nsWindow.cpp

@@ -5006,108 +5006,8 @@ LRESULT CALLBACK nsWindow::WindowProc(HWND hWnd, UINT msg, WPARAM wParam,
                                                wParam, lParam);
 }
 
-namespace geckoprofiler::markers {
-
-struct WindowProcMarker {
-  static constexpr Span<const char> MarkerTypeName() {
-    return MakeStringSpan("WindowProc");
-  }
-  static void StreamJSONMarkerData(baseprofiler::SpliceableJSONWriter& aWriter,
-                                   UINT aMsg, WPARAM aWParam, LPARAM aLParam) {
-    aWriter.IntProperty("uMsg", aMsg);
-    const char* name;
-    if (aMsg < WM_USER) {
-      const auto eventMsgInfo = mozilla::widget::gAllEvents.find(aMsg);
-      if (eventMsgInfo != mozilla::widget::gAllEvents.end()) {
-        name = eventMsgInfo->second.mStr;
-      } else {
-        name = "ui message";
-      }
-    } else if (aMsg >= WM_USER && aMsg < WM_APP) {
-      name = "WM_USER message";
-    } else if (aMsg >= WM_APP && aMsg < 0xC000) {
-      name = "WM_APP message";
-    } else if (aMsg >= 0xC000 && aMsg < 0x10000) {
-      name = "registered windows message";
-    } else {
-      name = "system message";
-    }
-    aWriter.StringProperty("name", MakeStringSpan(name));
-
-    if (aWParam) {
-      aWriter.IntProperty("wParam", aWParam);
-    }
-    if (aLParam) {
-      aWriter.IntProperty("lParam", aLParam);
-    }
-  }
-
-  static MarkerSchema MarkerTypeDisplay() {
-    using MS = MarkerSchema;
-    MS schema{MS::Location::MarkerChart, MS::Location::MarkerTable};
-    schema.AddKeyFormat("uMsg", MS::Format::Integer);
-    schema.SetChartLabel("{marker.data.name} ({marker.data.uMsg})");
-    schema.SetTableLabel(
-        "{marker.name} - {marker.data.name} ({marker.data.uMsg})");
-    schema.SetTooltipLabel("{marker.name} - {marker.data.name}");
-    schema.AddKeyFormat("wParam", MS::Format::Integer);
-    schema.AddKeyFormat("lParam", MS::Format::Integer);
-    return schema;
-  }
-};
-
-}  // namespace geckoprofiler::markers
-
-class MOZ_RAII AutoProfilerMessageMarker {
- public:
-  explicit AutoProfilerMessageMarker(HWND hWnd, UINT msg, WPARAM wParam,
-                                     LPARAM lParam)
-      : mMsg(msg), mWParam(wParam), mLParam(lParam) {
-    if (profiler_thread_is_being_profiled_for_markers()) {
-      mOptions.emplace(MarkerOptions(MarkerTiming::IntervalStart()));
-      nsWindow* win = WinUtils::GetNSWindowPtr(hWnd);
-      if (win) {
-        nsIWidgetListener* wl = win->GetWidgetListener();
-        if (wl) {
-          PresShell* presShell = wl->GetPresShell();
-          if (presShell) {
-            Document* doc = presShell->GetDocument();
-            if (doc) {
-              mOptions->Set(MarkerInnerWindowId(doc->InnerWindowID()));
-            }
-          }
-        }
-      }
-    }
-  }
-
-  ~AutoProfilerMessageMarker() {
-    if (!profiler_thread_is_being_profiled_for_markers()) {
-      return;
-    }
-
-    if (mOptions) {
-      mOptions->TimingRef().SetIntervalEnd();
-    } else {
-      mOptions.emplace(MarkerOptions(MarkerTiming::IntervalEnd()));
-    }
-    profiler_add_marker("WindowProc", ::mozilla::baseprofiler::category::OTHER,
-                        std::move(*mOptions),
-                        geckoprofiler::markers::WindowProcMarker{}, mMsg,
-                        mWParam, mLParam);
-  }
-
- protected:
-  Maybe<MarkerOptions> mOptions;
-  UINT mMsg;
-  WPARAM mWParam;
-  LPARAM mLParam;
-};
-
 LRESULT CALLBACK nsWindow::WindowProcInternal(HWND hWnd, UINT msg,
                                               WPARAM wParam, LPARAM lParam) {
-  AutoProfilerMessageMarker marker(hWnd, msg, wParam, lParam);
-
   if (::GetWindowLongPtrW(hWnd, GWLP_ID) == eFakeTrackPointScrollableID) {
     // This message was sent to the FAKETRACKPOINTSCROLLABLE.
     if (msg == WM_HSCROLL) {
@@ -5196,9 +5096,9 @@ bool nsWindow::ProcessMessage(UINT msg, WPARAM& wParam, LPARAM& lParam,
                               LRESULT* aRetValue) {
   // For some events we might change the parameter values, so log
   // before and after we process them.
-  PrintEvent printEvent(mWnd, msg, wParam, lParam);
+  NativeEventLogger eventLogger("nsWindow", mWnd, msg, wParam, lParam);
   bool result = ProcessMessageInternal(msg, wParam, lParam, aRetValue);
-  printEvent.SetResult(*aRetValue, result);
+  eventLogger.SetResult(*aRetValue, result);
 
   return result;
 }

widget/windows/nsWindowDbg.cpp

@@ -13,6 +13,11 @@
 #include "nsWindowLoggedMessages.h"
 #include "mozilla/Logging.h"
 #include "mozilla/Maybe.h"
+#include "nsWindow.h"
+#include "GeckoProfiler.h"
+#include "mozilla/PresShell.h"
+#include "mozilla/dom/Document.h"
+
 #include <winuser.h>
 #include <dbt.h>
 #include <imm.h>
@@ -35,8 +40,104 @@ MSGFEventMsgInfo gMSGFEvents[] = {
 static long gEventCounter = 0;
 static UINT gLastEventMsg = 0;
 
+namespace geckoprofiler::markers {
+
+struct WindowProcMarker {
+  static constexpr Span<const char> MarkerTypeName() {
+    return MakeStringSpan("WindowProc");
+  }
+  static void StreamJSONMarkerData(baseprofiler::SpliceableJSONWriter& aWriter,
+                                   const ProfilerString8View& aMsgLoopName,
+                                   UINT aMsg, WPARAM aWParam, LPARAM aLParam) {
+    aWriter.StringProperty("messageLoop", aMsgLoopName);
+    aWriter.IntProperty("uMsg", aMsg);
+    const char* name;
+    if (aMsg < WM_USER) {
+      const auto eventMsgInfo = mozilla::widget::gAllEvents.find(aMsg);
+      if (eventMsgInfo != mozilla::widget::gAllEvents.end()) {
+        name = eventMsgInfo->second.mStr;
+      } else {
+        name = "ui message";
+      }
+    } else if (aMsg >= WM_USER && aMsg < WM_APP) {
+      name = "WM_USER message";
+    } else if (aMsg >= WM_APP && aMsg < 0xC000) {
+      name = "WM_APP message";
+    } else if (aMsg >= 0xC000 && aMsg < 0x10000) {
+      name = "registered windows message";
+    } else {
+      name = "system message";
+    }
+    aWriter.StringProperty("name", MakeStringSpan(name));
+
+    if (aWParam) {
+      aWriter.IntProperty("wParam", aWParam);
+    }
+    if (aLParam) {
+      aWriter.IntProperty("lParam", aLParam);
+    }
+  }
+
+  static MarkerSchema MarkerTypeDisplay() {
+    using MS = MarkerSchema;
+    MS schema{MS::Location::MarkerChart, MS::Location::MarkerTable};
+    schema.AddKeyFormat("uMsg", MS::Format::Integer);
+    schema.SetChartLabel(
+        "{marker.data.messageLoop} | {marker.data.name} ({marker.data.uMsg})");
+    schema.SetTableLabel(
+        "{marker.name} - {marker.data.messageLoop} - {marker.data.name} "
+        "({marker.data.uMsg})");
+    schema.SetTooltipLabel(
+        "{marker.data.messageLoop} - {marker.name} - {marker.data.name}");
+    schema.AddKeyFormat("wParam", MS::Format::Integer);
+    schema.AddKeyFormat("lParam", MS::Format::Integer);
+    return schema;
+  }
+};
+
+}  // namespace geckoprofiler::markers
+
 namespace mozilla::widget {
 
+AutoProfilerMessageMarker::AutoProfilerMessageMarker(
+    Span<const char> aMsgLoopName, HWND hWnd, UINT msg, WPARAM wParam,
+    LPARAM lParam)
+    : mMsgLoopName(aMsgLoopName), mMsg(msg), mWParam(wParam), mLParam(lParam) {
+  if (profiler_thread_is_being_profiled_for_markers()) {
+    mOptions.emplace(MarkerOptions(MarkerTiming::IntervalStart()));
+    nsWindow* win = WinUtils::GetNSWindowPtr(hWnd);
+    if (win) {
+      nsIWidgetListener* wl = win->GetWidgetListener();
+      if (wl) {
+        PresShell* presShell = wl->GetPresShell();
+        if (presShell) {
+          dom::Document* doc = presShell->GetDocument();
+          if (doc) {
+            mOptions->Set(MarkerInnerWindowId(doc->InnerWindowID()));
+          }
+        }
+      }
+    }
+  }
+}
+
+AutoProfilerMessageMarker::~AutoProfilerMessageMarker() {
+  if (!profiler_thread_is_being_profiled_for_markers()) {
+    return;
+  }
+
+  if (mOptions) {
+    mOptions->TimingRef().SetIntervalEnd();
+  } else {
+    mOptions.emplace(MarkerOptions(MarkerTiming::IntervalEnd()));
+  }
+  profiler_add_marker(
+      "WindowProc", ::mozilla::baseprofiler::category::OTHER,
+      std::move(*mOptions), geckoprofiler::markers::WindowProcMarker{},
+      ProfilerString8View::WrapNullTerminatedString(mMsgLoopName.data()), mMsg,
+      mWParam, mLParam);
+}
+
 // Using an unordered_set so we can initialize this with nice syntax instead of
 // having to add them one at a time to a mozilla::HashSet.
 std::unordered_set<UINT> gEventsToLogOriginalParams = {
@@ -65,25 +166,28 @@ std::unordered_set<UINT> gEventsToRecordInAboutPage = {
     WM_GETMINMAXINFO,
 };
 
-PrintEvent::PrintEvent(HWND hwnd, UINT msg, WPARAM wParam, LPARAM lParam)
-    : mHwnd(hwnd),
+NativeEventLogger::NativeEventLogger(Span<const char> aMsgLoopName, HWND hwnd,
+                                     UINT msg, WPARAM wParam, LPARAM lParam)
+    : mProfilerMarker(aMsgLoopName, hwnd, msg, wParam, lParam),
+      mMsgLoopName(aMsgLoopName.data()),
+      mHwnd(hwnd),
       mMsg(msg),
       mWParam(wParam),
       mLParam(lParam),
       mResult(mozilla::Nothing()),
       mShouldLogPostCall(false) {
-  if (PrintEventInternal()) {
+  if (NativeEventLoggerInternal()) {
     // this event was logged, so reserve this counter number for the post-call
     mEventCounter = mozilla::Some(gEventCounter);
     ++gEventCounter;
   }
 }
 
-PrintEvent::~PrintEvent() {
+NativeEventLogger::~NativeEventLogger() {
   // If mResult is Nothing, perhaps an exception was thrown or something
   // before SetResult() was supposed to be called.
   if (mResult.isSome()) {
-    if (PrintEventInternal() && mEventCounter.isNothing()) {
+    if (NativeEventLoggerInternal() && mEventCounter.isNothing()) {
       // We didn't reserve a counter in the pre-call, so reserve it here.
       ++gEventCounter;
     }
@@ -174,7 +278,7 @@ bool AppendFlagsInfo(nsCString& str, uint64_t flags,
 // handling the message (for example WM_GETTEXT and WM_NCCALCSIZE)
 // Returns whether this message was logged, so we need to reserve a
 // counter number for it.
-bool PrintEvent::PrintEventInternal() {
+bool NativeEventLogger::NativeEventLoggerInternal() {
   mozilla::LogLevel const targetLogLevel = [&] {
     // These messages often take up more than 90% of logs if not filtered out.
     if (mMsg == WM_SETCURSOR || mMsg == WM_MOUSEMOVE || mMsg == WM_NCHITTEST) {
@@ -232,8 +336,8 @@ bool PrintEvent::PrintEventInternal() {
                                   : "initial call";
       nsAutoCString logMessage;
       logMessage.AppendPrintf(
-          "%6ld %08" PRIX64 " - 0x%04X %s%s%s: 0x%08" PRIX64 " (%s)\n",
-          mEventCounter.valueOr(gEventCounter),
+          "%s | %6ld %08" PRIX64 " - 0x%04X %s%s%s: 0x%08" PRIX64 " (%s)\n",
+          mMsgLoopName, mEventCounter.valueOr(gEventCounter),
           reinterpret_cast<uint64_t>(mHwnd), mMsg,
           msgText ? msgText : "Unknown", paramInfo.IsEmpty() ? "" : " ",
           paramInfo.get(),
@@ -1032,32 +1136,26 @@ void ResolutionParamInfo(nsCString& result, uint64_t value, const char* name,
 }
 
 // Window message with default wParam/lParam logging
-#define ENTRY(_msg)                 \
-  {                                 \
-    _msg, {                         \
-#      _msg, _msg, DefaultParamInfo \
-    }                               \
+#define ENTRY(_msg)                         \
+  {                                         \
+    _msg, { #_msg, _msg, DefaultParamInfo } \
   }
 // Window message with no parameters
 #define ENTRY_WITH_NO_PARAM_INFO(_msg) \
   {                                    \
-    _msg, {                            \
-#      _msg, _msg, nullptr             \
-    }                                  \
+    _msg, { #_msg, _msg, nullptr }     \
   }
 // Window message with custom parameter logging functions
 #define ENTRY_WITH_CUSTOM_PARAM_INFO(_msg, paramInfoFn) \
   {                                                     \
-    _msg, {                                             \
-#      _msg, _msg, paramInfoFn                          \
-    }                                                   \
+    _msg, { #_msg, _msg, paramInfoFn }                  \
   }
 // Window message with separate custom wParam and lParam logging functions
 #define ENTRY_WITH_SPLIT_PARAM_INFOS(_msg, wParamInfoFn, wParamName,           \
                                      lParamInfoFn, lParamName)                 \
   {                                                                            \
     _msg, {                                                                    \
-#      _msg, _msg, nullptr, wParamInfoFn, wParamName, lParamInfoFn, lParamName \
+      #_msg, _msg, nullptr, wParamInfoFn, wParamName, lParamInfoFn, lParamName \
     }                                                                          \
   }
 std::unordered_map<UINT, EventMsgInfo> gAllEvents = {

widget/windows/nsWindowDbg.h

@@ -11,6 +11,7 @@
  */
 
 #include "nsWindowDefs.h"
+#include "mozilla/BaseProfilerMarkersPrerequisites.h"
 
 // Enables debug output for popup rollup hooks
 // #define POPUP_ROLLUP_DEBUG_OUTPUT
@@ -26,6 +27,22 @@
 // #define DEBUG_VK
 
 namespace mozilla::widget {
+
+class MOZ_RAII AutoProfilerMessageMarker {
+ public:
+  explicit AutoProfilerMessageMarker(Span<const char> aMsgLoopName, HWND hWnd,
+                                     UINT msg, WPARAM wParam, LPARAM lParam);
+
+  ~AutoProfilerMessageMarker();
+
+ protected:
+  Maybe<MarkerOptions> mOptions;
+  Span<const char> mMsgLoopName;
+  UINT mMsg;
+  WPARAM mWParam;
+  LPARAM mLParam;
+};
+
 // Windows message debugging data
 struct EventMsgInfo {
   const char* mStr;
@@ -41,18 +58,26 @@ struct EventMsgInfo {
 extern std::unordered_map<UINT, EventMsgInfo> gAllEvents;
 
 // RAII-style class to log before and after an event is handled.
-class PrintEvent final {
+class NativeEventLogger final {
  public:
-  PrintEvent(HWND hwnd, UINT msg, WPARAM wParam, LPARAM lParam);
+  template <size_t N>
+  NativeEventLogger(const char (&aMsgLoopName)[N], HWND hwnd, UINT msg,
+                    WPARAM wParam, LPARAM lParam)
+      : NativeEventLogger(Span(aMsgLoopName), hwnd, msg, wParam, lParam) {}
+
   void SetResult(LRESULT lresult, bool result) {
     mRetValue = lresult;
     mResult = mozilla::Some(result);
   }
-  ~PrintEvent();
+  ~NativeEventLogger();
 
  private:
-  bool PrintEventInternal();
+  NativeEventLogger(Span<const char> aMsgLoopName, HWND hwnd, UINT msg,
+                    WPARAM wParam, LPARAM lParam);
+  bool NativeEventLoggerInternal();
 
+  AutoProfilerMessageMarker mProfilerMarker;
+  const char* mMsgLoopName;
   const HWND mHwnd;
   const UINT mMsg;
   const WPARAM mWParam;