Add support for Performance.mark events in PerformanceTracer (#48200)

Summary:
Pull Request resolved: #48200

Wires up `Performance.mark()` events, completing support for User Timings in Fusebox.

Other changes:

- Refactors `reportMeasure` to receive a `duration`.
- Fixes conversion for time values (ms -> µs) in emitted trace events.

Changelog: [Internal]

Reviewed By: hoxyq

Differential Revision: D66704283

fbshipit-source-id: 352abbade26eb976e793481dde04463431bf2eb7

packages/react-native/ReactCommon/jsinspector-modern/tracing/PerformanceTracer.cpp

@@ -10,7 +10,7 @@
 #include <folly/json.h>
 
 #include <mutex>
-#include <unordered_map>
+#include <unordered_set>
 
 namespace facebook::react::jsinspector_modern {
 
@@ -19,6 +19,9 @@ namespace {
 /** Process ID for all emitted events. */
 const uint64_t PID = 1000;
 
+/** Default/starting track ID for the "Timings" track. */
+const uint64_t USER_TIMINGS_DEFAULT_TRACK = 1000;
+
 } // namespace
 
 PerformanceTracer& PerformanceTracer::getInstance() {
@@ -50,6 +53,8 @@ bool PerformanceTracer::stopTracingAndCollectEvents(
   }
 
   auto traceEvents = folly::dynamic::array();
+  auto savedBuffer = std::move(buffer_);
+  buffer_.clear();
 
   // Register "Main" process
   traceEvents.push_back(folly::dynamic::object(
@@ -59,34 +64,22 @@ bool PerformanceTracer::stopTracingAndCollectEvents(
   // NOTE: This is a hack to make the trace viewer show a "Timings" track
   // adjacent to custom tracks in our current build of Chrome DevTools.
   // In future, we should align events exactly.
-  traceEvents.push_back(folly::dynamic::object(
-      "args", folly::dynamic::object("name", "Timings"))("cat", "__metadata")(
-      "name", "thread_name")("ph", "M")("pid", PID)("tid", 1000)("ts", 0));
-
-  auto savedBuffer = std::move(buffer_);
-  buffer_.clear();
-  std::unordered_map<std::string, uint64_t> trackIdMap;
-  uint64_t nextTrack = 1001;
-
-  for (auto& event : savedBuffer) {
-    // For events with a custom track name, register track
-    if (event.track.length() && !trackIdMap.contains(event.track)) {
-      auto trackId = nextTrack++;
-      trackIdMap[event.track] = trackId;
-      traceEvents.push_back(folly::dynamic::object(
-          "args", folly::dynamic::object("name", event.track))(
+  traceEvents.push_back(
+      folly::dynamic::object("args", folly::dynamic::object("name", "Timings"))(
           "cat", "__metadata")("name", "thread_name")("ph", "M")("pid", PID)(
-          "tid", trackId)("ts", 0));
-    }
-
-    auto trackId =
-        trackIdMap.contains(event.track) ? trackIdMap[event.track] : 1000;
+          "tid", USER_TIMINGS_DEFAULT_TRACK)("ts", 0));
 
-    // Emit "blink.user_timing" trace event
+  auto customTrackIdMap = getCustomTracks(savedBuffer);
+  for (const auto& [trackName, trackId] : customTrackIdMap) {
+    // Register custom tracks
     traceEvents.push_back(folly::dynamic::object(
-        "args", folly::dynamic::object())("cat", "blink.user_timing")(
-        "dur", (event.end - event.start) * 1000)("name", event.name)("ph", "X")(
-        "ts", event.start * 1000)("pid", PID)("tid", trackId));
+        "args", folly::dynamic::object("name", trackName))("cat", "__metadata")(
+        "name", "thread_name")("ph", "M")("pid", PID)("tid", trackId)("ts", 0));
+  }
+
+  for (auto& event : savedBuffer) {
+    // Emit trace events
+    traceEvents.push_back(serializeTraceEvent(event, customTrackIdMap));
 
     if (traceEvents.size() >= 1000) {
       resultCallback(traceEvents);
@@ -100,22 +93,86 @@ bool PerformanceTracer::stopTracingAndCollectEvents(
   return true;
 }
 
-void PerformanceTracer::addEvent(
+void PerformanceTracer::reportMark(
+    const std::string_view& name,
+    uint64_t start) {
+  std::lock_guard<std::mutex> lock(mutex_);
+  if (!tracing_) {
+    return;
+  }
+  buffer_.push_back(TraceEvent{
+      .type = TraceEventType::MARK, .name = std::string(name), .start = start});
+}
+
+void PerformanceTracer::reportMeasure(
     const std::string_view& name,
     uint64_t start,
-    uint64_t end,
+    uint64_t duration,
     const std::optional<DevToolsTrackEntryPayload>& trackMetadata) {
   std::lock_guard<std::mutex> lock(mutex_);
   if (!tracing_) {
     return;
   }
+
+  std::optional<std::string> track;
+  if (trackMetadata.has_value()) {
+    track = trackMetadata.value().track;
+  }
+
   buffer_.push_back(TraceEvent{
       .type = TraceEventType::MEASURE,
       .name = std::string(name),
       .start = start,
-      .end = end,
-      .track = trackMetadata.value_or(DevToolsTrackEntryPayload{.track = ""})
-                   .track});
+      .duration = duration,
+      .track = track});
+}
+
+std::unordered_map<std::string, uint32_t> PerformanceTracer::getCustomTracks(
+    std::vector<TraceEvent>& events) {
+  std::unordered_map<std::string, uint32_t> trackIdMap;
+
+  uint32_t nextTrack = USER_TIMINGS_DEFAULT_TRACK + 1;
+  for (auto& event : events) {
+    // Custom tracks are only supported by User Timing "measure" events
+    if (event.type != TraceEventType::MEASURE) {
+      continue;
+    }
+
+    if (event.track.has_value() && !trackIdMap.contains(event.track.value())) {
+      auto trackId = nextTrack++;
+      trackIdMap[event.track.value()] = trackId;
+    }
+  }
+
+  return trackIdMap;
+}
+
+folly::dynamic PerformanceTracer::serializeTraceEvent(
+    TraceEvent& event,
+    std::unordered_map<std::string, uint32_t>& customTrackIdMap) const {
+  folly::dynamic result = folly::dynamic::object;
+
+  result["args"] = folly::dynamic::object();
+  result["cat"] = "blink.user_timing";
+  result["name"] = event.name;
+  result["pid"] = PID;
+  result["ts"] = event.start;
+
+  switch (event.type) {
+    case TraceEventType::MARK:
+      result["ph"] = "I";
+      result["tid"] = USER_TIMINGS_DEFAULT_TRACK;
+      break;
+    case TraceEventType::MEASURE:
+      result["dur"] = event.duration;
+      result["ph"] = "X";
+      result["tid"] = event.track.has_value()
+          ? customTrackIdMap[event.track.value()]
+          : USER_TIMINGS_DEFAULT_TRACK;
+      break;
+  }
+
+  return result;
 }
 
 } // namespace facebook::react::jsinspector_modern

packages/react-native/ReactCommon/jsinspector-modern/tracing/PerformanceTracer.h

@@ -13,6 +13,7 @@
 
 #include <functional>
 #include <optional>
+#include <unordered_map>
 #include <vector>
 
 namespace facebook::react::jsinspector_modern {
@@ -29,8 +30,8 @@ struct TraceEvent {
   TraceEventType type;
   std::string name;
   uint64_t start;
-  uint64_t end;
-  std::string track;
+  uint64_t duration = 0;
+  std::optional<std::string> track;
 };
 
 /**
@@ -55,13 +56,25 @@ class PerformanceTracer {
   bool stopTracingAndCollectEvents(
       const std::function<void(const folly::dynamic& eventsChunk)>&
           resultCallback);
+
   /**
-   * Record a new trace event. If not currently tracing, this is a no-op.
+   * Record a `Performance.mark()` event - a labelled timestamp. If not
+   * currently tracing, this is a no-op.
+   *
+   * See https://w3c.github.io/user-timing/#mark-method.
    */
-  void addEvent(
+  void reportMark(const std::string_view& name, uint64_t start);
+
+  /**
+   * Record a `Performance.measure()` event - a labelled duration. If not
+   * currently tracing, this is a no-op.
+   *
+   * See https://w3c.github.io/user-timing/#measure-method.
+   */
+  void reportMeasure(
       const std::string_view& name,
       uint64_t start,
-      uint64_t end,
+      uint64_t duration,
       const std::optional<DevToolsTrackEntryPayload>& trackMetadata);
 
  private:
@@ -70,6 +83,12 @@ class PerformanceTracer {
   PerformanceTracer& operator=(const PerformanceTracer&) = delete;
   ~PerformanceTracer() = default;
 
+  std::unordered_map<std::string, uint32_t> getCustomTracks(
+      std::vector<TraceEvent>& events);
+  folly::dynamic serializeTraceEvent(
+      TraceEvent& event,
+      std::unordered_map<std::string, uint32_t>& customTrackIdMap) const;
+
   bool tracing_{false};
   std::vector<TraceEvent> buffer_;
   std::mutex mutex_;

packages/react-native/ReactCommon/react/performance/timeline/PerformanceEntryReporter.cpp

@@ -14,6 +14,7 @@
 namespace facebook::react {
 
 namespace {
+
 std::vector<PerformanceEntryType> getSupportedEntryTypesInternal() {
   std::vector<PerformanceEntryType> supportedEntryTypes{
       PerformanceEntryType::MARK,
@@ -27,6 +28,11 @@ std::vector<PerformanceEntryType> getSupportedEntryTypesInternal() {
 
   return supportedEntryTypes;
 }
+
+uint64_t timestampToMicroseconds(DOMHighResTimeStamp timestamp) {
+  return static_cast<uint64_t>(timestamp * 1000);
+}
+
 } // namespace
 
 std::shared_ptr<PerformanceEntryReporter>&
@@ -140,7 +146,9 @@ PerformanceEntry PerformanceEntryReporter::reportMark(
     markBuffer_.add(entry);
   }
 
-  // TODO(T198982317): Log `performance.mark()` events to jsinspector_modern
+  jsinspector_modern::PerformanceTracer::getInstance().reportMark(
+      name, timestampToMicroseconds(startTimeVal));
+
   observerRegistry_->queuePerformanceEntry(entry);
   return entry;
 }
@@ -178,8 +186,11 @@ PerformanceEntry PerformanceEntryReporter::reportMeasure(
     measureBuffer_.add(entry);
   }
 
-  jsinspector_modern::PerformanceTracer::getInstance().addEvent(
-      name, startTimeVal, endTimeVal, trackMetadata);
+  jsinspector_modern::PerformanceTracer::getInstance().reportMeasure(
+      name,
+      timestampToMicroseconds(startTimeVal),
+      timestampToMicroseconds(durationVal),
+      trackMetadata);
 
   observerRegistry_->queuePerformanceEntry(entry);
   return entry;