From 9888b499f51fbdb899df011091d3af7ed5de7b86 Mon Sep 17 00:00:00 2001 From: Alex Hunt Date: Thu, 12 Dec 2024 04:40:43 -0800 Subject: [PATCH] Add support for Performance.mark events in PerformanceTracer (#48200) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Summary: Pull Request resolved: https://github.com/facebook/react-native/pull/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 --- .../tracing/PerformanceTracer.cpp | 123 +++++++++++++----- .../tracing/PerformanceTracer.h | 29 ++++- .../timeline/PerformanceEntryReporter.cpp | 17 ++- 3 files changed, 128 insertions(+), 41 deletions(-) diff --git a/packages/react-native/ReactCommon/jsinspector-modern/tracing/PerformanceTracer.cpp b/packages/react-native/ReactCommon/jsinspector-modern/tracing/PerformanceTracer.cpp index b0ac60c025f..8bddc62df1b 100644 --- a/packages/react-native/ReactCommon/jsinspector-modern/tracing/PerformanceTracer.cpp +++ b/packages/react-native/ReactCommon/jsinspector-modern/tracing/PerformanceTracer.cpp @@ -10,7 +10,7 @@ #include #include -#include +#include 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)); + traceEvents.push_back( + folly::dynamic::object("args", folly::dynamic::object("name", "Timings"))( + "cat", "__metadata")("name", "thread_name")("ph", "M")("pid", PID)( + "tid", USER_TIMINGS_DEFAULT_TRACK)("ts", 0)); - auto savedBuffer = std::move(buffer_); - buffer_.clear(); - std::unordered_map trackIdMap; - uint64_t nextTrack = 1001; + auto customTrackIdMap = getCustomTracks(savedBuffer); + for (const auto& [trackName, trackId] : customTrackIdMap) { + // Register custom tracks + traceEvents.push_back(folly::dynamic::object( + "args", folly::dynamic::object("name", trackName))("cat", "__metadata")( + "name", "thread_name")("ph", "M")("pid", PID)("tid", trackId)("ts", 0)); + } 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))( - "cat", "__metadata")("name", "thread_name")("ph", "M")("pid", PID)( - "tid", trackId)("ts", 0)); - } - - auto trackId = - trackIdMap.contains(event.track) ? trackIdMap[event.track] : 1000; - - // Emit "blink.user_timing" trace event - 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)); + // 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, - uint64_t end, - const std::optional& trackMetadata) { + uint64_t start) { std::lock_guard 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 duration, + const std::optional& trackMetadata) { + std::lock_guard lock(mutex_); + if (!tracing_) { + return; + } + + std::optional 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 PerformanceTracer::getCustomTracks( + std::vector& events) { + std::unordered_map 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& 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 diff --git a/packages/react-native/ReactCommon/jsinspector-modern/tracing/PerformanceTracer.h b/packages/react-native/ReactCommon/jsinspector-modern/tracing/PerformanceTracer.h index 804a6f22c93..f7b9e1e17e5 100644 --- a/packages/react-native/ReactCommon/jsinspector-modern/tracing/PerformanceTracer.h +++ b/packages/react-native/ReactCommon/jsinspector-modern/tracing/PerformanceTracer.h @@ -13,6 +13,7 @@ #include #include +#include #include 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 track; }; /** @@ -55,13 +56,25 @@ class PerformanceTracer { bool stopTracingAndCollectEvents( const std::function& 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& trackMetadata); private: @@ -70,6 +83,12 @@ class PerformanceTracer { PerformanceTracer& operator=(const PerformanceTracer&) = delete; ~PerformanceTracer() = default; + std::unordered_map getCustomTracks( + std::vector& events); + folly::dynamic serializeTraceEvent( + TraceEvent& event, + std::unordered_map& customTrackIdMap) const; + bool tracing_{false}; std::vector buffer_; std::mutex mutex_; diff --git a/packages/react-native/ReactCommon/react/performance/timeline/PerformanceEntryReporter.cpp b/packages/react-native/ReactCommon/react/performance/timeline/PerformanceEntryReporter.cpp index 5114f529ed0..36c947cda77 100644 --- a/packages/react-native/ReactCommon/react/performance/timeline/PerformanceEntryReporter.cpp +++ b/packages/react-native/ReactCommon/react/performance/timeline/PerformanceEntryReporter.cpp @@ -14,6 +14,7 @@ namespace facebook::react { namespace { + std::vector getSupportedEntryTypesInternal() { std::vector supportedEntryTypes{ PerformanceEntryType::MARK, @@ -27,6 +28,11 @@ std::vector getSupportedEntryTypesInternal() { return supportedEntryTypes; } + +uint64_t timestampToMicroseconds(DOMHighResTimeStamp timestamp) { + return static_cast(timestamp * 1000); +} + } // namespace std::shared_ptr& @@ -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;