Implement "paint time" support in Event Timing API (facebook#41484)

Summary: ## Changelog: [Internal] - Uses mount hooks to report "paint time" via the Event Timing API - i.e. "duration" now corresponds not the the JS dispatch end point, but to the moment when the corresponding mount ("paint") happened on the native side. This feature is disabled by default for now, but can be enabled via `NativePerformanceObserver.setIsReportingEventPaintTime(true);`. Reviewed By: rubennorte Differential Revision: D51313902
rshest · Nov 15, 2023 · 07d0e5f · 07d0e5f
1 parent 7f52791
commit 07d0e5f
Show file tree

Hide file tree

Showing 7 changed files with 112 additions and 38 deletions.
diff --git a/packages/react-native/Libraries/WebPerformance/NativePerformanceObserver.cpp b/packages/react-native/Libraries/WebPerformance/NativePerformanceObserver.cpp
@@ -10,6 +10,9 @@
 #include "NativePerformanceObserver.h"
 #include "PerformanceEntryReporter.h"
 
+#include <react/renderer/uimanager/UIManagerBinding.h>
+#include <react/utils/CoreFeatures.h>
+
 #include "Plugins.h"
 
 std::shared_ptr<facebook::react::TurboModule>
@@ -34,15 +37,33 @@ NativePerformanceObserver::~NativePerformanceObserver() {
 void NativePerformanceObserver::startReporting(
     jsi::Runtime& rt,
     int32_t entryType) {
-  PerformanceEntryReporter::getInstance().startReporting(
-      static_cast<PerformanceEntryType>(entryType));
+  PerformanceEntryReporter& reporter = PerformanceEntryReporter::getInstance();
+
+  PerformanceEntryType entryTypeEnum =
+      static_cast<PerformanceEntryType>(entryType);
+  reporter.startReporting(entryTypeEnum);
+
+  if (entryTypeEnum == PerformanceEntryType::EVENT &&
+      CoreFeatures::enableReportEventPaintTime) {
+    UIManagerBinding::getBinding(rt)->getUIManager().registerMountHook(
+        reporter);
+  }
 }
 
 void NativePerformanceObserver::stopReporting(
     jsi::Runtime& rt,
     int32_t entryType) {
-  PerformanceEntryReporter::getInstance().stopReporting(
-      static_cast<PerformanceEntryType>(entryType));
+  PerformanceEntryReporter& reporter = PerformanceEntryReporter::getInstance();
+
+  PerformanceEntryType entryTypeEnum =
+      static_cast<PerformanceEntryType>(entryType);
+  reporter.stopReporting(entryTypeEnum);
+
+  if (entryTypeEnum == PerformanceEntryType::EVENT &&
+      CoreFeatures::enableReportEventPaintTime) {
+    UIManagerBinding::getBinding(rt)->getUIManager().unregisterMountHook(
+        reporter);
+  }
 }
 
 void NativePerformanceObserver::setIsBuffered(

diff --git a/packages/react-native/Libraries/WebPerformance/PerformanceEntryReporter.cpp b/packages/react-native/Libraries/WebPerformance/PerformanceEntryReporter.cpp
@@ -8,11 +8,14 @@
 #include "PerformanceEntryReporter.h"
 #include <cxxreact/JSExecutor.h>
 #include <react/renderer/core/EventLogger.h>
+#include <react/utils/CoreFeatures.h>
 #include "NativePerformanceObserver.h"
 
 #include <functional>
 #include <unordered_map>
 
+#include <glog/logging.h>
+
 namespace facebook::react {
 EventTag PerformanceEntryReporter::sCurrentEventTag_{0};
 
@@ -67,7 +70,7 @@ void PerformanceEntryReporter::stopReporting() {
 }
 
 GetPendingEntriesResult PerformanceEntryReporter::popPendingEntries() {
-  std::scoped_lock lock(entriesMutex_);
+  std::lock_guard lock(entriesMutex_);
   GetPendingEntriesResult res = {
       std::vector<RawPerformanceEntry>(), droppedEntryCount_};
   for (auto& buffer : buffers_) {
@@ -100,7 +103,7 @@ void PerformanceEntryReporter::logEntry(const RawPerformanceEntry& entry) {
     return;
   }
 
-  std::scoped_lock lock(entriesMutex_);
+  std::lock_guard lock(entriesMutex_);
 
   auto& buffer = buffers_[entry.entryType];
 
@@ -112,7 +115,7 @@ void PerformanceEntryReporter::logEntry(const RawPerformanceEntry& entry) {
   if (buffer.hasNameLookup) {
     auto overwriteCandidate = buffer.entries.getNextOverwriteCandidate();
     if (overwriteCandidate != nullptr) {
-      std::scoped_lock lock2(nameLookupMutex_);
+      std::lock_guard lock2(nameLookupMutex_);
       auto it = buffer.nameLookup.find(overwriteCandidate);
       if (it != buffer.nameLookup.end() && *it == overwriteCandidate) {
         buffer.nameLookup.erase(it);
@@ -130,7 +133,7 @@ void PerformanceEntryReporter::logEntry(const RawPerformanceEntry& entry) {
   }
 
   if (buffer.hasNameLookup) {
-    std::scoped_lock lock2(nameLookupMutex_);
+    std::lock_guard lock2(nameLookupMutex_);
     buffer.nameLookup.insert(&buffer.entries.back());
   }
 
@@ -166,7 +169,7 @@ void PerformanceEntryReporter::clearEntries(
     auto& buffer = getBuffer(entryType);
     if (!entryName.empty()) {
       if (buffer.hasNameLookup) {
-        std::scoped_lock lock2(nameLookupMutex_);
+        std::lock_guard lock2(nameLookupMutex_);
         RawPerformanceEntry entry{
             std::string(entryName),
             static_cast<int>(entryType),
@@ -178,17 +181,17 @@ void PerformanceEntryReporter::clearEntries(
         buffer.nameLookup.erase(&entry);
       }
 
-      std::scoped_lock lock(entriesMutex_);
+      std::lock_guard lock(entriesMutex_);
       buffer.entries.clear([entryName](const RawPerformanceEntry& entry) {
         return entry.name == entryName;
       });
     } else {
       {
-        std::scoped_lock lock(entriesMutex_);
+        std::lock_guard lock(entriesMutex_);
         buffer.entries.clear();
       }
       {
-        std::scoped_lock lock2(nameLookupMutex_);
+        std::lock_guard lock2(nameLookupMutex_);
         buffer.nameLookup.clear();
       }
     }
@@ -205,7 +208,7 @@ void PerformanceEntryReporter::getEntries(
       getEntries(static_cast<PerformanceEntryType>(i), entryName, res);
     }
   } else {
-    std::scoped_lock lock(entriesMutex_);
+    std::lock_guard lock(entriesMutex_);
     const auto& entries = getBuffer(entryType).entries;
     if (entryName.empty()) {
       entries.getEntries(res);
@@ -264,7 +267,7 @@ double PerformanceEntryReporter::getMarkTime(
       std::nullopt,
       std::nullopt};
 
-  std::scoped_lock lock(nameLookupMutex_);
+  std::lock_guard lock(nameLookupMutex_);
   const auto& marksBuffer = getBuffer(PerformanceEntryType::MARK);
   auto it = marksBuffer.nameLookup.find(&mark);
   if (it != marksBuffer.nameLookup.end()) {
@@ -274,7 +277,7 @@ double PerformanceEntryReporter::getMarkTime(
   }
 }
 
-void PerformanceEntryReporter::event(
+void PerformanceEntryReporter::logEventEntry(
     std::string name,
     double startTime,
     double duration,
@@ -381,53 +384,87 @@ EventTag PerformanceEntryReporter::onEventStart(std::string_view name) {
 
   auto timeStamp = getCurrentTimeStamp();
   {
-    std::scoped_lock lock(eventsInFlightMutex_);
+    std::lock_guard lock(eventsInFlightMutex_);
     eventsInFlight_.emplace(std::make_pair(
         sCurrentEventTag_, EventEntry{reportedName, timeStamp, 0.0}));
   }
   return sCurrentEventTag_;
 }
 
-void PerformanceEntryReporter::onEventDispatch(EventTag tag) {
+void PerformanceEntryReporter::onEventProcessingStart(EventTag tag) {
   if (!isReporting(PerformanceEntryType::EVENT) || tag == 0) {
     return;
   }
   auto timeStamp = getCurrentTimeStamp();
   {
-    std::scoped_lock lock(eventsInFlightMutex_);
+    std::lock_guard lock(eventsInFlightMutex_);
     auto it = eventsInFlight_.find(tag);
     if (it != eventsInFlight_.end()) {
-      it->second.dispatchTime = timeStamp;
+      it->second.processingStartTime = timeStamp;
     }
   }
 }
 
-void PerformanceEntryReporter::onEventEnd(EventTag tag) {
+void PerformanceEntryReporter::onEventProcessingEnd(EventTag tag) {
   if (!isReporting(PerformanceEntryType::EVENT) || tag == 0) {
     return;
   }
   auto timeStamp = getCurrentTimeStamp();
   {
-    std::scoped_lock lock(eventsInFlightMutex_);
+    std::lock_guard lock(eventsInFlightMutex_);
     auto it = eventsInFlight_.find(tag);
     if (it == eventsInFlight_.end()) {
       return;
     }
     auto& entry = it->second;
-    auto& name = entry.name;
+    entry.processingEndTime = timeStamp;
+
+    if (CoreFeatures::enableReportEventPaintTime) {
+      // If reporting paint time, don't send the entry just yet and wait for the
+      // mount hook callback to be called
+      return;
+    }
 
-    // TODO: Define the way to assign interaction IDs to the event chains
-    // (T141358175)
-    const uint32_t interactionId = 0;
-    event(
+    const auto& name = entry.name;
+
+    logEventEntry(
         std::string(name),
         entry.startTime,
         timeStamp - entry.startTime,
-        entry.dispatchTime,
-        timeStamp,
-        interactionId);
+        entry.processingStartTime,
+        entry.processingEndTime,
+        entry.interactionId);
     eventsInFlight_.erase(it);
   }
 }
 
+void PerformanceEntryReporter::shadowTreeDidMount(
+    const RootShadowNode::Shared& /*rootShadowNode*/,
+    double mountTime) noexcept {
+  if (!isReporting(PerformanceEntryType::EVENT) ||
+      !CoreFeatures::enableReportEventPaintTime) {
+    return;
+  }
+
+  std::lock_guard lock(eventsInFlightMutex_);
+  auto it = eventsInFlight_.begin();
+  while (it != eventsInFlight_.end()) {
+    const auto& entry = it->second;
+    if (entry.processingEndTime == 0.0 || entry.processingEndTime > mountTime) {
+      // This mount doesn't correspond to the event
+      ++it;
+      continue;
+    }
+
+    logEventEntry(
+        std::string(entry.name),
+        entry.startTime,
+        mountTime - entry.startTime,
+        entry.processingStartTime,
+        entry.processingEndTime,
+        entry.interactionId);
+    it = eventsInFlight_.erase(it);
+  }
+}
+
 } // namespace facebook::react
diff --git a/packages/react-native/Libraries/WebPerformance/PerformanceEntryReporter.h b/packages/react-native/Libraries/WebPerformance/PerformanceEntryReporter.h
@@ -19,6 +19,8 @@
 #include "BoundedConsumableBuffer.h"
 #include "NativePerformanceObserver.h"
 
+#include <react/renderer/uimanager/UIManagerMountHook.h>
+
 namespace facebook::react {
 
 struct PerformanceEntryHash {
@@ -67,7 +69,7 @@ enum class PerformanceEntryType {
 constexpr size_t NUM_PERFORMANCE_ENTRY_TYPES =
     (size_t)PerformanceEntryType::_COUNT;
 
-class PerformanceEntryReporter : public EventLogger {
+class PerformanceEntryReporter : public EventLogger, public UIManagerMountHook {
  public:
   PerformanceEntryReporter(const PerformanceEntryReporter&) = delete;
   void operator=(const PerformanceEntryReporter&) = delete;
@@ -132,7 +134,7 @@ class PerformanceEntryReporter : public EventLogger {
       PerformanceEntryType entryType = PerformanceEntryType::UNDEFINED,
       std::string_view entryName = {}) const;
 
-  void event(
+  void logEventEntry(
       std::string name,
       double startTime,
       double duration,
@@ -141,8 +143,12 @@ class PerformanceEntryReporter : public EventLogger {
       uint32_t interactionId);
 
   EventTag onEventStart(std::string_view name) override;
-  void onEventDispatch(EventTag tag) override;
-  void onEventEnd(EventTag tag) override;
+  void onEventProcessingStart(EventTag tag) override;
+  void onEventProcessingEnd(EventTag tag) override;
+
+  void shadowTreeDidMount(
+      const RootShadowNode::Shared& rootShadowNode,
+      double mountTime) noexcept override;
 
   const std::unordered_map<std::string, uint32_t>& getEventCounts() const {
     return eventCounts_;
@@ -164,7 +170,12 @@ class PerformanceEntryReporter : public EventLogger {
   struct EventEntry {
     std::string_view name;
     double startTime{0.0};
-    double dispatchTime{0.0};
+    double processingStartTime{0.0};
+    double processingEndTime{0.0};
+
+    // TODO: Define the way to assign interaction IDs to the event chains
+    // (T141358175)
+    uint32_t interactionId{0};
   };
 
   // Registry to store the events that are currently ongoing.

diff --git a/packages/react-native/ReactCommon/react/renderer/core/EventLogger.h b/packages/react-native/ReactCommon/react/renderer/core/EventLogger.h
@@ -32,12 +32,12 @@ class EventLogger {
    * Called when event starts getting dispatched (processed by the handlers, if
    * any)
    */
-  virtual void onEventDispatch(EventTag tag) = 0;
+  virtual void onEventProcessingStart(EventTag tag) = 0;
 
   /*
    * Called when event finishes being dispatched
    */
-  virtual void onEventEnd(EventTag tag) = 0;
+  virtual void onEventProcessingEnd(EventTag tag) = 0;
 };
 
 void setEventLogger(EventLogger* eventLogger);

diff --git a/packages/react-native/ReactCommon/react/renderer/core/EventQueueProcessor.cpp b/packages/react-native/ReactCommon/react/renderer/core/EventQueueProcessor.cpp
@@ -55,7 +55,7 @@ void EventQueueProcessor::flushEvents(
 
     auto eventLogger = getEventLogger();
     if (eventLogger != nullptr) {
-      eventLogger->onEventDispatch(event.loggingTag);
+      eventLogger->onEventProcessingStart(event.loggingTag);
     }
 
     if (event.eventPayload == nullptr) {
@@ -77,7 +77,7 @@ void EventQueueProcessor::flushEvents(
     }
 
     if (eventLogger != nullptr) {
-      eventLogger->onEventEnd(event.loggingTag);
+      eventLogger->onEventProcessingEnd(event.loggingTag);
     }
 
     if (event.category == RawEvent::Category::ContinuousStart) {

diff --git a/packages/react-native/ReactCommon/react/utils/CoreFeatures.cpp b/packages/react-native/ReactCommon/react/utils/CoreFeatures.cpp
@@ -23,5 +23,6 @@ bool CoreFeatures::enableDefaultAsyncBatchedPriority = false;
 bool CoreFeatures::enableClonelessStateProgression = false;
 bool CoreFeatures::excludeYogaFromRawProps = false;
 bool CoreFeatures::enableMicrotasks = false;
+bool CoreFeatures::enableReportEventPaintTime = false;
 
 } // namespace facebook::react
diff --git a/packages/react-native/ReactCommon/react/utils/CoreFeatures.h b/packages/react-native/ReactCommon/react/utils/CoreFeatures.h
@@ -67,6 +67,10 @@ class CoreFeatures {
   // Enables the use of microtasks in Hermes (scheduling) and RuntimeScheduler
   // (execution).
   static bool enableMicrotasks;
+
+  // Report paint time inside the Event Timing API implementation
+  // (PerformanceObserver).
+  static bool enableReportEventPaintTime;
 };
 
 } // namespace facebook::react