From f2df5694f2be141954f22618fd3ad035203241a3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Sebastian=20Markb=C3=A5ge?= Date: Mon, 16 Sep 2024 11:45:50 -0400 Subject: [PATCH] [Fiber] Log Component Renders to Custom Performance Track (#30967) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Stacked on #30960 and #30966. Behind the enableComponentPerformanceTrack flag. This is the first step of performance logging. This logs the start and end time of a component render in the passive effect phase. We use the data we're already tracking on components when the Profiler component or DevTools is active in the Profiling or Dev builds. By backdating this after committing we avoid adding more overhead in the hot path. By only logging things that actually committed, we avoid the costly unwinding of an interrupted render which was hard to maintain in earlier versions. We already have the start time but we don't have the end time. That's because `actualStartTime + actualDuration` isn't enough since `actualDuration` counts the actual CPU time excluding yields and suspending in the render. Instead, we infer the end time to be the start time of the next sibling or the complete time of the whole root if there are no more siblings. We need to pass this down the passive effect tree. This will mean that any overhead and yields are attributed to this component's span. In a follow up, we'll need to start logging these yields to make it clear that this is not part of the component's self-time. In follow ups, I'll do the same for commit phases. We'll also need to log more information about the phases in the top track. We'll also need to filter out more components from the trees that we don't need to highlight like the internal Offscreen components. It also needs polish on colors etc. Currently, I place the components into separate tracks depending on which lane currently committed. That way you can see what was blocking Transitions or Suspense etc. One problem that I've hit with the new performance.measure extensions is that these tracks show up in the order they're used which is not the order of priority that we use. Even when you add fake markers they have to actually be within the performance run since otherwise the calls are noops so it's not enough to do that once. However, I think this visualization is actually not good because these trees end up so large that you can't see any other lanes once you expand one. Therefore, I think in a follow up I'll actually instead switch to a model where Components is a single track regardless of lane since we don't currently have overlap anyway. Then the description about what is actually rendering can be separate lanes. Screenshot 2024-09-15 at 10 55 55 PM Screenshot 2024-09-15 at 10 56 27 PM --- .../src/ReactFiberCommitWork.js | 74 +++++++++++++++-- .../react-reconciler/src/ReactFiberLane.js | 32 ++++++++ .../src/ReactFiberPerformanceTrack.js | 61 ++++++++++++++ .../src/ReactFiberWorkLoop.js | 60 ++++++++------ .../src/ReactProfilerTimer.js | 16 +++- .../src/__tests__/ReactSuspenseList-test.js | 10 +++ .../__tests__/ReactProfiler-test.internal.js | 81 +++++++++++++++---- 7 files changed, 285 insertions(+), 49 deletions(-) create mode 100644 packages/react-reconciler/src/ReactFiberPerformanceTrack.js diff --git a/packages/react-reconciler/src/ReactFiberCommitWork.js b/packages/react-reconciler/src/ReactFiberCommitWork.js index bb37628c2d7a7..bba93bbc0da2e 100644 --- a/packages/react-reconciler/src/ReactFiberCommitWork.js +++ b/packages/react-reconciler/src/ReactFiberCommitWork.js @@ -53,6 +53,7 @@ import { enableUseEffectEventHook, enableLegacyHidden, disableLegacyMode, + enableComponentPerformanceTrack, } from 'shared/ReactFeatureFlags'; import { FunctionComponent, @@ -102,7 +103,9 @@ import { getCommitTime, recordLayoutEffectDuration, startLayoutEffectTimer, + getCompleteTime, } from './ReactProfilerTimer'; +import {logComponentRender} from './ReactFiberPerformanceTrack'; import {ConcurrentMode, NoMode, ProfileMode} from './ReactTypeOfMode'; import {deferHiddenCallbacks} from './ReactFiberClassUpdateQueue'; import { @@ -2648,6 +2651,9 @@ export function commitPassiveMountEffects( finishedWork, committedLanes, committedTransitions, + enableProfilerTimer && enableComponentPerformanceTrack + ? getCompleteTime() + : 0, ); } @@ -2656,17 +2662,41 @@ function recursivelyTraversePassiveMountEffects( parentFiber: Fiber, committedLanes: Lanes, committedTransitions: Array | null, + endTime: number, // Profiling-only. The start time of the next Fiber or root completion. ) { - if (parentFiber.subtreeFlags & PassiveMask) { + if ( + parentFiber.subtreeFlags & PassiveMask || + // If this subtree rendered with profiling this commit, we need to visit it to log it. + (enableProfilerTimer && + enableComponentPerformanceTrack && + parentFiber.actualDuration !== 0 && + (parentFiber.alternate === null || + parentFiber.alternate.child !== parentFiber.child)) + ) { let child = parentFiber.child; while (child !== null) { - commitPassiveMountOnFiber( - root, - child, - committedLanes, - committedTransitions, - ); - child = child.sibling; + if (enableProfilerTimer && enableComponentPerformanceTrack) { + const nextSibling = child.sibling; + commitPassiveMountOnFiber( + root, + child, + committedLanes, + committedTransitions, + nextSibling !== null + ? ((nextSibling.actualStartTime: any): number) + : endTime, + ); + child = nextSibling; + } else { + commitPassiveMountOnFiber( + root, + child, + committedLanes, + committedTransitions, + 0, + ); + child = child.sibling; + } } } } @@ -2676,7 +2706,25 @@ function commitPassiveMountOnFiber( finishedWork: Fiber, committedLanes: Lanes, committedTransitions: Array | null, + endTime: number, // Profiling-only. The start time of the next Fiber or root completion. ): void { + // If this component rendered in Profiling mode (DEV or in Profiler component) then log its + // render time. We do this after the fact in the passive effect to avoid the overhead of this + // getting in the way of the render characteristics and avoid the overhead of unwinding + // uncommitted renders. + if ( + enableProfilerTimer && + enableComponentPerformanceTrack && + (finishedWork.mode & ProfileMode) !== NoMode && + ((finishedWork.actualStartTime: any): number) > 0 + ) { + logComponentRender( + finishedWork, + ((finishedWork.actualStartTime: any): number), + endTime, + ); + } + // When updating this function, also update reconnectPassiveEffects, which does // most of the same things when an offscreen tree goes from hidden -> visible, // or when toggling effects inside a hidden tree. @@ -2690,6 +2738,7 @@ function commitPassiveMountOnFiber( finishedWork, committedLanes, committedTransitions, + endTime, ); if (flags & Passive) { commitHookPassiveMountEffects( @@ -2705,6 +2754,7 @@ function commitPassiveMountOnFiber( finishedWork, committedLanes, committedTransitions, + endTime, ); if (flags & Passive) { if (enableCache) { @@ -2762,6 +2812,7 @@ function commitPassiveMountOnFiber( finishedWork, committedLanes, committedTransitions, + endTime, ); // Only Profilers with work in their subtree will have a Passive effect scheduled. @@ -2809,6 +2860,7 @@ function commitPassiveMountOnFiber( finishedWork, committedLanes, committedTransitions, + endTime, ); if (flags & Passive) { @@ -2834,6 +2886,7 @@ function commitPassiveMountOnFiber( finishedWork, committedLanes, committedTransitions, + endTime, ); } else { if (disableLegacyMode || finishedWork.mode & ConcurrentMode) { @@ -2858,6 +2911,7 @@ function commitPassiveMountOnFiber( finishedWork, committedLanes, committedTransitions, + endTime, ); } } @@ -2870,6 +2924,7 @@ function commitPassiveMountOnFiber( finishedWork, committedLanes, committedTransitions, + endTime, ); } else { // The effects are currently disconnected. Reconnect them, while also @@ -2901,6 +2956,7 @@ function commitPassiveMountOnFiber( finishedWork, committedLanes, committedTransitions, + endTime, ); if (flags & Passive) { // TODO: Pass `current` as argument to this function @@ -2916,6 +2972,7 @@ function commitPassiveMountOnFiber( finishedWork, committedLanes, committedTransitions, + endTime, ); if (flags & Passive) { commitTracingMarkerPassiveMountEffect(finishedWork); @@ -2930,6 +2987,7 @@ function commitPassiveMountOnFiber( finishedWork, committedLanes, committedTransitions, + endTime, ); break; } diff --git a/packages/react-reconciler/src/ReactFiberLane.js b/packages/react-reconciler/src/ReactFiberLane.js index 4338d3af58546..f72174e208555 100644 --- a/packages/react-reconciler/src/ReactFiberLane.js +++ b/packages/react-reconciler/src/ReactFiberLane.js @@ -1143,3 +1143,35 @@ export function clearTransitionsForLanes(root: FiberRoot, lanes: Lane | Lanes) { lanes &= ~lane; } } + +// Used to name the Performance Track +export function getGroupNameOfHighestPriorityLane(lanes: Lanes): string { + if ( + lanes & + (SyncHydrationLane | + SyncLane | + InputContinuousHydrationLane | + InputContinuousLane | + DefaultHydrationLane | + DefaultLane) + ) { + return 'Blocking'; + } + if (lanes & (TransitionHydrationLane | TransitionLanes)) { + return 'Transition'; + } + if (lanes & RetryLanes) { + return 'Suspense'; + } + if ( + lanes & + (SelectiveHydrationLane | + IdleHydrationLane | + IdleLane | + OffscreenLane | + DeferredLane) + ) { + return 'Idle'; + } + return 'Other'; +} diff --git a/packages/react-reconciler/src/ReactFiberPerformanceTrack.js b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js new file mode 100644 index 0000000000000..2058a04e47454 --- /dev/null +++ b/packages/react-reconciler/src/ReactFiberPerformanceTrack.js @@ -0,0 +1,61 @@ +/** + * 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. + * + * @flow + */ + +import type {Fiber} from './ReactInternalTypes'; + +import getComponentNameFromFiber from './getComponentNameFromFiber'; + +import {getGroupNameOfHighestPriorityLane} from './ReactFiberLane'; + +import {enableProfilerTimer} from 'shared/ReactFeatureFlags'; + +const supportsUserTiming = + enableProfilerTimer && + typeof performance !== 'undefined' && + // $FlowFixMe[method-unbinding] + typeof performance.measure === 'function'; + +const TRACK_GROUP = 'Components ⚛'; + +// Reused to avoid thrashing the GC. +const reusableComponentDevToolDetails = { + dataType: 'track-entry', + color: 'primary', + track: 'Blocking', // Lane + trackGroup: TRACK_GROUP, +}; +const reusableComponentOptions = { + start: -0, + end: -0, + detail: { + devtools: reusableComponentDevToolDetails, + }, +}; + +export function setCurrentTrackFromLanes(lanes: number): void { + reusableComponentDevToolDetails.track = + getGroupNameOfHighestPriorityLane(lanes); +} + +export function logComponentRender( + fiber: Fiber, + startTime: number, + endTime: number, +): void { + const name = getComponentNameFromFiber(fiber); + if (name === null) { + // Skip + return; + } + if (supportsUserTiming) { + reusableComponentOptions.start = startTime; + reusableComponentOptions.end = endTime; + performance.measure(name, reusableComponentOptions); + } +} diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.js b/packages/react-reconciler/src/ReactFiberWorkLoop.js index c3f413d0ed0b9..dba089e81f3e0 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.js +++ b/packages/react-reconciler/src/ReactFiberWorkLoop.js @@ -44,6 +44,7 @@ import { disableDefaultPropsExceptForClasses, disableStringRefs, enableSiblingPrerendering, + enableComponentPerformanceTrack, } from 'shared/ReactFeatureFlags'; import ReactSharedInternals from 'shared/ReactSharedInternals'; import is from 'shared/objectIs'; @@ -221,6 +222,7 @@ import { import { markNestedUpdateScheduled, + recordCompleteTime, recordCommitTime, resetNestedUpdateFlag, startProfilerTimer, @@ -228,6 +230,7 @@ import { stopProfilerTimerIfRunningAndRecordIncompleteDuration, syncNestedUpdateFlag, } from './ReactProfilerTimer'; +import {setCurrentTrackFromLanes} from './ReactFiberPerformanceTrack'; // DEV stuff import getComponentNameFromFiber from 'react-reconciler/src/getComponentNameFromFiber'; @@ -1098,6 +1101,12 @@ function finishConcurrentRender( finishedWork: Fiber, lanes: Lanes, ) { + if (enableProfilerTimer && enableComponentPerformanceTrack) { + // Track when we finished the last unit of work, before we actually commit it. + // The commit can be suspended/blocked until we commit it. + recordCompleteTime(); + } + // TODO: The fact that most of these branches are identical suggests that some // of the exit statuses are not best modeled as exit statuses and should be // tracked orthogonally. @@ -1479,6 +1488,10 @@ export function performSyncWorkOnRoot(root: FiberRoot, lanes: Lanes): null { return null; } + if (enableProfilerTimer && enableComponentPerformanceTrack) { + recordCompleteTime(); + } + // We now have a consistent tree. Because this is a sync render, we // will commit it even if something suspended. const finishedWork: Fiber = (root.current.alternate: any); @@ -2824,35 +2837,22 @@ function completeUnitOfWork(unitOfWork: Fiber): void { const returnFiber = completedWork.return; let next; - if (!enableProfilerTimer || (completedWork.mode & ProfileMode) === NoMode) { - if (__DEV__) { - next = runWithFiberInDEV( - completedWork, - completeWork, - current, - completedWork, - entangledRenderLanes, - ); - } else { - next = completeWork(current, completedWork, entangledRenderLanes); - } + startProfilerTimer(completedWork); + if (__DEV__) { + next = runWithFiberInDEV( + completedWork, + completeWork, + current, + completedWork, + entangledRenderLanes, + ); } else { - startProfilerTimer(completedWork); - if (__DEV__) { - next = runWithFiberInDEV( - completedWork, - completeWork, - current, - completedWork, - entangledRenderLanes, - ); - } else { - next = completeWork(current, completedWork, entangledRenderLanes); - } + next = completeWork(current, completedWork, entangledRenderLanes); + } + if (enableProfilerTimer && (completedWork.mode & ProfileMode) !== NoMode) { // Update render duration assuming we didn't error. stopProfilerTimerIfRunningAndRecordIncompleteDuration(completedWork); } - if (next !== null) { // Completing this fiber spawned new work. Work on that next. workInProgress = next; @@ -3104,6 +3104,10 @@ function commitRootImpl( // TODO: Delete all other places that schedule the passive effect callback // They're redundant. if ( + // If this subtree rendered with profiling this commit, we need to visit it to log it. + (enableProfilerTimer && + enableComponentPerformanceTrack && + finishedWork.actualDuration !== 0) || (finishedWork.subtreeFlags & PassiveMask) !== NoFlags || (finishedWork.flags & PassiveMask) !== NoFlags ) { @@ -3494,6 +3498,12 @@ function flushPassiveEffectsImpl() { throw new Error('Cannot flush passive effects while already rendering.'); } + if (enableProfilerTimer && enableComponentPerformanceTrack) { + // We're about to log a lot of profiling for this commit. + // We set this once so we don't have to recompute it for every log. + setCurrentTrackFromLanes(lanes); + } + if (__DEV__) { isFlushingPassiveEffects = true; didScheduleUpdateDuringPassiveEffects = false; diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js index e0c634b190001..bad2f60490d54 100644 --- a/packages/react-reconciler/src/ReactProfilerTimer.js +++ b/packages/react-reconciler/src/ReactProfilerTimer.js @@ -35,6 +35,7 @@ export type ProfilerTimer = { ... }; +let completeTime: number = 0; let commitTime: number = 0; let layoutEffectStartTime: number = -1; let profilerStartTime: number = -1; @@ -83,6 +84,17 @@ function syncNestedUpdateFlag(): void { } } +function getCompleteTime(): number { + return completeTime; +} + +function recordCompleteTime(): void { + if (!enableProfilerTimer) { + return; + } + completeTime = now(); +} + function getCommitTime(): number { return commitTime; } @@ -233,10 +245,12 @@ function transferActualDuration(fiber: Fiber): void { } export { + getCompleteTime, + recordCompleteTime, getCommitTime, + recordCommitTime, isCurrentUpdateNested, markNestedUpdateScheduled, - recordCommitTime, recordLayoutEffectDuration, recordPassiveEffectDuration, resetNestedUpdateFlag, diff --git a/packages/react-reconciler/src/__tests__/ReactSuspenseList-test.js b/packages/react-reconciler/src/__tests__/ReactSuspenseList-test.js index b4a7bcc186b6d..63c398a657b09 100644 --- a/packages/react-reconciler/src/__tests__/ReactSuspenseList-test.js +++ b/packages/react-reconciler/src/__tests__/ReactSuspenseList-test.js @@ -1,3 +1,13 @@ +/** + * 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. + * + * @emails react-core + * @jest-environment node + */ + let React; let ReactNoop; let Scheduler; diff --git a/packages/react/src/__tests__/ReactProfiler-test.internal.js b/packages/react/src/__tests__/ReactProfiler-test.internal.js index c4d72ffee7241..a19e9b1c6d161 100644 --- a/packages/react/src/__tests__/ReactProfiler-test.internal.js +++ b/packages/react/src/__tests__/ReactProfiler-test.internal.js @@ -164,22 +164,73 @@ describe(`onRender`, () => { // TODO: unstable_now is called by more places than just the profiler. // Rewrite this test so it's less fragile. if (gate(flags => flags.enableDeferRootSchedulingToMicrotask)) { - assertLog([ - 'read current time', - 'read current time', - 'read current time', - 'read current time', - ]); + if (gate(flags => flags.enableComponentPerformanceTrack)) { + assertLog([ + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + ]); + } else { + assertLog([ + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + ]); + } } else { - assertLog([ - 'read current time', - 'read current time', - 'read current time', - 'read current time', - 'read current time', - 'read current time', - 'read current time', - ]); + if (gate(flags => flags.enableComponentPerformanceTrack)) { + assertLog([ + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + ]); + } else { + assertLog([ + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + 'read current time', + ]); + } } });