From 07d0e5f13df1aed086fbc38cfce31acb7fc9f68d Mon Sep 17 00:00:00 2001 From: Ruslan Shestopalyuk Date: Wed, 15 Nov 2023 06:19:28 -0800 Subject: [PATCH] Implement "paint time" support in Event Timing API (#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 --- .../NativePerformanceObserver.cpp | 29 ++++++- .../PerformanceEntryReporter.cpp | 87 +++++++++++++------ .../WebPerformance/PerformanceEntryReporter.h | 21 +++-- .../react/renderer/core/EventLogger.h | 4 +- .../renderer/core/EventQueueProcessor.cpp | 4 +- .../ReactCommon/react/utils/CoreFeatures.cpp | 1 + .../ReactCommon/react/utils/CoreFeatures.h | 4 + 7 files changed, 112 insertions(+), 38 deletions(-) diff --git a/packages/react-native/Libraries/WebPerformance/NativePerformanceObserver.cpp b/packages/react-native/Libraries/WebPerformance/NativePerformanceObserver.cpp index 206da95d6c269e..9e40a7e74b4467 100644 --- 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 +#include + #include "Plugins.h" std::shared_ptr @@ -34,15 +37,33 @@ NativePerformanceObserver::~NativePerformanceObserver() { void NativePerformanceObserver::startReporting( jsi::Runtime& rt, int32_t entryType) { - PerformanceEntryReporter::getInstance().startReporting( - static_cast(entryType)); + PerformanceEntryReporter& reporter = PerformanceEntryReporter::getInstance(); + + PerformanceEntryType entryTypeEnum = + static_cast(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(entryType)); + PerformanceEntryReporter& reporter = PerformanceEntryReporter::getInstance(); + + PerformanceEntryType entryTypeEnum = + static_cast(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 index ff7389eeb1775a..5d07b3043c5642 100644 --- a/packages/react-native/Libraries/WebPerformance/PerformanceEntryReporter.cpp +++ b/packages/react-native/Libraries/WebPerformance/PerformanceEntryReporter.cpp @@ -8,11 +8,14 @@ #include "PerformanceEntryReporter.h" #include #include +#include #include "NativePerformanceObserver.h" #include #include +#include + 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(), 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(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(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 index 5c805beac2d4ca..ca436d9746f8c4 100644 --- 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 + 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& 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 index 3a2863ba9d7d58..ba0cabd17764a3 100644 --- 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 index b562e0e8768575..b595cc31895c87 100644 --- 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 index c24e9e1d4c3727..6bdcc5d651e05e 100644 --- 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 index 400e1f90509908..2a377625791e66 100644 --- 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