From 09ad0cc0c692d150f4291890cfa346a21e7bd801 Mon Sep 17 00:00:00 2001 From: Ruslan Shestopalyuk Date: Tue, 3 Jan 2023 11:11:37 -0800 Subject: [PATCH] Implement reporting of events from native side to WebPerformance API (#35768) Summary: Pull Request resolved: https://github.com/facebook/react-native/pull/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 --- BUCK | 2 + .../NativePerformanceObserver.cpp | 9 +- .../NativePerformanceObserver.h | 1 + .../PerformanceEntryReporter.cpp | 97 ++++++++++++++++--- .../WebPerformance/PerformanceEntryReporter.h | 41 +++++++- .../WebPerformance/PerformanceEventTiming.js | 2 +- ReactCommon/react/renderer/core/BUCK | 2 + .../react/renderer/core/EventDispatcher.cpp | 8 +- .../react/renderer/core/EventLogger.cpp | 22 +++++ ReactCommon/react/renderer/core/EventLogger.h | 44 +++++++++ .../renderer/core/EventQueueProcessor.cpp | 14 ++- ReactCommon/react/renderer/core/RawEvent.h | 2 + packages/rn-tester/Podfile.lock | 2 +- 13 files changed, 224 insertions(+), 22 deletions(-) create mode 100644 ReactCommon/react/renderer/core/EventLogger.cpp create mode 100644 ReactCommon/react/renderer/core/EventLogger.h diff --git a/BUCK b/BUCK index f798fb50226..25fe38e6a3a 100644 --- a/BUCK +++ b/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"), ], ) diff --git a/Libraries/WebPerformance/NativePerformanceObserver.cpp b/Libraries/WebPerformance/NativePerformanceObserver.cpp index 89a69216a9a..58a2744b2dd 100644 --- a/Libraries/WebPerformance/NativePerformanceObserver.cpp +++ b/Libraries/WebPerformance/NativePerformanceObserver.cpp @@ -6,7 +6,6 @@ */ #include "NativePerformanceObserver.h" -#include #include "PerformanceEntryReporter.h" namespace facebook::react { @@ -28,7 +27,13 @@ static PerformanceEntryType stringToPerformanceEntryType( NativePerformanceObserver::NativePerformanceObserver( std::shared_ptr jsInvoker) - : NativePerformanceObserverCxxSpec(std::move(jsInvoker)) {} + : NativePerformanceObserverCxxSpec(std::move(jsInvoker)) { + setEventLogger(&PerformanceEntryReporter::getInstance()); +} + +NativePerformanceObserver::~NativePerformanceObserver() { + setEventLogger(nullptr); +} void NativePerformanceObserver::startReporting( jsi::Runtime &rt, diff --git a/Libraries/WebPerformance/NativePerformanceObserver.h b/Libraries/WebPerformance/NativePerformanceObserver.h index dbef244feb6..7eb5349c0ee 100644 --- a/Libraries/WebPerformance/NativePerformanceObserver.h +++ b/Libraries/WebPerformance/NativePerformanceObserver.h @@ -57,6 +57,7 @@ class NativePerformanceObserver std::enable_shared_from_this { public: NativePerformanceObserver(std::shared_ptr jsInvoker); + ~NativePerformanceObserver(); void startReporting(jsi::Runtime &rt, std::string entryType); diff --git a/Libraries/WebPerformance/PerformanceEntryReporter.cpp b/Libraries/WebPerformance/PerformanceEntryReporter.cpp index b78184408c9..8a5de57f311 100644 --- a/Libraries/WebPerformance/PerformanceEntryReporter.cpp +++ b/Libraries/WebPerformance/PerformanceEntryReporter.cpp @@ -6,16 +6,20 @@ */ #include "PerformanceEntryReporter.h" -#include -#include +#include +#include #include "NativePerformanceObserver.h" +#include + // 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(entryType)] = false; } -const std::vector - &PerformanceEntryReporter::getPendingEntries() const { - return entries_; -} - GetPendingEntriesResult PerformanceEntryReporter::popPendingEntries() { + std::lock_guard 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(entry.entryType))) { return; } + std::lock_guard 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( 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 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 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 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 diff --git a/Libraries/WebPerformance/PerformanceEntryReporter.h b/Libraries/WebPerformance/PerformanceEntryReporter.h index d53f8ba535c..0bc175d5d79 100644 --- a/Libraries/WebPerformance/PerformanceEntryReporter.h +++ b/Libraries/WebPerformance/PerformanceEntryReporter.h @@ -8,9 +8,12 @@ #pragma once #include +#include #include #include +#include #include +#include #include #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 &getPendingEntries() const; GetPendingEntriesResult popPendingEntries(); - void clearPendingEntries(); void logEntry(const RawPerformanceEntry &entry); bool isReportingType(PerformanceEntryType entryType) const { @@ -99,6 +100,10 @@ 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() {} @@ -106,8 +111,22 @@ class PerformanceEntryReporter { void clearEntries(std::function 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> callback_; std::vector entries_; + std::mutex entriesMutex_; std::array reportingType_{false}; // Mark registry for "measure" lookup @@ -115,6 +134,22 @@ class PerformanceEntryReporter { std::array 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 eventsInFlight_; + std::mutex eventsInFlightMutex_; + std::unordered_set firstInputs_; + + static EventTag sCurrentEventTag_; }; } // namespace facebook::react diff --git a/Libraries/WebPerformance/PerformanceEventTiming.js b/Libraries/WebPerformance/PerformanceEventTiming.js index 43b971a12f2..d82a7c304b2 100644 --- a/Libraries/WebPerformance/PerformanceEventTiming.js +++ b/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, }); diff --git a/ReactCommon/react/renderer/core/BUCK b/ReactCommon/react/renderer/core/BUCK index d6c1b356f71..51912e149e7 100644 --- a/ReactCommon/react/renderer/core/BUCK +++ b/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"), ], ) diff --git a/ReactCommon/react/renderer/core/EventDispatcher.cpp b/ReactCommon/react/renderer/core/EventDispatcher.cpp index 5152c263eb3..55c4cd3744e 100644 --- a/ReactCommon/react/renderer/core/EventDispatcher.cpp +++ b/ReactCommon/react/renderer/core/EventDispatcher.cpp @@ -6,8 +6,9 @@ */ #include "EventDispatcher.h" - +#include #include +#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)); } diff --git a/ReactCommon/react/renderer/core/EventLogger.cpp b/ReactCommon/react/renderer/core/EventLogger.cpp new file mode 100644 index 00000000000..b751d291b03 --- /dev/null +++ b/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 diff --git a/ReactCommon/react/renderer/core/EventLogger.h b/ReactCommon/react/renderer/core/EventLogger.h new file mode 100644 index 00000000000..bac04866382 --- /dev/null +++ b/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 diff --git a/ReactCommon/react/renderer/core/EventQueueProcessor.cpp b/ReactCommon/react/renderer/core/EventQueueProcessor.cpp index 1b92d530b96..4ff9406f60b 100644 --- a/ReactCommon/react/renderer/core/EventQueueProcessor.cpp +++ b/ReactCommon/react/renderer/core/EventQueueProcessor.cpp @@ -5,9 +5,10 @@ * LICENSE file in the root directory of this source tree. */ -#include "EventQueue.h" - +#include #include "EventEmitter.h" +#include "EventLogger.h" +#include "EventQueue.h" #include "ShadowNodeFamily.h" namespace facebook::react { @@ -47,6 +48,11 @@ void EventQueueProcessor::flushEvents( reactPriority = ReactEventPriority::Discrete; } + auto eventLogger = getEventLogger(); + if (eventLogger != nullptr) { + eventLogger->onEventDispatch(event.loggingTag); + } + eventPipe_( runtime, event.eventTarget.get(), @@ -54,6 +60,10 @@ void EventQueueProcessor::flushEvents( reactPriority, event.payloadFactory); + if (eventLogger != nullptr) { + eventLogger->onEventEnd(event.loggingTag); + } + if (event.category == RawEvent::Category::ContinuousStart) { hasContinuousEventStarted_ = true; } diff --git a/ReactCommon/react/renderer/core/RawEvent.h b/ReactCommon/react/renderer/core/RawEvent.h index bd57b7e37c6..43ce761cddb 100644 --- a/ReactCommon/react/renderer/core/RawEvent.h +++ b/ReactCommon/react/renderer/core/RawEvent.h @@ -10,6 +10,7 @@ #include #include +#include #include #include @@ -68,6 +69,7 @@ struct RawEvent { ValueFactory payloadFactory; SharedEventTarget eventTarget; Category category; + EventTag loggingTag{0}; }; } // namespace react diff --git a/packages/rn-tester/Podfile.lock b/packages/rn-tester/Podfile.lock index 31835108598..8f73b40cc4b 100644 --- a/packages/rn-tester/Podfile.lock +++ b/packages/rn-tester/Podfile.lock @@ -944,7 +944,7 @@ SPEC CHECKSUMS: FlipperKit: cbdee19bdd4e7f05472a66ce290f1b729ba3cb86 fmt: ff9d55029c625d3757ed641535fd4a75fedc7ce9 glog: 04b94705f318337d7ead9e6d17c019bd9b1f6b1b - hermes-engine: 7d26e374fcbc156bd34f7a5c6530b5f3b7679df2 + hermes-engine: 1b25fd843452b19b888d47a6022bc0623ede0f38 libevent: 4049cae6c81cdb3654a443be001fb9bdceff7913 OpenSSL-Universal: ebc357f1e6bc71fa463ccb2fe676756aff50e88c RCT-Folly: 424b8c9a7a0b9ab2886ffe9c3b041ef628fd4fb1