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', + ]); + } } });