Implement reporting of events from native side to WebPerformance API (#35768)

Summary:
Pull Request resolved: #35768

Changelog: [Internal]

This implements native side mechanics for reporting user events timing to JS  (PerformanceObserver API).

See the standard for more details: https://www.w3.org/TR/event-timing/

The events are only logged when there are any active subscriptions (via `PerformanceObserver.observe`), also we only log "discrete events" (i.e. no likes of mouse move), so the overhead is non-existing.

There are two main metrics of interest for an event lifecycle:
* Time the event is spent in the queue, i.e. the time between it's created and dispatched
* Time that is spend in the event handler on the JS side (event dispatch), or processing time

Both of these are measured, and the corresponding fields are populated.

Reviewed By: sammy-SC

Differential Revision: D42294947

fbshipit-source-id: 4fd7938c04b942400befa4057d4929fb2763cee1

Author: rshest

BUCK

@@ -1477,5 +1477,7 @@ rn_apple_xplat_cxx_library(
     visibility = ["PUBLIC"],
     deps = [
         ":FBReactNativeSpecJSI",
+        react_native_xplat_target("react/renderer/core:core"),
+        react_native_xplat_target("cxxreact:bridge"),
     ],
 )

Libraries/WebPerformance/NativePerformanceObserver.cpp

@@ -6,7 +6,6 @@
  */
 
 #include "NativePerformanceObserver.h"
-#include <glog/logging.h>
 #include "PerformanceEntryReporter.h"
 
 namespace facebook::react {
@@ -28,7 +27,13 @@ static PerformanceEntryType stringToPerformanceEntryType(
 
 NativePerformanceObserver::NativePerformanceObserver(
     std::shared_ptr<CallInvoker> jsInvoker)
-    : NativePerformanceObserverCxxSpec(std::move(jsInvoker)) {}
+    : NativePerformanceObserverCxxSpec(std::move(jsInvoker)) {
+  setEventLogger(&PerformanceEntryReporter::getInstance());
+}
+
+NativePerformanceObserver::~NativePerformanceObserver() {
+  setEventLogger(nullptr);
+}
 
 void NativePerformanceObserver::startReporting(
     jsi::Runtime &rt,

Libraries/WebPerformance/NativePerformanceObserver.h

@@ -57,6 +57,7 @@ class NativePerformanceObserver
       std::enable_shared_from_this<NativePerformanceObserver> {
  public:
   NativePerformanceObserver(std::shared_ptr<CallInvoker> jsInvoker);
+  ~NativePerformanceObserver();
 
   void startReporting(jsi::Runtime &rt, std::string entryType);
 

Libraries/WebPerformance/PerformanceEntryReporter.cpp

@@ -6,16 +6,20 @@
  */
 
 #include "PerformanceEntryReporter.h"
-#include <glog/logging.h>
-#include <react/renderer/runtimescheduler/RuntimeScheduler.h>
+#include <cxxreact/JSExecutor.h>
+#include <react/renderer/core/EventLogger.h>
 #include "NativePerformanceObserver.h"
 
+#include <algorithm>
+
 // All the unflushed entries beyond this amount will get discarded, with
 // the amount of discarded ones sent back to the observers' callbacks as
 // "droppedEntryCount" value
 static constexpr size_t MAX_ENTRY_BUFFER_SIZE = 1024;
 
 namespace facebook::react {
+EventTag PerformanceEntryReporter::sCurrentEventTag_{0};
+
 PerformanceEntryReporter &PerformanceEntryReporter::getInstance() {
   static PerformanceEntryReporter instance;
   return instance;
@@ -33,27 +37,22 @@ void PerformanceEntryReporter::stopReporting(PerformanceEntryType entryType) {
   reportingType_[static_cast<int>(entryType)] = false;
 }
 
-const std::vector<RawPerformanceEntry>
-    &PerformanceEntryReporter::getPendingEntries() const {
-  return entries_;
-}
-
 GetPendingEntriesResult PerformanceEntryReporter::popPendingEntries() {
+  std::lock_guard<std::mutex> lock(entriesMutex_);
+
   GetPendingEntriesResult res = {std::move(entries_), droppedEntryCount_};
   entries_ = {};
   droppedEntryCount_ = 0;
   return res;
 }
 
-void PerformanceEntryReporter::clearPendingEntries() {
-  entries_.clear();
-}
-
 void PerformanceEntryReporter::logEntry(const RawPerformanceEntry &entry) {
   if (!isReportingType(static_cast<PerformanceEntryType>(entry.entryType))) {
     return;
   }
 
+  std::lock_guard<std::mutex> lock(entriesMutex_);
+
   if (entries_.size() == MAX_ENTRY_BUFFER_SIZE) {
     // Start dropping entries once reached maximum buffer size.
     // The number of dropped entries will be reported back to the corresponding
@@ -179,7 +178,7 @@ void PerformanceEntryReporter::event(
       {name,
        static_cast<int>(
            isFirstInput ? PerformanceEntryType::FIRST_INPUT
-                        : PerformanceEntryType::MEASURE),
+                        : PerformanceEntryType::EVENT),
        startTime,
        duration,
        processingStart,
@@ -207,4 +206,78 @@ void PerformanceEntryReporter::scheduleFlushBuffer() {
   }
 }
 
+static bool isDiscreteEvent(const char *name) {
+  return !std::strstr(name, "Move") && !std::strstr(name, "Layout");
+}
+
+EventTag PerformanceEntryReporter::onEventStart(const char *name) {
+  if (!isReportingEvents() || !isDiscreteEvent(name)) {
+    return 0;
+  }
+
+  sCurrentEventTag_++;
+  if (sCurrentEventTag_ == 0) {
+    // The tag wrapped around (which is highly unlikely, but still)
+    sCurrentEventTag_ = 1;
+  }
+
+  if (std::strstr(name, "top") == name) {
+    // Skip the "top" prefix if present
+    name += 3;
+  }
+
+  auto timeStamp = JSExecutor::performanceNow();
+  {
+    std::lock_guard<std::mutex> lock(eventsInFlightMutex_);
+    eventsInFlight_.emplace(
+        std::make_pair(sCurrentEventTag_, EventEntry{name, timeStamp, 0.0}));
+  }
+  return sCurrentEventTag_;
+}
+
+void PerformanceEntryReporter::onEventDispatch(EventTag tag) {
+  if (!isReportingEvents() || tag == 0) {
+    return;
+  }
+  auto timeStamp = JSExecutor::performanceNow();
+  {
+    std::lock_guard<std::mutex> lock(eventsInFlightMutex_);
+    auto it = eventsInFlight_.find(tag);
+    if (it != eventsInFlight_.end()) {
+      it->second.dispatchTime = timeStamp;
+    }
+  }
+}
+
+void PerformanceEntryReporter::onEventEnd(EventTag tag) {
+  if (!isReportingEvents() || tag == 0) {
+    return;
+  }
+  auto timeStamp = JSExecutor::performanceNow();
+  {
+    std::lock_guard<std::mutex> lock(eventsInFlightMutex_);
+    auto it = eventsInFlight_.find(tag);
+    if (it == eventsInFlight_.end()) {
+      return;
+    }
+    auto &entry = it->second;
+    auto &name = entry.name;
+    std::transform(name.begin(), name.end(), name.begin(), ::tolower);
+
+    // TODO: Define the way to assign interaction IDs to the event chains
+    // (T141358175)
+    const uint32_t interactionId = 0;
+    bool firstInput = isFirstInput(name);
+    event(
+        std::move(name),
+        entry.startTime,
+        timeStamp - entry.startTime,
+        firstInput,
+        entry.dispatchTime,
+        timeStamp,
+        interactionId);
+    eventsInFlight_.erase(it);
+  }
+}
+
 } // namespace facebook::react

Libraries/WebPerformance/PerformanceEntryReporter.h

@@ -8,9 +8,12 @@
 #pragma once
 
 #include <react/bridging/Function.h>
+#include <react/renderer/core/EventLogger.h>
 #include <array>
 #include <functional>
+#include <mutex>
 #include <optional>
+#include <unordered_map>
 #include <unordered_set>
 #include "NativePerformanceObserver.h"
 
@@ -50,7 +53,7 @@ enum class PerformanceEntryType {
   _COUNT = 5,
 };
 
-class PerformanceEntryReporter {
+class PerformanceEntryReporter : public EventLogger {
  public:
   PerformanceEntryReporter(PerformanceEntryReporter const &) = delete;
   void operator=(PerformanceEntryReporter const &) = delete;
@@ -65,9 +68,7 @@ class PerformanceEntryReporter {
   void startReporting(PerformanceEntryType entryType);
   void stopReporting(PerformanceEntryType entryType);
 
-  const std::vector<RawPerformanceEntry> &getPendingEntries() const;
   GetPendingEntriesResult popPendingEntries();
-  void clearPendingEntries();
   void logEntry(const RawPerformanceEntry &entry);
 
   bool isReportingType(PerformanceEntryType entryType) const {
@@ -99,22 +100,56 @@ class PerformanceEntryReporter {
       double processingEnd,
       uint32_t interactionId);
 
+  EventTag onEventStart(const char *name) override;
+  void onEventDispatch(EventTag tag) override;
+  void onEventEnd(EventTag tag) override;
+
  private:
   PerformanceEntryReporter() {}
 
   double getMarkTime(const std::string &markName) const;
   void clearEntries(std::function<bool(const RawPerformanceEntry &)> predicate);
   void scheduleFlushBuffer();
 
+  bool isReportingEvents() const {
+    return isReportingType(PerformanceEntryType::EVENT) ||
+        isReportingType(PerformanceEntryType::FIRST_INPUT);
+  }
+
+  bool isFirstInput(std::string name) {
+    if (firstInputs_.find(name) == firstInputs_.end()) {
+      firstInputs_.insert(std::move(name));
+      return true;
+    }
+    return false;
+  }
+
   std::optional<AsyncCallback<>> callback_;
   std::vector<RawPerformanceEntry> entries_;
+  std::mutex entriesMutex_;
   std::array<bool, (size_t)PerformanceEntryType::_COUNT> reportingType_{false};
 
   // Mark registry for "measure" lookup
   PerformanceMarkRegistryType marksRegistry_;
   std::array<PerformanceMark, MARKS_BUFFER_SIZE> marksBuffer_;
   size_t marksBufferPosition_{0};
   uint32_t droppedEntryCount_{0};
+
+  struct EventEntry {
+    std::string name;
+    double startTime{0.0};
+    double dispatchTime{0.0};
+  };
+
+  // Registry to store the events that are currently ongoing.
+  // Note that we could probably use a more efficient container for that,
+  // but since we only report discrete events, the volume is normally low,
+  // so a hash map should be just fine.
+  std::unordered_map<EventTag, EventEntry> eventsInFlight_;
+  std::mutex eventsInFlightMutex_;
+  std::unordered_set<std::string> firstInputs_;
+
+  static EventTag sCurrentEventTag_;
 };
 
 } // namespace facebook::react

Libraries/WebPerformance/PerformanceEventTiming.js

@@ -28,7 +28,7 @@ export class PerformanceEventTiming extends PerformanceEntry {
   }) {
     super({
       name: init.name,
-      entryType: init.isFirstInput === true ? 'first-input' : 'measure',
+      entryType: init.isFirstInput === true ? 'first-input' : 'event',
       startTime: init.startTime ?? 0,
       duration: init.duration ?? 0,
     });

ReactCommon/react/renderer/core/BUCK

@@ -59,6 +59,7 @@ rn_xplat_cxx_library(
         react_native_xplat_target("react/utils:utils"),
         react_native_xplat_target("react/renderer/debug:debug"),
         react_native_xplat_target("react/renderer/graphics:graphics"),
+        react_native_xplat_target("cxxreact:bridge"),
     ],
 )
 
@@ -84,6 +85,7 @@ fb_xplat_cxx_test(
         react_native_xplat_target("react/renderer/components/text:text"),
         react_native_xplat_target("react/renderer/element:element"),
         react_native_xplat_target("react/renderer/components/view:view"),
+        react_native_xplat_target("cxxreact:bridge"),
     ],
 )
 

ReactCommon/react/renderer/core/EventDispatcher.cpp

@@ -6,8 +6,9 @@
  */
 
 #include "EventDispatcher.h"
-
+#include <cxxreact/JSExecutor.h>
 #include <react/renderer/core/StateUpdate.h>
+#include "EventLogger.h"
 
 #include "BatchedEventQueue.h"
 #include "RawEvent.h"
@@ -39,6 +40,11 @@ void EventDispatcher::dispatchEvent(RawEvent &&rawEvent, EventPriority priority)
   if (eventListeners_.willDispatchEvent(rawEvent)) {
     return;
   }
+
+  auto eventLogger = getEventLogger();
+  if (eventLogger != nullptr) {
+    rawEvent.loggingTag = eventLogger->onEventStart(rawEvent.type.c_str());
+  }
   getEventQueue(priority).enqueueEvent(std::move(rawEvent));
 }
 

ReactCommon/react/renderer/core/EventLogger.cpp

@@ -0,0 +1,22 @@
+/*
+ * Copyright (c) Meta Platforms, Inc. and affiliates.
+ *
+ * This source code is licensed under the MIT license found in the
+ * LICENSE file in the root directory of this source tree.
+ */
+
+#include "EventLogger.h"
+
+namespace facebook::react {
+
+EventLogger *eventLogger;
+
+void setEventLogger(EventLogger *logger) {
+  eventLogger = logger;
+}
+
+EventLogger *getEventLogger() {
+  return eventLogger;
+}
+
+} // namespace facebook::react

ReactCommon/react/renderer/core/EventLogger.h

@@ -0,0 +1,44 @@
+/*
+ * Copyright (c) Meta Platforms, Inc. and affiliates.
+ *
+ * This source code is licensed under the MIT license found in the
+ * LICENSE file in the root directory of this source tree.
+ */
+
+#pragma once
+
+namespace facebook::react {
+
+using EventTag = unsigned int;
+
+/*
+ * Interface for logging discrete events (such as pointerenter/leave),
+ * which can be used for implementing W3C Event Timing API standard,
+ * see https://www.w3.org/TR/event-timing
+ */
+class EventLogger {
+ public:
+  virtual ~EventLogger() = default;
+
+  /*
+   * Called when an event is first created, returns and unique tag for this
+   * event, which can be used to log further event processing stages.
+   */
+  virtual EventTag onEventStart(const char *name) = 0;
+
+  /*
+   * Called when event starts getting dispatched (processed by the handlers, if
+   * any)
+   */
+  virtual void onEventDispatch(EventTag tag) = 0;
+
+  /*
+   * Called when event finishes being dispatched
+   */
+  virtual void onEventEnd(EventTag tag) = 0;
+};
+
+void setEventLogger(EventLogger *eventLogger);
+EventLogger *getEventLogger();
+
+} // namespace facebook::react