Skip to content

Commit

Permalink
Fix incorrect timing for events that do not update the UI (#46253)
Browse files Browse the repository at this point in the history
Summary:
Pull Request resolved: #46253

Changelog: [internal]

This is still internal because this API hasn't been publicly released yet.

## Context

This fixes a problem in our implementation for Event Timing API with paint time reporting (currently gated behind `ReactNativeFeatureFlags::enableReportEventPaintTime`) where events that don't trigger UI changes would wait for the next (unrelated) UI change to finish the event timing information.

## Implementation

We had this issue because we were relying on mount hooks to finish pending events. The problem is that if the event itself didn't cause a commit, the mount hook will not execute immediately, and we'll wait for the mount notification of whatever is the next change (in an arbitrary point in time in the future).

The fix for this has several parts:
1. Modify `RuntimeScheduler` to start tracking which surface IDs are the rendering updates applying to. It makes sense to do this regardless because `RuntimeScheduler` implements the Event Loop, and the Event Loop is aware of "documents" on Web (and the equivalent are surfaces in RN).
2. Create a new hook in `RuntimeScheduler` to report events after the task has finished executing (which is already a step in the Event Loop on Web). This will pass the list of surface IDs with pending changes, so the listener can determine if the events should be finished already or they should wait for mount for those changes.
3. Integrate `EventPerformanceLogger` with `RuntimeScheduler` and add the proper logic to handle this.

Reviewed By: sammy-SC, rshest

Differential Revision: D61939260
  • Loading branch information
rubennorte authored and facebook-github-bot committed Aug 29, 2024
1 parent c30930a commit e7ecb2b
Show file tree
Hide file tree
Showing 15 changed files with 198 additions and 24 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -37,7 +37,8 @@ void EventDispatcher::dispatchEvent(RawEvent&& rawEvent) const {

auto eventLogger = eventLogger_.lock();
if (eventLogger != nullptr) {
rawEvent.loggingTag = eventLogger->onEventStart(rawEvent.type);
rawEvent.loggingTag =
eventLogger->onEventStart(rawEvent.type, rawEvent.eventTarget);
}
eventQueue_.enqueueEvent(std::move(rawEvent));
}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@

#pragma once

#include <react/renderer/core/EventTarget.h>
#include <string_view>

namespace facebook::react {
Expand All @@ -27,7 +28,9 @@ class EventLogger {
* 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(std::string_view name) = 0;
virtual EventTag onEventStart(
std::string_view name,
SharedEventTarget target) = 0;

/*
* Called when event starts getting dispatched (processed by the handlers, if
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@
#include <react/renderer/core/EventLogger.h>
#include <react/renderer/core/EventPipe.h>
#include <react/renderer/core/EventQueueProcessor.h>
#include <react/renderer/core/EventTarget.h>
#include <react/renderer/core/StatePipe.h>
#include <react/renderer/core/ValueFactoryEventPayload.h>

Expand All @@ -20,7 +21,8 @@
namespace facebook::react {

class MockEventLogger : public EventLogger {
EventTag onEventStart(std::string_view /*name*/) override {
EventTag onEventStart(std::string_view /*name*/, SharedEventTarget /*target*/)
override {
return EMPTY_EVENT_TAG;
}
void onEventProcessingStart(EventTag /*tag*/) override {}
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -20,7 +20,9 @@ add_library(react_render_observers_events OBJECT ${react_render_observers_events
target_include_directories(react_render_observers_events PUBLIC ${REACT_COMMON_DIR})
target_link_libraries(react_render_observers_events
react_performance_timeline
react_timing
react_render_core
react_render_runtimescheduler
react_featureflags
react_render_uimanager
react_utils)
Original file line number Diff line number Diff line change
Expand Up @@ -8,13 +8,29 @@
#include "EventPerformanceLogger.h"

#include <react/featureflags/ReactNativeFeatureFlags.h>
#include <react/timing/primitives.h>
#include <react/utils/CoreFeatures.h>
#include <unordered_map>

namespace facebook::react {

namespace {

bool isTargetInRootShadowNode(
const SharedEventTarget& target,
const RootShadowNode::Shared& rootShadowNode) {
return target && rootShadowNode &&
target->getSurfaceId() == rootShadowNode->getSurfaceId();
}

bool hasPendingRenderingUpdates(
const SharedEventTarget& target,
const std::unordered_set<SurfaceId>&
surfaceIdsWithPendingRenderingUpdates) {
return target != nullptr &&
surfaceIdsWithPendingRenderingUpdates.contains(target->getSurfaceId());
}

struct StrKey {
size_t key;
StrKey(std::string_view s) : key(std::hash<std::string_view>{}(s)) {}
Expand Down Expand Up @@ -85,7 +101,9 @@ EventPerformanceLogger::EventPerformanceLogger(
std::weak_ptr<PerformanceEntryReporter> performanceEntryReporter)
: performanceEntryReporter_(std::move(performanceEntryReporter)) {}

EventTag EventPerformanceLogger::onEventStart(std::string_view name) {
EventTag EventPerformanceLogger::onEventStart(
std::string_view name,
SharedEventTarget target) {
auto performanceEntryReporter = performanceEntryReporter_.lock();
if (performanceEntryReporter == nullptr) {
return EMPTY_EVENT_TAG;
Expand All @@ -104,7 +122,8 @@ EventTag EventPerformanceLogger::onEventStart(std::string_view name) {
auto timeStamp = performanceEntryReporter->getCurrentTimeStamp();
{
std::lock_guard lock(eventsInFlightMutex_);
eventsInFlight_.emplace(eventTag, EventEntry{reportedName, timeStamp, 0.0});
eventsInFlight_.emplace(
eventTag, EventEntry{reportedName, target, timeStamp, 0.0});
}
return eventTag;
}
Expand Down Expand Up @@ -138,12 +157,13 @@ void EventPerformanceLogger::onEventProcessingEnd(EventTag tag) {
if (it == eventsInFlight_.end()) {
return;
}

auto& entry = it->second;
entry.processingEndTime = timeStamp;

if (ReactNativeFeatureFlags::enableReportEventPaintTime()) {
// If reporting paint time, don't send the entry just yet and wait for the
// mount hook callback to be called
// task to finish.
return;
}

Expand All @@ -160,8 +180,45 @@ void EventPerformanceLogger::onEventProcessingEnd(EventTag tag) {
}
}

void EventPerformanceLogger::dispatchPendingEventTimingEntries(
const std::unordered_set<SurfaceId>&
surfaceIdsWithPendingRenderingUpdates) {
if (!ReactNativeFeatureFlags::enableReportEventPaintTime()) {
return;
}

auto performanceEntryReporter = performanceEntryReporter_.lock();
if (performanceEntryReporter == nullptr) {
return;
}

std::lock_guard lock(eventsInFlightMutex_);
auto it = eventsInFlight_.begin();
while (it != eventsInFlight_.end()) {
auto& entry = it->second;

if (entry.isWaitingForDispatch() || entry.isWaitingForMount) {
++it;
} else if (hasPendingRenderingUpdates(
entry.target, surfaceIdsWithPendingRenderingUpdates)) {
// We'll wait for mount to report the event
entry.isWaitingForMount = true;
++it;
} else {
performanceEntryReporter->logEventEntry(
std::string(entry.name),
entry.startTime,
performanceEntryReporter->getCurrentTimeStamp() - entry.startTime,
entry.processingStartTime,
entry.processingEndTime,
entry.interactionId);
it = eventsInFlight_.erase(it);
}
}
}

void EventPerformanceLogger::shadowTreeDidMount(
const RootShadowNode::Shared& /*rootShadowNode*/,
const RootShadowNode::Shared& rootShadowNode,
double mountTime) noexcept {
if (!ReactNativeFeatureFlags::enableReportEventPaintTime()) {
return;
Expand All @@ -176,20 +233,19 @@ void EventPerformanceLogger::shadowTreeDidMount(
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
if (entry.isWaitingForMount &&
isTargetInRootShadowNode(entry.target, rootShadowNode)) {
performanceEntryReporter->logEventEntry(
std::string(entry.name),
entry.startTime,
mountTime - entry.startTime,
entry.processingStartTime,
entry.processingEndTime,
entry.interactionId);
it = eventsInFlight_.erase(it);
} else {
++it;
continue;
}

performanceEntryReporter->logEventEntry(
std::string(entry.name),
entry.startTime,
mountTime - entry.startTime,
entry.processingStartTime,
entry.processingEndTime,
entry.interactionId);
it = eventsInFlight_.erase(it);
}
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,7 @@

#include <react/performance/timeline/PerformanceEntryReporter.h>
#include <react/renderer/core/EventLogger.h>
#include <react/renderer/runtimescheduler/RuntimeSchedulerEventTimingDelegate.h>
#include <react/renderer/uimanager/UIManagerMountHook.h>
#include <memory>
#include <mutex>
Expand All @@ -17,17 +18,26 @@

namespace facebook::react {

class EventPerformanceLogger : public EventLogger, public UIManagerMountHook {
class EventPerformanceLogger : public EventLogger,
public RuntimeSchedulerEventTimingDelegate,
public UIManagerMountHook {
public:
explicit EventPerformanceLogger(
std::weak_ptr<PerformanceEntryReporter> performanceEntryReporter);

#pragma mark - EventLogger

EventTag onEventStart(std::string_view name) override;
EventTag onEventStart(std::string_view name, SharedEventTarget target)
override;
void onEventProcessingStart(EventTag tag) override;
void onEventProcessingEnd(EventTag tag) override;

#pragma mark - RuntimeSchedulerEventTimingDelegate

void dispatchPendingEventTimingEntries(
const std::unordered_set<SurfaceId>&
surfaceIdsWithPendingRenderingUpdates) override;

#pragma mark - UIManagerMountHook

void shadowTreeDidMount(
Expand All @@ -37,13 +47,20 @@ class EventPerformanceLogger : public EventLogger, public UIManagerMountHook {
private:
struct EventEntry {
std::string_view name;
SharedEventTarget target{nullptr};
DOMHighResTimeStamp startTime{0.0};
DOMHighResTimeStamp processingStartTime{0.0};
DOMHighResTimeStamp processingEndTime{0.0};

bool isWaitingForMount{false};

// TODO: Define the way to assign interaction IDs to the event chains
// (T141358175)
PerformanceEntryInteractionId interactionId{0};

bool isWaitingForDispatch() {
return processingEndTime == 0.0;
}
};

// Registry to store the events that are currently ongoing.
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -101,9 +101,10 @@ void RuntimeScheduler::callExpiredTasks(jsi::Runtime& runtime) {
}

void RuntimeScheduler::scheduleRenderingUpdate(
SurfaceId surfaceId,
RuntimeSchedulerRenderingUpdate&& renderingUpdate) {
return runtimeSchedulerImpl_->scheduleRenderingUpdate(
std::move(renderingUpdate));
surfaceId, std::move(renderingUpdate));
}

void RuntimeScheduler::setShadowTreeRevisionConsistencyManager(
Expand All @@ -119,4 +120,9 @@ void RuntimeScheduler::setPerformanceEntryReporter(
performanceEntryReporter);
}

void RuntimeScheduler::setEventTimingDelegate(
RuntimeSchedulerEventTimingDelegate* eventTimingDelegate) {
return runtimeSchedulerImpl_->setEventTimingDelegate(eventTimingDelegate);
}

} // namespace facebook::react
Original file line number Diff line number Diff line change
Expand Up @@ -13,11 +13,13 @@
#include <react/renderer/runtimescheduler/RuntimeSchedulerClock.h>
#include <react/renderer/runtimescheduler/SchedulerPriorityUtils.h>
#include <react/renderer/runtimescheduler/Task.h>
#include "RuntimeSchedulerEventTimingDelegate.h"

namespace facebook::react {

using RuntimeSchedulerRenderingUpdate = std::function<void()>;
using RuntimeSchedulerTimeout = std::chrono::milliseconds;
using SurfaceId = int32_t;

using RuntimeSchedulerTaskErrorHandler =
std::function<void(jsi::Runtime& runtime, jsi::JSError& error)>;
Expand Down Expand Up @@ -49,11 +51,14 @@ class RuntimeSchedulerBase {
virtual RuntimeSchedulerTimePoint now() const noexcept = 0;
virtual void callExpiredTasks(jsi::Runtime& runtime) = 0;
virtual void scheduleRenderingUpdate(
SurfaceId surfaceId,
RuntimeSchedulerRenderingUpdate&& renderingUpdate) = 0;
virtual void setShadowTreeRevisionConsistencyManager(
ShadowTreeRevisionConsistencyManager* provider) = 0;
virtual void setPerformanceEntryReporter(
PerformanceEntryReporter* reporter) = 0;
virtual void setEventTimingDelegate(
RuntimeSchedulerEventTimingDelegate* eventTimingDelegate) = 0;
};

// This is a proxy for RuntimeScheduler implementation, which will be selected
Expand Down Expand Up @@ -155,6 +160,7 @@ class RuntimeScheduler final : RuntimeSchedulerBase {
void callExpiredTasks(jsi::Runtime& runtime) override;

void scheduleRenderingUpdate(
SurfaceId surfaceId,
RuntimeSchedulerRenderingUpdate&& renderingUpdate) override;

void setShadowTreeRevisionConsistencyManager(
Expand All @@ -163,6 +169,9 @@ class RuntimeScheduler final : RuntimeSchedulerBase {

void setPerformanceEntryReporter(PerformanceEntryReporter* reporter) override;

void setEventTimingDelegate(
RuntimeSchedulerEventTimingDelegate* eventTimingDelegate) override;

private:
// Actual implementation, stored as a unique pointer to simplify memory
// management.
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,25 @@
/*
* 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

#include <unordered_set>

namespace facebook::react {

using SurfaceId = int32_t;

class RuntimeSchedulerEventTimingDelegate {
public:
virtual ~RuntimeSchedulerEventTimingDelegate() = default;

virtual void dispatchPendingEventTimingEntries(
const std::unordered_set<SurfaceId>&
surfaceIdsWithPendingRenderingUpdates) = 0;
};

} // namespace facebook::react
Original file line number Diff line number Diff line change
Expand Up @@ -176,6 +176,7 @@ void RuntimeScheduler_Legacy::callExpiredTasks(jsi::Runtime& runtime) {
}

void RuntimeScheduler_Legacy::scheduleRenderingUpdate(
SurfaceId /*surfaceId*/,
RuntimeSchedulerRenderingUpdate&& renderingUpdate) {
SystraceSection s("RuntimeScheduler::scheduleRenderingUpdate");

Expand All @@ -195,6 +196,11 @@ void RuntimeScheduler_Legacy::setPerformanceEntryReporter(
// No-op in the legacy scheduler
}

void RuntimeScheduler_Legacy::setEventTimingDelegate(
RuntimeSchedulerEventTimingDelegate* /*eventTimingDelegate*/) {
// No-op in the legacy scheduler
}

#pragma mark - Private

void RuntimeScheduler_Legacy::scheduleWorkLoopIfNecessary() {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -122,6 +122,7 @@ class RuntimeScheduler_Legacy final : public RuntimeSchedulerBase {
void callExpiredTasks(jsi::Runtime& runtime) override;

void scheduleRenderingUpdate(
SurfaceId surfaceId,
RuntimeSchedulerRenderingUpdate&& renderingUpdate) override;

void setShadowTreeRevisionConsistencyManager(
Expand All @@ -131,6 +132,9 @@ class RuntimeScheduler_Legacy final : public RuntimeSchedulerBase {
void setPerformanceEntryReporter(
PerformanceEntryReporter* performanceEntryReporter) override;

void setEventTimingDelegate(
RuntimeSchedulerEventTimingDelegate* eventTimingDelegate) override;

private:
std::priority_queue<
std::shared_ptr<Task>,
Expand Down
Loading

0 comments on commit e7ecb2b

Please sign in to comment.