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);`.

Differential Revision: D51313902

packages/react-native/Libraries/WebPerformance/NativePerformanceObserver.cpp

@@ -10,8 +10,12 @@
 #include "NativePerformanceObserver.h"
 #include "PerformanceEntryReporter.h"
 
+#include <react/renderer/uimanager/UIManagerBinding.h>
+
 #include "Plugins.h"
 
+#include <glog/logging.h>
+
 std::shared_ptr<facebook::react::TurboModule>
 NativePerformanceObserverModuleProvider(
     std::shared_ptr<facebook::react::CallInvoker> jsInvoker) {
@@ -34,15 +38,44 @@ 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 &&
+      reporter.isReportingEventPaintTime()) {
+    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 &&
+      reporter.isReportingEventPaintTime()) {
+    UIManagerBinding::getBinding(rt)->getUIManager().unregisterMountHook(
+        reporter);
+  }
+}
+
+void NativePerformanceObserver::setIsReportingEventPaintTime(
+    jsi::Runtime& rt,
+    bool isReportingEventPaintTime) {
+  PerformanceEntryReporter::getInstance().setIsReportingEventPaintTime(
+      isReportingEventPaintTime);
+}
+
+bool NativePerformanceObserver::isReportingEventPaintTime(jsi::Runtime& rt) {
+  return PerformanceEntryReporter::getInstance().isReportingEventPaintTime();
 }
 
 void NativePerformanceObserver::setIsBuffered(

packages/react-native/Libraries/WebPerformance/NativePerformanceObserver.h

@@ -76,6 +76,12 @@ class NativePerformanceObserver
       jsi::Runtime& rt,
       std::optional<AsyncCallback<>> callback);
 
+  void setIsReportingEventPaintTime(
+      jsi::Runtime& rt,
+      bool isReportingEventPaintTime);
+
+  bool isReportingEventPaintTime(jsi::Runtime& rt);
+
   void logRawEntry(jsi::Runtime& rt, RawPerformanceEntry entry);
 
   std::vector<std::pair<std::string, uint32_t>> getEventCounts(

packages/react-native/Libraries/WebPerformance/NativePerformanceObserver.js

@@ -54,6 +54,8 @@ export interface Spec extends TurboModule {
     entryName?: string,
   ) => $ReadOnlyArray<RawPerformanceEntry>;
   +getSupportedPerformanceEntryTypes: () => $ReadOnlyArray<RawPerformanceEntryType>;
+  +isReportingEventPaintTime: () => boolean;
+  +setIsReportingEventPaintTime: (isReportingEventPaintTime: boolean) => void;
 }
 
 export default (TurboModuleRegistry.get<Spec>(

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};
 
@@ -32,6 +35,18 @@ void PerformanceEntryReporter::setReportingCallback(
   callback_ = callback;
 }
 
+void PerformanceEntryReporter::setIsReportingEventPaintTime(
+    bool isReportingEventPaintTime) {
+  isReportingEventPaintTime_ = isReportingEventPaintTime;
+
+  if (!CoreFeatures::enableMountHooks) {
+    // Force to false, as this relies on mount hooks being enabled
+    LOG(WARNING)
+        << "PerformanceEntryReporter: mount hooks must be enabled to report paint times.";
+    isReportingEventPaintTime_ = false;
+  }
+}
+
 double PerformanceEntryReporter::getCurrentTimeStamp() const {
   return timeStampProvider_ != nullptr ? timeStampProvider_()
                                        : JSExecutor::performanceNow();
@@ -397,12 +412,12 @@ void PerformanceEntryReporter::onEventDispatch(EventTag tag) {
     std::scoped_lock 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::onEventDispatchEnd(EventTag tag) {
   if (!isReporting(PerformanceEntryType::EVENT) || tag == 0) {
     return;
   }
@@ -414,7 +429,15 @@ void PerformanceEntryReporter::onEventEnd(EventTag tag) {
       return;
     }
     auto& entry = it->second;
-    auto& name = entry.name;
+    entry.processingEndTime = timeStamp;
+
+    if (isReportingEventPaintTime_) {
+      // If reporting paint time, don't send the entry just yet and wait for the
+      // mount hook callback to be called
+      return;
+    }
+
+    const auto& name = entry.name;
 
     // TODO: Define the way to assign interaction IDs to the event chains
     // (T141358175)
@@ -423,11 +446,41 @@ void PerformanceEntryReporter::onEventEnd(EventTag tag) {
         std::string(name),
         entry.startTime,
         timeStamp - entry.startTime,
-        entry.dispatchTime,
-        timeStamp,
+        entry.processingStartTime,
+        entry.processingEndTime,
         interactionId);
     eventsInFlight_.erase(it);
   }
 }
 
+void PerformanceEntryReporter::shadowTreeDidMount(
+    const RootShadowNode::Shared& rootShadowNode,
+    double mountTime) noexcept {
+  if (!isReporting(PerformanceEntryType::EVENT) ||
+      !isReportingEventPaintTime_) {
+    return;
+  }
+
+  std::scoped_lock 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;
+    }
+
+    const uint32_t interactionId = 0;
+    event(
+        std::string(entry.name),
+        entry.startTime,
+        mountTime - entry.startTime,
+        entry.processingStartTime,
+        entry.processingEndTime,
+        interactionId);
+    it = eventsInFlight_.erase(it);
+  }
+}
+
 } // namespace facebook::react

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;
@@ -142,7 +144,11 @@ class PerformanceEntryReporter : public EventLogger {
 
   EventTag onEventStart(std::string_view name) override;
   void onEventDispatch(EventTag tag) override;
-  void onEventEnd(EventTag tag) override;
+  void onEventDispatchEnd(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_;
@@ -152,6 +158,12 @@ class PerformanceEntryReporter : public EventLogger {
     timeStampProvider_ = provider;
   }
 
+  void setIsReportingEventPaintTime(bool isReportingEventPaintTime);
+
+  bool isReportingEventPaintTime() const {
+    return isReportingEventPaintTime_;
+  }
+
  private:
   std::optional<AsyncCallback<>> callback_;
 
@@ -164,7 +176,8 @@ 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};
   };
 
   // Registry to store the events that are currently ongoing.
@@ -176,6 +189,10 @@ class PerformanceEntryReporter : public EventLogger {
 
   std::function<double()> timeStampProvider_ = nullptr;
 
+  // When set to true, the events end will be corresponding to the "paint" time,
+  // instead of processing end
+  bool isReportingEventPaintTime_ = false;
+
   mutable std::mutex nameLookupMutex_;
 
   static EventTag sCurrentEventTag_;

packages/react-native/Libraries/WebPerformance/__mocks__/NativePerformanceObserver.js

@@ -123,6 +123,13 @@ const NativePerformanceObserverMock: NativePerformanceObserver = {
         RawPerformanceEntryTypeValues.EVENT,
       ];
     },
+
+  isReportingEventPaintTime: (): boolean => {
+    return false;
+  },
+  setIsReportingEventPaintTime: (
+    isReportingEventPaintTime: boolean,
+  ): void => {},
 };
 
 export default NativePerformanceObserverMock;

packages/react-native/ReactCommon/react/renderer/core/EventLogger.h

@@ -37,7 +37,7 @@ class EventLogger {
   /*
    * Called when event finishes being dispatched
    */
-  virtual void onEventEnd(EventTag tag) = 0;
+  virtual void onEventDispatchEnd(EventTag tag) = 0;
 };
 
 void setEventLogger(EventLogger* eventLogger);

packages/react-native/ReactCommon/react/renderer/core/EventQueueProcessor.cpp

@@ -77,7 +77,7 @@ void EventQueueProcessor::flushEvents(
     }
 
     if (eventLogger != nullptr) {
-      eventLogger->onEventEnd(event.loggingTag);
+      eventLogger->onEventDispatchEnd(event.loggingTag);
     }
 
     if (event.category == RawEvent::Category::ContinuousStart) {