diff --git a/packages/react-dom/src/server/ReactPartialRenderer.js b/packages/react-dom/src/server/ReactPartialRenderer.js index ec26eba2c1d..d0cef9c60a4 100644 --- a/packages/react-dom/src/server/ReactPartialRenderer.js +++ b/packages/react-dom/src/server/ReactPartialRenderer.js @@ -34,6 +34,7 @@ import { REACT_CALL_TYPE, REACT_RETURN_TYPE, REACT_PORTAL_TYPE, + REACT_PROFILER_TYPE, REACT_PROVIDER_TYPE, REACT_CONTEXT_TYPE, } from 'shared/ReactSymbols'; @@ -811,6 +812,7 @@ class ReactDOMServerRenderer { switch (elementType) { case REACT_STRICT_MODE_TYPE: case REACT_ASYNC_MODE_TYPE: + case REACT_PROFILER_TYPE: case REACT_FRAGMENT_TYPE: { const nextChildren = toArray( ((nextChild: any): ReactElement).props.children, diff --git a/packages/react-is/src/ReactIs.js b/packages/react-is/src/ReactIs.js index 4418759a9b2..e94599474dc 100644 --- a/packages/react-is/src/ReactIs.js +++ b/packages/react-is/src/ReactIs.js @@ -16,6 +16,7 @@ import { REACT_FORWARD_REF_TYPE, REACT_FRAGMENT_TYPE, REACT_PORTAL_TYPE, + REACT_PROFILER_TYPE, REACT_PROVIDER_TYPE, REACT_STRICT_MODE_TYPE, } from 'shared/ReactSymbols'; @@ -32,6 +33,7 @@ export function typeOf(object: any) { switch (type) { case REACT_ASYNC_MODE_TYPE: case REACT_FRAGMENT_TYPE: + case REACT_PROFILER_TYPE: case REACT_STRICT_MODE_TYPE: return type; default: @@ -60,6 +62,7 @@ export const ContextProvider = REACT_PROVIDER_TYPE; export const Element = REACT_ELEMENT_TYPE; export const ForwardRef = REACT_FORWARD_REF_TYPE; export const Fragment = REACT_FRAGMENT_TYPE; +export const Profiler = REACT_PROFILER_TYPE; export const Portal = REACT_PORTAL_TYPE; export const StrictMode = REACT_STRICT_MODE_TYPE; @@ -87,6 +90,9 @@ export function isForwardRef(object: any) { export function isFragment(object: any) { return typeOf(object) === REACT_FRAGMENT_TYPE; } +export function isProfiler(object: any) { + return typeOf(object) === REACT_PROFILER_TYPE; +} export function isPortal(object: any) { return typeOf(object) === REACT_PORTAL_TYPE; } diff --git a/packages/react-is/src/__tests__/ReactIs-test.js b/packages/react-is/src/__tests__/ReactIs-test.js index e4ce5074b1a..04c7cec745d 100644 --- a/packages/react-is/src/__tests__/ReactIs-test.js +++ b/packages/react-is/src/__tests__/ReactIs-test.js @@ -145,4 +145,18 @@ describe('ReactIs', () => { expect(ReactIs.isStrictMode()).toBe(false); expect(ReactIs.isStrictMode(
)).toBe(false); }); + + it('should identify profile root', () => { + expect( + ReactIs.typeOf(), + ).toBe(ReactIs.Profiler); + expect( + ReactIs.isProfiler( + , + ), + ).toBe(true); + expect(ReactIs.isProfiler({type: ReactIs.unstable_Profiler})).toBe(false); + expect(ReactIs.isProfiler()).toBe(false); + expect(ReactIs.isProfiler(
)).toBe(false); + }); }); diff --git a/packages/react-reconciler/src/ReactFiber.js b/packages/react-reconciler/src/ReactFiber.js index 393cecb5276..51c4d52fe57 100644 --- a/packages/react-reconciler/src/ReactFiber.js +++ b/packages/react-reconciler/src/ReactFiber.js @@ -15,6 +15,7 @@ import type {ExpirationTime} from './ReactFiberExpirationTime'; import type {UpdateQueue} from './ReactUpdateQueue'; import invariant from 'fbjs/lib/invariant'; +import {enableProfilerTimer} from 'shared/ReactFeatureFlags'; import {NoEffect} from 'shared/ReactTypeOfSideEffect'; import { IndeterminateComponent, @@ -30,17 +31,19 @@ import { Mode, ContextProvider, ContextConsumer, + Profiler, } from 'shared/ReactTypeOfWork'; import getComponentName from 'shared/getComponentName'; import {NoWork} from './ReactFiberExpirationTime'; -import {NoContext, AsyncMode, StrictMode} from './ReactTypeOfMode'; +import {NoContext, AsyncMode, ProfileMode, StrictMode} from './ReactTypeOfMode'; import { REACT_FORWARD_REF_TYPE, REACT_FRAGMENT_TYPE, REACT_RETURN_TYPE, REACT_CALL_TYPE, REACT_STRICT_MODE_TYPE, + REACT_PROFILER_TYPE, REACT_PROVIDER_TYPE, REACT_CONTEXT_TYPE, REACT_ASYNC_MODE_TYPE, @@ -150,6 +153,10 @@ export type Fiber = {| // memory if we need to. alternate: Fiber | null, + // Profiling metrics + selfBaseTime?: number, + treeBaseTime?: number, + // Conceptual aliases // workInProgress : Fiber -> alternate The alternate used for reuse happens // to be the same as work in progress. @@ -204,6 +211,11 @@ function FiberNode( this.alternate = null; + if (enableProfilerTimer) { + this.selfBaseTime = 0; + this.treeBaseTime = 0; + } + if (__DEV__) { this._debugID = debugCounter++; this._debugSource = null; @@ -298,6 +310,11 @@ export function createWorkInProgress( workInProgress.index = current.index; workInProgress.ref = current.ref; + if (enableProfilerTimer) { + workInProgress.selfBaseTime = current.selfBaseTime; + workInProgress.treeBaseTime = current.treeBaseTime; + } + return workInProgress; } @@ -343,6 +360,8 @@ export function createFiberFromElement( fiberTag = Mode; mode |= StrictMode; break; + case REACT_PROFILER_TYPE: + return createFiberFromProfiler(pendingProps, mode, expirationTime, key); case REACT_CALL_TYPE: fiberTag = CallComponent; break; @@ -440,6 +459,35 @@ export function createFiberFromFragment( return fiber; } +export function createFiberFromProfiler( + pendingProps: any, + mode: TypeOfMode, + expirationTime: ExpirationTime, + key: null | string, +): Fiber { + if (__DEV__) { + if ( + typeof pendingProps.id !== 'string' || + typeof pendingProps.onRender !== 'function' + ) { + invariant( + false, + 'Profiler must specify an "id" string and "onRender" function as props', + ); + } + } + + const fiber = createFiber(Profiler, pendingProps, key, mode | ProfileMode); + fiber.type = REACT_PROFILER_TYPE; + fiber.expirationTime = expirationTime; + fiber.stateNode = { + duration: 0, + startTime: 0, + }; + + return fiber; +} + export function createFiberFromText( content: string, mode: TypeOfMode, @@ -509,6 +557,10 @@ export function assignFiberPropertiesInDEV( target.lastEffect = source.lastEffect; target.expirationTime = source.expirationTime; target.alternate = source.alternate; + if (enableProfilerTimer) { + target.selfBaseTime = source.selfBaseTime; + target.treeBaseTime = source.treeBaseTime; + } target._debugID = source._debugID; target._debugSource = source._debugSource; target._debugOwner = source._debugOwner; diff --git a/packages/react-reconciler/src/ReactFiberBeginWork.js b/packages/react-reconciler/src/ReactFiberBeginWork.js index 5aa7ffc446c..2c80e26ffb5 100644 --- a/packages/react-reconciler/src/ReactFiberBeginWork.js +++ b/packages/react-reconciler/src/ReactFiberBeginWork.js @@ -16,6 +16,7 @@ import type {NewContext} from './ReactFiberNewContext'; import type {HydrationContext} from './ReactFiberHydrationContext'; import type {FiberRoot} from './ReactFiberRoot'; import type {ExpirationTime} from './ReactFiberExpirationTime'; +import type {ProfilerTimer} from './ReactProfilerTimer'; import checkPropTypes from 'prop-types/checkPropTypes'; import { @@ -34,6 +35,7 @@ import { Mode, ContextProvider, ContextConsumer, + Profiler, } from 'shared/ReactTypeOfWork'; import { NoEffect, @@ -42,12 +44,14 @@ import { ContentReset, Ref, DidCapture, + Update, } from 'shared/ReactTypeOfSideEffect'; import {ReactCurrentOwner} from 'shared/ReactGlobalSharedState'; import { enableGetDerivedStateFromCatch, debugRenderPhaseSideEffects, debugRenderPhaseSideEffectsForStrictMode, + enableProfilerTimer, } from 'shared/ReactFeatureFlags'; import invariant from 'fbjs/lib/invariant'; import getComponentName from 'shared/getComponentName'; @@ -88,6 +92,7 @@ export default function( hydrationContext: HydrationContext, scheduleWork: (fiber: Fiber, expirationTime: ExpirationTime) => void, computeExpirationForFiber: (fiber: Fiber) => ExpirationTime, + profilerTimer: ProfilerTimer, ) { const {shouldSetTextContent, shouldDeprioritizeSubtree} = config; @@ -95,6 +100,11 @@ export default function( const {pushProvider} = newContext; + const { + markActualRenderTimeStarted, + stopBaseRenderTimerIfRunning, + } = profilerTimer; + const { getMaskedContext, getUnmaskedContext, @@ -215,6 +225,25 @@ export default function( return workInProgress.child; } + function updateProfiler(current, workInProgress) { + const nextProps = workInProgress.pendingProps; + if (enableProfilerTimer) { + // Start render timer here and push start time onto queue + markActualRenderTimeStarted(workInProgress); + + // Let the "complete" phase know to stop the timer, + // And the scheduler to record the measured time. + workInProgress.effectTag |= Update; + } + if (workInProgress.memoizedProps === nextProps) { + return bailoutOnAlreadyFinishedWork(current, workInProgress); + } + const nextChildren = nextProps.children; + reconcileChildren(current, workInProgress, nextChildren); + memoizeProps(workInProgress, nextProps); + return workInProgress.child; + } + function markRef(current: Fiber | null, workInProgress: Fiber) { const ref = workInProgress.ref; if ( @@ -344,6 +373,10 @@ export default function( // the new API. // TODO: Warn in a future release. nextChildren = null; + + if (enableProfilerTimer) { + stopBaseRenderTimerIfRunning(); + } } else { if (__DEV__) { ReactDebugCurrentFiber.setCurrentPhase('render'); @@ -1054,6 +1087,11 @@ export default function( ): Fiber | null { cancelWorkTimer(workInProgress); + if (enableProfilerTimer) { + // Don't update "base" render times for bailouts. + stopBaseRenderTimerIfRunning(); + } + // TODO: We should ideally be able to bail out early if the children have no // more work to do. However, since we don't have a separation of this // Fiber's priority and its children yet - we don't know without doing lots @@ -1075,6 +1113,11 @@ export default function( function bailoutOnLowPriority(current, workInProgress) { cancelWorkTimer(workInProgress); + if (enableProfilerTimer) { + // Don't update "base" render times for bailouts. + stopBaseRenderTimerIfRunning(); + } + // TODO: Handle HostComponent tags here as well and call pushHostContext()? // See PR 8590 discussion for context switch (workInProgress.tag) { @@ -1093,6 +1136,11 @@ export default function( case ContextProvider: pushProvider(workInProgress); break; + case Profiler: + if (enableProfilerTimer) { + markActualRenderTimeStarted(workInProgress); + } + break; } // TODO: What if this is currently in progress? // How can that happen? How is this not being cloned? @@ -1173,6 +1221,8 @@ export default function( return updateFragment(current, workInProgress); case Mode: return updateMode(current, workInProgress); + case Profiler: + return updateProfiler(current, workInProgress); case ContextProvider: return updateContextProvider( current, diff --git a/packages/react-reconciler/src/ReactFiberCommitWork.js b/packages/react-reconciler/src/ReactFiberCommitWork.js index a3754902975..686a49219be 100644 --- a/packages/react-reconciler/src/ReactFiberCommitWork.js +++ b/packages/react-reconciler/src/ReactFiberCommitWork.js @@ -17,6 +17,7 @@ import { enableMutatingReconciler, enableNoopReconciler, enablePersistentReconciler, + enableProfilerTimer, } from 'shared/ReactFeatureFlags'; import { ClassComponent, @@ -25,13 +26,14 @@ import { HostText, HostPortal, CallComponent, + Profiler, } from 'shared/ReactTypeOfWork'; import ReactErrorUtils from 'shared/ReactErrorUtils'; import { - Placement, - Update, ContentReset, + Placement, Snapshot, + Update, } from 'shared/ReactTypeOfSideEffect'; import {commitUpdateQueue} from './ReactUpdateQueue'; import invariant from 'fbjs/lib/invariant'; @@ -308,6 +310,10 @@ export default function( // We have no life-cycles associated with portals. return; } + case Profiler: { + // We have no life-cycles associated with Profiler. + return; + } default: { invariant( false, @@ -814,6 +820,22 @@ export default function( case HostRoot: { return; } + case Profiler: { + if (enableProfilerTimer) { + const onRender = finishedWork.memoizedProps.onRender; + onRender( + finishedWork.memoizedProps.id, + current === null ? 'mount' : 'update', + finishedWork.stateNode.duration, + finishedWork.treeBaseTime, + ); + + // Reset actualTime after successful commit. + // By default, we append to this time to account for errors and pauses. + finishedWork.stateNode.duration = 0; + } + return; + } default: { invariant( false, diff --git a/packages/react-reconciler/src/ReactFiberCompleteWork.js b/packages/react-reconciler/src/ReactFiberCompleteWork.js index aec3bc17c6f..e9752e38da4 100644 --- a/packages/react-reconciler/src/ReactFiberCompleteWork.js +++ b/packages/react-reconciler/src/ReactFiberCompleteWork.js @@ -15,11 +15,13 @@ import type {LegacyContext} from './ReactFiberContext'; import type {NewContext} from './ReactFiberNewContext'; import type {HydrationContext} from './ReactFiberHydrationContext'; import type {FiberRoot} from './ReactFiberRoot'; +import type {ProfilerTimer} from './ReactProfilerTimer'; import { enableMutatingReconciler, enablePersistentReconciler, enableNoopReconciler, + enableProfilerTimer, } from 'shared/ReactFeatureFlags'; import { IndeterminateComponent, @@ -37,6 +39,7 @@ import { ForwardRef, Fragment, Mode, + Profiler, } from 'shared/ReactTypeOfWork'; import {Placement, Ref, Update} from 'shared/ReactTypeOfSideEffect'; import invariant from 'fbjs/lib/invariant'; @@ -49,6 +52,7 @@ export default function( legacyContext: LegacyContext, newContext: NewContext, hydrationContext: HydrationContext, + profilerTimer: ProfilerTimer, ) { const { createInstance, @@ -67,6 +71,8 @@ export default function( popHostContainer, } = hostContext; + const {recordElapsedActualRenderTime} = profilerTimer; + const { popContextProvider: popLegacyContextProvider, popTopLevelContextObject: popTopLevelLegacyContextObject, @@ -591,6 +597,11 @@ export default function( return null; case Mode: return null; + case Profiler: + if (enableProfilerTimer) { + recordElapsedActualRenderTime(workInProgress); + } + return null; case HostPortal: popHostContainer(workInProgress); updateHostContainer(workInProgress); diff --git a/packages/react-reconciler/src/ReactFiberScheduler.js b/packages/react-reconciler/src/ReactFiberScheduler.js index 1a9846b0bdb..fde57fd5a42 100644 --- a/packages/react-reconciler/src/ReactFiberScheduler.js +++ b/packages/react-reconciler/src/ReactFiberScheduler.js @@ -40,10 +40,12 @@ import { HostPortal, } from 'shared/ReactTypeOfWork'; import { + enableProfilerTimer, enableUserTimingAPI, - warnAboutDeprecatedLifecycles, replayFailedUnitOfWorkWithInvokeGuardedCallback, + warnAboutDeprecatedLifecycles, } from 'shared/ReactFeatureFlags'; +import {createProfilerTimer} from './ReactProfilerTimer'; import getComponentName from 'shared/getComponentName'; import invariant from 'fbjs/lib/invariant'; import warning from 'fbjs/lib/warning'; @@ -85,7 +87,7 @@ import { expirationTimeToMs, computeExpirationBucket, } from './ReactFiberExpirationTime'; -import {AsyncMode} from './ReactTypeOfMode'; +import {AsyncMode, ProfileMode} from './ReactTypeOfMode'; import ReactFiberLegacyContext from './ReactFiberContext'; import ReactFiberNewContext from './ReactFiberNewContext'; import {enqueueUpdate, resetCurrentlyProcessingQueue} from './ReactUpdateQueue'; @@ -158,10 +160,18 @@ if (__DEV__) { export default function( config: HostConfig, ) { + const { + now, + scheduleDeferredCallback, + cancelDeferredCallback, + prepareForCommit, + resetAfterCommit, + } = config; const stack = ReactFiberStack(); const hostContext = ReactFiberHostContext(config, stack); const legacyContext = ReactFiberLegacyContext(stack); const newContext = ReactFiberNewContext(stack); + const profilerTimer = createProfilerTimer(now); const {popHostContext, popHostContainer} = hostContext; const { popTopLevelContextObject: popTopLevelLegacyContextObject, @@ -179,6 +189,7 @@ export default function( hydrationContext, scheduleWork, computeExpirationForFiber, + profilerTimer, ); const {completeWork} = ReactFiberCompleteWork( config, @@ -186,6 +197,7 @@ export default function( legacyContext, newContext, hydrationContext, + profilerTimer, ); const { throwException, @@ -194,6 +206,7 @@ export default function( createRootErrorUpdate, createClassErrorUpdate, } = ReactFiberUnwindWork( + config, hostContext, legacyContext, newContext, @@ -201,6 +214,7 @@ export default function( markLegacyErrorBoundaryAsFailed, isAlreadyFailedLegacyErrorBoundary, onUncaughtError, + profilerTimer, ); const { commitBeforeMutationLifeCycles, @@ -219,13 +233,16 @@ export default function( markLegacyErrorBoundaryAsFailed, recalculateCurrentTime, ); + const { - now, - scheduleDeferredCallback, - cancelDeferredCallback, - prepareForCommit, - resetAfterCommit, - } = config; + checkActualRenderTimeStackEmpty, + pauseActualRenderTimerIfRunning, + recordElapsedBaseRenderTimeIfRunning, + resetActualRenderTimer, + resumeActualRenderTimerIfPaused, + startBaseRenderTimer, + stopBaseRenderTimerIfRunning, + } = profilerTimer; // Represents the current time in ms. const originalStartTimeMs = now(); @@ -305,6 +322,11 @@ export default function( originalReplayError = null; if (hasCaughtError()) { clearCaughtError(); + + if (enableProfilerTimer) { + // Stop "base" render timer again (after the re-thrown error). + stopBaseRenderTimerIfRunning(); + } } else { // If the begin phase did not fail the second time, set this pointer // back to the original value. @@ -645,6 +667,13 @@ export default function( } } + if (enableProfilerTimer) { + if (__DEV__) { + checkActualRenderTimeStackEmpty(); + } + resetActualRenderTimer(); + } + isCommitting = false; isWorking = false; stopCommitLifeCyclesTimer(); @@ -690,17 +719,36 @@ export default function( // TODO: Calls need to visit stateNode // Bubble up the earliest expiration time. - let child = workInProgress.child; - while (child !== null) { - if ( - child.expirationTime !== NoWork && - (newExpirationTime === NoWork || - newExpirationTime > child.expirationTime) - ) { - newExpirationTime = child.expirationTime; + // (And "base" render timers if that feature flag is enabled) + if (enableProfilerTimer && workInProgress.mode & ProfileMode) { + let treeBaseTime = workInProgress.selfBaseTime; + let child = workInProgress.child; + while (child !== null) { + treeBaseTime += child.treeBaseTime; + if ( + child.expirationTime !== NoWork && + (newExpirationTime === NoWork || + newExpirationTime > child.expirationTime) + ) { + newExpirationTime = child.expirationTime; + } + child = child.sibling; + } + workInProgress.treeBaseTime = treeBaseTime; + } else { + let child = workInProgress.child; + while (child !== null) { + if ( + child.expirationTime !== NoWork && + (newExpirationTime === NoWork || + newExpirationTime > child.expirationTime) + ) { + newExpirationTime = child.expirationTime; + } + child = child.sibling; } - child = child.sibling; } + workInProgress.expirationTime = newExpirationTime; } @@ -875,7 +923,19 @@ export default function( workInProgress, ); } - let next = beginWork(current, workInProgress, nextRenderExpirationTime); + + let next; + if (enableProfilerTimer) { + startBaseRenderTimer(); + next = beginWork(current, workInProgress, nextRenderExpirationTime); + + // Update "base" time if the render wasn't bailed out on. + recordElapsedBaseRenderTimeIfRunning(workInProgress); + stopBaseRenderTimerIfRunning(); + } else { + next = beginWork(current, workInProgress, nextRenderExpirationTime); + } + if (__DEV__) { ReactDebugCurrentFiber.resetCurrentFiber(); if (isReplayingFailedUnitOfWork) { @@ -911,6 +971,12 @@ export default function( while (nextUnitOfWork !== null && !shouldYield()) { nextUnitOfWork = performUnitOfWork(nextUnitOfWork); } + + if (enableProfilerTimer) { + // If we didn't finish, pause the "actual" render timer. + // We'll restart it when we resume work. + pauseActualRenderTimerIfRunning(); + } } } @@ -953,6 +1019,11 @@ export default function( try { workLoop(isAsync); } catch (thrownValue) { + if (enableProfilerTimer) { + // Stop "base" render timer in the event of an error. + stopBaseRenderTimerIfRunning(); + } + if (nextUnitOfWork === null) { // This is a fatal error. didFatal = true; @@ -1516,6 +1587,10 @@ export default function( // the deadline. findHighestPriorityRoot(); + if (enableProfilerTimer) { + resumeActualRenderTimerIfPaused(); + } + if (enableUserTimingAPI && deadline !== null) { const didExpire = nextFlushedExpirationTime < recalculateCurrentTime(); const timeout = expirationTimeToMs(nextFlushedExpirationTime); @@ -1661,6 +1736,12 @@ export default function( // There's no time left. Mark this root as complete. We'll come // back and commit it later. root.finishedWork = finishedWork; + + if (enableProfilerTimer) { + // If we didn't finish, pause the "actual" render timer. + // We'll restart it when we resume work. + pauseActualRenderTimerIfRunning(); + } } } } diff --git a/packages/react-reconciler/src/ReactFiberUnwindWork.js b/packages/react-reconciler/src/ReactFiberUnwindWork.js index 05a8a1856d0..3337f02fcd5 100644 --- a/packages/react-reconciler/src/ReactFiberUnwindWork.js +++ b/packages/react-reconciler/src/ReactFiberUnwindWork.js @@ -7,12 +7,14 @@ * @flow */ +import type {HostConfig} from 'react-reconciler'; import type {Fiber} from './ReactFiber'; import type {ExpirationTime} from './ReactFiberExpirationTime'; import type {HostContext} from './ReactFiberHostContext'; import type {LegacyContext} from './ReactFiberContext'; import type {NewContext} from './ReactFiberNewContext'; import type {CapturedValue} from './ReactCapturedValue'; +import type {ProfilerTimer} from './ReactProfilerTimer'; import type {Update} from './ReactUpdateQueue'; import {createCapturedValue} from './ReactCapturedValue'; @@ -29,17 +31,21 @@ import { HostComponent, HostPortal, ContextProvider, + Profiler, } from 'shared/ReactTypeOfWork'; import { - NoEffect, DidCapture, Incomplete, + NoEffect, ShouldCapture, } from 'shared/ReactTypeOfSideEffect'; +import { + enableGetDerivedStateFromCatch, + enableProfilerTimer, +} from 'shared/ReactFeatureFlags'; -import {enableGetDerivedStateFromCatch} from 'shared/ReactFeatureFlags'; - -export default function( +export default function( + config: HostConfig, hostContext: HostContext, legacyContext: LegacyContext, newContext: NewContext, @@ -51,6 +57,7 @@ export default function( markLegacyErrorBoundaryAsFailed: (instance: mixed) => void, isAlreadyFailedLegacyErrorBoundary: (instance: mixed) => boolean, onUncaughtError: (error: mixed) => void, + profilerTimer: ProfilerTimer, ) { const {popHostContainer, popHostContext} = hostContext; const { @@ -58,6 +65,10 @@ export default function( popTopLevelContextObject: popTopLevelLegacyContextObject, } = legacyContext; const {popProvider} = newContext; + const { + resumeActualRenderTimerIfPaused, + recordElapsedActualRenderTime, + } = profilerTimer; function createRootErrorUpdate( fiber: Fiber, @@ -236,6 +247,13 @@ export default function( case ContextProvider: popProvider(interruptedWork); break; + case Profiler: + if (enableProfilerTimer) { + // Resume in case we're picking up on work that was paused. + resumeActualRenderTimerIfPaused(); + recordElapsedActualRenderTime(interruptedWork); + } + break; default: break; } diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js new file mode 100644 index 00000000000..d192bc1e91d --- /dev/null +++ b/packages/react-reconciler/src/ReactProfilerTimer.js @@ -0,0 +1,144 @@ +/** + * Copyright (c) 2013-present, Facebook, Inc. + * + * 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 './ReactFiber'; + +import {enableProfilerTimer} from 'shared/ReactFeatureFlags'; + +import warning from 'fbjs/lib/warning'; + +/** + * The "actual" render time is total time required to render the descendants of a Profiler component. + * This time is stored as a stack, since Profilers can be nested. + * This time is started during the "begin" phase and stopped during the "complete" phase. + * It is paused (and accumulated) in the event of an interruption or an aborted render. + */ + +export type ProfilerTimer = { + checkActualRenderTimeStackEmpty(): void, + markActualRenderTimeStarted(fiber: Fiber): void, + pauseActualRenderTimerIfRunning(): void, + recordElapsedActualRenderTime(fiber: Fiber): void, + resetActualRenderTimer(): void, + resumeActualRenderTimerIfPaused(): void, + recordElapsedBaseRenderTimeIfRunning(fiber: Fiber): void, + startBaseRenderTimer(): void, + stopBaseRenderTimerIfRunning(): void, +}; + +export function createProfilerTimer(now: () => number): ProfilerTimer { + let fiberStack: Array; + + if (__DEV__) { + fiberStack = []; + } + + let timerPausedAt: number = 0; + let totalElapsedPauseTime: number = 0; + + function checkActualRenderTimeStackEmpty(): void { + if (__DEV__) { + warning( + fiberStack.length === 0, + 'Expected an empty stack. Something was not reset properly.', + ); + } + } + + function markActualRenderTimeStarted(fiber: Fiber): void { + if (__DEV__) { + fiberStack.push(fiber); + } + fiber.stateNode.startTime = now() - totalElapsedPauseTime; + } + + function pauseActualRenderTimerIfRunning(): void { + if (timerPausedAt === 0) { + timerPausedAt = now(); + } + } + + function recordElapsedActualRenderTime(fiber: Fiber): void { + if (__DEV__) { + warning(fiber === fiberStack.pop(), 'Unexpected Fiber popped.'); + } + fiber.stateNode.duration += + now() - totalElapsedPauseTime - fiber.stateNode.startTime; + } + + function resetActualRenderTimer(): void { + totalElapsedPauseTime = 0; + } + + function resumeActualRenderTimerIfPaused(): void { + if (timerPausedAt > 0) { + totalElapsedPauseTime += now() - timerPausedAt; + timerPausedAt = 0; + } + } + + /** + * The "base" render time is the duration of the “begin” phase of work for a particular fiber. + * This time is measured and stored on each fiber. + * The time for all sibling fibers are accumulated and stored on their parent during the "complete" phase. + * If a fiber bails out (sCU false) then its "base" timer is cancelled and the fiber is not updated. + */ + + let baseStartTime: number = -1; + + function recordElapsedBaseRenderTimeIfRunning(fiber: Fiber): void { + if (baseStartTime !== -1) { + fiber.selfBaseTime = now() - baseStartTime; + } + } + + function startBaseRenderTimer(): void { + if (__DEV__) { + if (baseStartTime !== -1) { + warning( + false, + 'Cannot start base timer that is already running. ' + + 'This error is likely caused by a bug in React. ' + + 'Please file an issue.', + ); + } + } + baseStartTime = now(); + } + + function stopBaseRenderTimerIfRunning(): void { + baseStartTime = -1; + } + + if (enableProfilerTimer) { + return { + checkActualRenderTimeStackEmpty, + markActualRenderTimeStarted, + pauseActualRenderTimerIfRunning, + recordElapsedActualRenderTime, + resetActualRenderTimer, + resumeActualRenderTimerIfPaused, + recordElapsedBaseRenderTimeIfRunning, + startBaseRenderTimer, + stopBaseRenderTimerIfRunning, + }; + } else { + return { + checkActualRenderTimeStackEmpty(): void {}, + markActualRenderTimeStarted(fiber: Fiber): void {}, + pauseActualRenderTimerIfRunning(): void {}, + recordElapsedActualRenderTime(fiber: Fiber): void {}, + resetActualRenderTimer(): void {}, + resumeActualRenderTimerIfPaused(): void {}, + recordElapsedBaseRenderTimeIfRunning(fiber: Fiber): void {}, + startBaseRenderTimer(): void {}, + stopBaseRenderTimerIfRunning(): void {}, + }; + } +} diff --git a/packages/react-reconciler/src/ReactTypeOfMode.js b/packages/react-reconciler/src/ReactTypeOfMode.js index e93b4d984de..4bf9da2ec8f 100644 --- a/packages/react-reconciler/src/ReactTypeOfMode.js +++ b/packages/react-reconciler/src/ReactTypeOfMode.js @@ -9,6 +9,7 @@ export type TypeOfMode = number; -export const NoContext = 0b00; -export const AsyncMode = 0b01; -export const StrictMode = 0b10; +export const NoContext = 0b000; +export const AsyncMode = 0b001; +export const StrictMode = 0b010; +export const ProfileMode = 0b100; diff --git a/packages/react-reconciler/src/__tests__/ReactIncrementalPerf-test.internal.js b/packages/react-reconciler/src/__tests__/ReactIncrementalPerf-test.internal.js index d5dc2b6f6ab..1e33804d12f 100644 --- a/packages/react-reconciler/src/__tests__/ReactIncrementalPerf-test.internal.js +++ b/packages/react-reconciler/src/__tests__/ReactIncrementalPerf-test.internal.js @@ -187,15 +187,17 @@ describe('ReactDebugFiberPerf', () => { expect(getFlameChart()).toMatchSnapshot(); }); - it('does not include StrictMode or AsyncMode components in measurements', () => { + it('does not include AsyncMode, StrictMode, or Profiler components in measurements', () => { ReactNoop.render( - - - - - - - , + + + + + + + + + , ); addComment('Mount'); ReactNoop.flush(); diff --git a/packages/react-reconciler/src/__tests__/__snapshots__/ReactIncrementalPerf-test.internal.js.snap b/packages/react-reconciler/src/__tests__/__snapshots__/ReactIncrementalPerf-test.internal.js.snap index ffe5706d1c0..119c55154e3 100644 --- a/packages/react-reconciler/src/__tests__/__snapshots__/ReactIncrementalPerf-test.internal.js.snap +++ b/packages/react-reconciler/src/__tests__/__snapshots__/ReactIncrementalPerf-test.internal.js.snap @@ -91,13 +91,14 @@ exports[`ReactDebugFiberPerf deduplicates lifecycle names during commit to reduc " `; -exports[`ReactDebugFiberPerf does not include StrictMode or AsyncMode components in measurements 1`] = ` +exports[`ReactDebugFiberPerf does not include AsyncMode, StrictMode, or Profiler components in measurements 1`] = ` "⚛ (Waiting for async callback... will force flush in 5230 ms) // Mount ⚛ (React Tree Reconciliation: Completed Root) - ⚛ Parent [mount] - ⚛ Child [mount] + ⚛ Profiler(test) [mount] + ⚛ Parent [mount] + ⚛ Child [mount] ⚛ (Committing Changes) ⚛ (Committing Snapshot Effects: 0 Total) diff --git a/packages/react-test-renderer/src/ReactTestRenderer.js b/packages/react-test-renderer/src/ReactTestRenderer.js index d3ef7aff4fc..561aed6c584 100644 --- a/packages/react-test-renderer/src/ReactTestRenderer.js +++ b/packages/react-test-renderer/src/ReactTestRenderer.js @@ -27,6 +27,7 @@ import { ContextProvider, Mode, ForwardRef, + Profiler, } from 'shared/ReactTypeOfWork'; import invariant from 'fbjs/lib/invariant'; @@ -119,7 +120,7 @@ function removeChild( } // Current virtual time -let currentTime: number = 0; +let nowImplementation = () => 0; let scheduledCallback: ((deadline: Deadline) => mixed) | null = null; let yieldedValues: Array | null = null; @@ -221,9 +222,9 @@ const TestRenderer = ReactFiberReconciler({ getPublicInstance, - now(): number { - return currentTime; - }, + // This approach enables `now` to be mocked by tests, + // Even after the reconciler has initialized and read host config values. + now: () => nowImplementation(), mutation: { commitUpdate( @@ -383,6 +384,7 @@ function toTree(node: ?Fiber) { case ContextProvider: case ContextConsumer: case Mode: + case Profiler: case ForwardRef: return childrenToTree(node.child); default: @@ -486,6 +488,7 @@ class ReactTestInstance { case ContextProvider: case ContextConsumer: case Mode: + case Profiler: descend = true; break; default: @@ -737,7 +740,11 @@ const ReactTestRendererFiber = { } return TestRenderer.getPublicRootInstance(root); }, - unstable_flushSync: TestRenderer.flushSync, + unstable_flushSync(fn: Function) { + yieldedValues = []; + TestRenderer.flushSync(fn); + return yieldedValues; + }, }; Object.defineProperty( @@ -761,6 +768,10 @@ const ReactTestRendererFiber = { /* eslint-disable camelcase */ unstable_batchedUpdates: batchedUpdates, /* eslint-enable camelcase */ + + unstable_setNowImplementation(implementation: () => number): void { + nowImplementation = implementation; + }, }; export default ReactTestRendererFiber; diff --git a/packages/react-test-renderer/src/__tests__/ReactShallowRenderer-test.js b/packages/react-test-renderer/src/__tests__/ReactShallowRenderer-test.js index b20f316d9ed..ce62bba2807 100644 --- a/packages/react-test-renderer/src/__tests__/ReactShallowRenderer-test.js +++ b/packages/react-test-renderer/src/__tests__/ReactShallowRenderer-test.js @@ -230,6 +230,32 @@ describe('ReactShallowRenderer', () => { ]); }); + it('should handle Profiler', () => { + class SomeComponent extends React.Component { + render() { + return ( + +
+ + +
+
+ ); + } + } + + const shallowRenderer = createRenderer(); + const result = shallowRenderer.render(); + + expect(result.type).toBe(React.unstable_Profiler); + expect(result.props.children).toEqual( +
+ + +
, + ); + }); + it('should enable shouldComponentUpdate to prevent a re-render', () => { let renderCounter = 0; class SimpleComponent extends React.Component { diff --git a/packages/react-test-renderer/src/__tests__/ReactTestRendererTraversal-test.js b/packages/react-test-renderer/src/__tests__/ReactTestRendererTraversal-test.js index e6f3909b0b4..cefef5657c8 100644 --- a/packages/react-test-renderer/src/__tests__/ReactTestRendererTraversal-test.js +++ b/packages/react-test-renderer/src/__tests__/ReactTestRendererTraversal-test.js @@ -37,7 +37,9 @@ describe('ReactTestRendererTraversal', () => { - + {}}> + + ); diff --git a/packages/react/src/React.js b/packages/react/src/React.js index d3a52cf61c4..d4740406116 100644 --- a/packages/react/src/React.js +++ b/packages/react/src/React.js @@ -8,9 +8,10 @@ import assign from 'object-assign'; import ReactVersion from 'shared/ReactVersion'; import { + REACT_ASYNC_MODE_TYPE, REACT_FRAGMENT_TYPE, + REACT_PROFILER_TYPE, REACT_STRICT_MODE_TYPE, - REACT_ASYNC_MODE_TYPE, } from 'shared/ReactSymbols'; import {Component, PureComponent} from './ReactBaseClasses'; @@ -51,6 +52,7 @@ const React = { Fragment: REACT_FRAGMENT_TYPE, StrictMode: REACT_STRICT_MODE_TYPE, unstable_AsyncMode: REACT_ASYNC_MODE_TYPE, + unstable_Profiler: REACT_PROFILER_TYPE, createElement: __DEV__ ? createElementWithValidation : createElement, cloneElement: __DEV__ ? cloneElementWithValidation : cloneElement, diff --git a/packages/react/src/__tests__/ReactProfiler-test.internal.js b/packages/react/src/__tests__/ReactProfiler-test.internal.js new file mode 100644 index 00000000000..e97d8eeef97 --- /dev/null +++ b/packages/react/src/__tests__/ReactProfiler-test.internal.js @@ -0,0 +1,862 @@ +/** + * Copyright (c) 2013-present, Facebook, Inc. + * + * 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 + */ + +'use strict'; + +let React; +let ReactFeatureFlags; +let ReactTestRenderer; + +function loadModules({ + enableProfilerTimer = true, + replayFailedUnitOfWorkWithInvokeGuardedCallback = false, +} = {}) { + ReactFeatureFlags = require('shared/ReactFeatureFlags'); + ReactFeatureFlags.debugRenderPhaseSideEffects = false; + ReactFeatureFlags.debugRenderPhaseSideEffectsForStrictMode = false; + ReactFeatureFlags.enableProfilerTimer = enableProfilerTimer; + ReactFeatureFlags.enableGetDerivedStateFromCatch = true; + ReactFeatureFlags.replayFailedUnitOfWorkWithInvokeGuardedCallback = replayFailedUnitOfWorkWithInvokeGuardedCallback; + React = require('react'); + ReactTestRenderer = require('react-test-renderer'); +} + +describe('Profiler', () => { + describe('works in profiling and non-profiling bundles', () => { + [true, false].forEach(flagEnabled => { + describe(`enableProfilerTimer ${ + flagEnabled ? 'enabled' : 'disabled' + }`, () => { + beforeEach(() => { + jest.resetModules(); + + loadModules({enableProfilerTimer: flagEnabled}); + }); + + // This will throw in production too, + // But the test is only interested in verifying the DEV error message. + if (__DEV__) { + it('should warn if required params are missing', () => { + expect(() => { + ReactTestRenderer.create(); + }).toThrow( + 'Profiler must specify an "id" string and "onRender" function as props', + ); + }); + } + + it('should support an empty Profiler (with no children)', () => { + // As root + expect( + ReactTestRenderer.create( + , + ).toJSON(), + ).toMatchSnapshot(); + + // As non-root + expect( + ReactTestRenderer.create( +
+ +
, + ).toJSON(), + ).toMatchSnapshot(); + }); + + it('should render children', () => { + const FunctionalComponent = ({label}) => {label}; + const renderer = ReactTestRenderer.create( +
+ outside span + + inside span + + +
, + ); + expect(renderer.toJSON()).toMatchSnapshot(); + }); + + it('should support nested Profilers', () => { + const FunctionalComponent = ({label}) =>
{label}
; + class ClassComponent extends React.Component { + render() { + return {this.props.label}; + } + } + const renderer = ReactTestRenderer.create( + + + + + inner span + + , + ); + expect(renderer.toJSON()).toMatchSnapshot(); + }); + }); + }); + }); + + describe('onRender callback', () => { + let AdvanceTime; + let advanceTimeBy; + + const mockNowForTests = () => { + let currentTime = 0; + ReactTestRenderer.unstable_setNowImplementation(() => currentTime); + advanceTimeBy = amount => { + currentTime += amount; + }; + }; + + beforeEach(() => { + jest.resetModules(); + + loadModules(); + mockNowForTests(); + + AdvanceTime = class extends React.Component { + static defaultProps = { + byAmount: 10, + shouldComponentUpdate: true, + }; + shouldComponentUpdate(nextProps) { + return nextProps.shouldComponentUpdate; + } + render() { + // Simulate time passing when this component is rendered + advanceTimeBy(this.props.byAmount); + return this.props.children || null; + } + }; + }); + + it('is not invoked until the commit phase', () => { + const callback = jest.fn(); + + const Yield = ({value}) => { + renderer.unstable_yield(value); + return null; + }; + + const renderer = ReactTestRenderer.create( + + + + , + { + unstable_isAsync: true, + }, + ); + + // Times are logged until a render is committed. + renderer.unstable_flushThrough(['first']); + expect(callback).toHaveBeenCalledTimes(0); + expect(renderer.unstable_flushAll()).toEqual(['last']); + expect(callback).toHaveBeenCalledTimes(1); + }); + + it('logs render times for both mount and update', () => { + const callback = jest.fn(); + + const renderer = ReactTestRenderer.create( + + + , + ); + + expect(callback).toHaveBeenCalledTimes(1); + + let [call] = callback.mock.calls; + + expect(call).toHaveLength(4); + expect(call[0]).toBe('test'); + expect(call[1]).toBe('mount'); + expect(call[2]).toBe(10); // "actual" time + expect(call[3]).toBe(10); // "base" time + + callback.mockReset(); + + renderer.update( + + + , + ); + + expect(callback).toHaveBeenCalledTimes(1); + + [call] = callback.mock.calls; + + expect(call).toHaveLength(4); + expect(call[0]).toBe('test'); + expect(call[1]).toBe('update'); + expect(call[2]).toBe(10); // "actual" time + expect(call[3]).toBe(10); // "base" time + }); + + it('includes render times of nested Profilers in their parent times', () => { + const callback = jest.fn(); + + ReactTestRenderer.create( + + + + + + + + + , + ); + + expect(callback).toHaveBeenCalledTimes(2); + + // Callbacks bubble (reverse order). + const [childCall, parentCall] = callback.mock.calls; + expect(childCall[0]).toBe('child'); + expect(parentCall[0]).toBe('parent'); + + // Parent times should include child times + expect(childCall[2]).toBe(20); // "actual" time + expect(childCall[3]).toBe(20); // "base" time + expect(parentCall[2]).toBe(30); // "actual" time + expect(parentCall[3]).toBe(30); // "base" time + }); + + it('tracks sibling Profilers separately', () => { + const callback = jest.fn(); + + ReactTestRenderer.create( + + + + + + + + , + ); + + expect(callback).toHaveBeenCalledTimes(2); + + const [firstCall, secondCall] = callback.mock.calls; + expect(firstCall[0]).toBe('first'); + expect(secondCall[0]).toBe('second'); + + // Parent times should include child times + expect(firstCall[2]).toBe(20); // "actual" time + expect(firstCall[3]).toBe(20); // "base" time + expect(secondCall[2]).toBe(5); // "actual" time + expect(secondCall[3]).toBe(5); // "base" time + }); + + it('does not include time spent outside of profile root', () => { + const callback = jest.fn(); + + ReactTestRenderer.create( + + + + + + + , + ); + + expect(callback).toHaveBeenCalledTimes(1); + + const [call] = callback.mock.calls; + expect(call[0]).toBe('test'); + expect(call[2]).toBe(5); // "actual" time + expect(call[3]).toBe(5); // "base" time + }); + + it('is not called when blocked by sCU false', () => { + const callback = jest.fn(); + + let instance; + class Updater extends React.Component { + state = {}; + render() { + instance = this; + return this.props.children; + } + } + + class Pure extends React.PureComponent { + render() { + return this.props.children; + } + } + + const renderer = ReactTestRenderer.create( + + + + + +
+ + + + + , + ); + + // All profile callbacks are called for initial render + expect(callback).toHaveBeenCalledTimes(3); + + callback.mockReset(); + + renderer.unstable_flushSync(() => { + instance.setState({ + count: 1, + }); + }); + + // Only call profile updates for paths that have re-rendered + // Since "inner" is beneath a pure compoent, it isn't called + expect(callback).toHaveBeenCalledTimes(2); + expect(callback.mock.calls[0][0]).toBe('middle'); + expect(callback.mock.calls[1][0]).toBe('outer'); + }); + + it('decreases "actual" time but not "base" time when sCU prevents an update', () => { + const callback = jest.fn(); + + const renderer = ReactTestRenderer.create( + + + + + , + ); + + expect(callback).toHaveBeenCalledTimes(1); + + renderer.update( + + + + + , + ); + + expect(callback).toHaveBeenCalledTimes(2); + + const [mountCall, updateCall] = callback.mock.calls; + + expect(mountCall[1]).toBe('mount'); + expect(mountCall[2]).toBe(20); // "actual" time + expect(mountCall[3]).toBe(20); // "base" time + + expect(updateCall[1]).toBe('update'); + expect(updateCall[2]).toBe(10); // "actual" time + expect(updateCall[3]).toBe(20); // "base" time + }); + + it('includes time spent in render phase lifecycles', () => { + class WithLifecycles extends React.Component { + state = {}; + static getDerivedStateFromProps() { + advanceTimeBy(3); + return null; + } + shouldComponentUpdate() { + advanceTimeBy(7); + return true; + } + render() { + advanceTimeBy(5); + return null; + } + } + + const callback = jest.fn(); + + const renderer = ReactTestRenderer.create( + + + , + ); + + renderer.update( + + + , + ); + + expect(callback).toHaveBeenCalledTimes(2); + + const [mountCall, updateCall] = callback.mock.calls; + + expect(mountCall[1]).toBe('mount'); + expect(mountCall[2]).toBe(8); // "actual" time + expect(mountCall[3]).toBe(8); // "base" time + + expect(updateCall[1]).toBe('update'); + expect(updateCall[2]).toBe(15); // "actual" time + expect(updateCall[3]).toBe(15); // "base" time + }); + + describe('with regard to interruptions', () => { + it('should accumulate "actual" time after a scheduling interruptions', () => { + const callback = jest.fn(); + + const Yield = ({renderTime}) => { + advanceTimeBy(renderTime); + renderer.unstable_yield('Yield:' + renderTime); + return null; + }; + + // Render partially, but run out of time before completing. + const renderer = ReactTestRenderer.create( + + + + , + {unstable_isAsync: true}, + ); + expect(renderer.unstable_flushThrough(['Yield:2'])).toEqual([ + 'Yield:2', + ]); + expect(callback).toHaveBeenCalledTimes(0); + + // Resume render for remaining children. + expect(renderer.unstable_flushAll()).toEqual(['Yield:3']); + + // Verify that logged times include both durations above. + expect(callback).toHaveBeenCalledTimes(1); + expect(callback.mock.calls[0][2]).toBe(5); // "actual" time + expect(callback.mock.calls[0][3]).toBe(5); // "base" time + }); + + it('should not include time between frames', () => { + const callback = jest.fn(); + + const Yield = ({renderTime}) => { + advanceTimeBy(renderTime); + renderer.unstable_yield('Yield:' + renderTime); + return null; + }; + + // Render partially, but don't finish. + // This partial render should take 5ms of simulated time. + const renderer = ReactTestRenderer.create( + + + + + + + , + {unstable_isAsync: true}, + ); + expect(renderer.unstable_flushThrough(['Yield:5'])).toEqual([ + 'Yield:5', + ]); + expect(callback).toHaveBeenCalledTimes(0); + + // Simulate time moving forward while frame is paused. + advanceTimeBy(50); + + // Flush the remaninig work, + // Which should take an additional 10ms of simulated time. + expect(renderer.unstable_flushAll()).toEqual(['Yield:10', 'Yield:17']); + expect(callback).toHaveBeenCalledTimes(2); + + const [innerCall, outerCall] = callback.mock.calls; + + // Verify that the "actual" time includes all work times, + // But not the time that elapsed between frames. + expect(innerCall[0]).toBe('inner'); + expect(innerCall[2]).toBe(17); // "actual" time + expect(innerCall[3]).toBe(17); // "base" time + expect(outerCall[0]).toBe('outer'); + expect(outerCall[2]).toBe(32); // "actual" time + expect(outerCall[3]).toBe(32); // "base" time + }); + + it('should report the expected times when a high-priority update replaces an in-progress initial render', () => { + const callback = jest.fn(); + + const Yield = ({renderTime}) => { + advanceTimeBy(renderTime); + renderer.unstable_yield('Yield:' + renderTime); + return null; + }; + + // Render a partially update, but don't finish. + // This partial render should take 10ms of simulated time. + const renderer = ReactTestRenderer.create( + + + + , + {unstable_isAsync: true}, + ); + expect(renderer.unstable_flushThrough(['first'])).toEqual(['Yield:10']); + expect(callback).toHaveBeenCalledTimes(0); + + // Simulate time moving forward while frame is paused. + advanceTimeBy(100); + + // Interrupt with higher priority work. + // The interrupted work simulates an additional 5ms of time. + expect( + renderer.unstable_flushSync(() => { + renderer.update( + + + , + ); + }), + ).toEqual(['Yield:5']); + + // The initial work was thrown away in this case, + // So the "actual" and "base" times should only include the final rendered tree times. + expect(callback).toHaveBeenCalledTimes(1); + let call = callback.mock.calls[0]; + expect(call[2]).toBe(5); // "actual" time + expect(call[3]).toBe(5); // "base" time + + callback.mockReset(); + + // Verify no more unexpected callbacks from low priority work + expect(renderer.unstable_flushAll()).toEqual([]); + expect(callback).toHaveBeenCalledTimes(0); + }); + + it('should report the expected times when a high-priority update replaces a low-priority update', () => { + const callback = jest.fn(); + + const Yield = ({renderTime}) => { + advanceTimeBy(renderTime); + renderer.unstable_yield('Yield:' + renderTime); + return null; + }; + + const renderer = ReactTestRenderer.create( + + + + , + {unstable_isAsync: true}, + ); + + // Render everything initially. + // This should take 21 seconds of "actual" and "base" time. + expect(renderer.unstable_flushAll()).toEqual(['Yield:6', 'Yield:15']); + expect(callback).toHaveBeenCalledTimes(1); + let call = callback.mock.calls[0]; + expect(call[2]).toBe(21); // "actual" time + expect(call[3]).toBe(21); // "base" time + + callback.mockReset(); + + // Render a partially update, but don't finish. + // This partial render should take 3ms of simulated time. + renderer.update( + + + + + , + ); + expect(renderer.unstable_flushThrough(['Yield:3'])).toEqual([ + 'Yield:3', + ]); + expect(callback).toHaveBeenCalledTimes(0); + + // Simulate time moving forward while frame is paused. + advanceTimeBy(100); + + // Render another 5ms of simulated time. + expect(renderer.unstable_flushThrough(['Yield:5'])).toEqual([ + 'Yield:5', + ]); + expect(callback).toHaveBeenCalledTimes(0); + + // Simulate time moving forward while frame is paused. + advanceTimeBy(100); + + // Interrupt with higher priority work. + // The interrupted work simulates an additional 11ms of time. + expect( + renderer.unstable_flushSync(() => { + renderer.update( + + + , + ); + }), + ).toEqual(['Yield:11']); + + // Verify that the "actual" time includes all three durations above. + // And the "base" time includes only the final rendered tree times. + expect(callback).toHaveBeenCalledTimes(1); + call = callback.mock.calls[0]; + expect(call[2]).toBe(19); // "actual" time + expect(call[3]).toBe(11); // "base" time + + // Verify no more unexpected callbacks from low priority work + expect(renderer.unstable_flushAll()).toEqual([]); + expect(callback).toHaveBeenCalledTimes(1); + }); + + it('should report the expected times when a high-priority update interrupts a low-priority update', () => { + const callback = jest.fn(); + + const Yield = ({renderTime}) => { + advanceTimeBy(renderTime); + renderer.unstable_yield('Yield:' + renderTime); + return null; + }; + + let first; + class FirstComponent extends React.Component { + state = {renderTime: 1}; + render() { + first = this; + advanceTimeBy(this.state.renderTime); + renderer.unstable_yield('FirstComponent:' + this.state.renderTime); + return ; + } + } + let second; + class SecondComponent extends React.Component { + state = {renderTime: 2}; + render() { + second = this; + advanceTimeBy(this.state.renderTime); + renderer.unstable_yield('SecondComponent:' + this.state.renderTime); + return ; + } + } + + const renderer = ReactTestRenderer.create( + + + + , + {unstable_isAsync: true}, + ); + + // Render everything initially. + // This simulates a total of 14ms of "actual" render time. + // The "base" render time is also 14ms for the initial render. + expect(renderer.unstable_flushAll()).toEqual([ + 'FirstComponent:1', + 'Yield:4', + 'SecondComponent:2', + 'Yield:7', + ]); + expect(callback).toHaveBeenCalledTimes(1); + let call = callback.mock.calls[0]; + expect(call[2]).toBe(14); // "actual" time + expect(call[3]).toBe(14); // "base" time + + callback.mockClear(); + + // Render a partially update, but don't finish. + // This partial render will take 10ms of "actual" render time. + first.setState({renderTime: 10}); + expect(renderer.unstable_flushThrough(['FirstComponent:10'])).toEqual([ + 'FirstComponent:10', + ]); + expect(callback).toHaveBeenCalledTimes(0); + + // Simulate time moving forward while frame is paused. + advanceTimeBy(100); + + // Interrupt with higher priority work. + // This simulates a total of 37ms of "actual" render time. + expect( + renderer.unstable_flushSync(() => second.setState({renderTime: 30})), + ).toEqual(['SecondComponent:30', 'Yield:7']); + + // Verify that the "actual" time includes time spent in the both renders so far (10ms and 37ms). + // The "base" time should include the more recent times for the SecondComponent subtree, + // As well as the original times for the FirstComponent subtree. + expect(callback).toHaveBeenCalledTimes(1); + call = callback.mock.calls[0]; + expect(call[2]).toBe(47); // "actual" time + expect(call[3]).toBe(42); // "base" time + + callback.mockClear(); + + // Resume the original low priority update, with rebased state. + // This simulates a total of 14ms of "actual" render time, + // And does not include the original (interrupted) 10ms. + // The tree contains 42ms of "base" render time at this point, + // Reflecting the most recent (longer) render durations. + // TODO: This "actual" time should decrease by 10ms once the scheduler supports resuming. + expect(renderer.unstable_flushAll()).toEqual([ + 'FirstComponent:10', + 'Yield:4', + ]); + expect(callback).toHaveBeenCalledTimes(1); + call = callback.mock.calls[0]; + expect(call[2]).toBe(14); // "actual" time + expect(call[3]).toBe(51); // "base" time + }); + + [true, false].forEach(flagEnabled => { + describe(`replayFailedUnitOfWorkWithInvokeGuardedCallback ${ + flagEnabled ? 'enabled' : 'disabled' + }`, () => { + beforeEach(() => { + jest.resetModules(); + + loadModules({ + replayFailedUnitOfWorkWithInvokeGuardedCallback: flagEnabled, + }); + mockNowForTests(); + }); + + it('should accumulate "actual" time after an error handled by componentDidCatch()', () => { + const callback = jest.fn(); + + const ThrowsError = () => { + advanceTimeBy(10); + throw Error('expected error'); + }; + + class ErrorBoundary extends React.Component { + state = {error: null}; + componentDidCatch(error) { + this.setState({error}); + } + render() { + advanceTimeBy(2); + return this.state.error === null ? ( + this.props.children + ) : ( + + ); + } + } + + ReactTestRenderer.create( + + + + + + , + ); + + expect(callback).toHaveBeenCalledTimes(2); + + // Callbacks bubble (reverse order). + let [mountCall, updateCall] = callback.mock.calls; + + // The initial mount only includes the ErrorBoundary (which takes 2ms) + // But it spends time rendering all of the failed subtree also. + expect(mountCall[1]).toBe('mount'); + // "actual" time includes: 2 (ErrorBoundary) + 5 (AdvanceTime) + 10 (ThrowsError) + // If replayFailedUnitOfWorkWithInvokeGuardedCallback is enbaled, ThrowsError is replayed. + expect(mountCall[2]).toBe(flagEnabled && __DEV__ ? 27 : 17); + // "base" time includes: 2 (ErrorBoundary) + expect(mountCall[3]).toBe(2); + + // The update includes the ErrorBoundary and its fallback child + expect(updateCall[1]).toBe('update'); + // "actual" time includes: 2 (ErrorBoundary) + 20 (AdvanceTime) + expect(updateCall[2]).toBe(22); + // "base" time includes: 2 (ErrorBoundary) + 20 (AdvanceTime) + expect(updateCall[3]).toBe(22); + }); + + it('should accumulate "actual" time after an error handled by getDerivedStateFromCatch()', () => { + const callback = jest.fn(); + + const ThrowsError = () => { + advanceTimeBy(10); + throw Error('expected error'); + }; + + class ErrorBoundary extends React.Component { + state = {error: null}; + static getDerivedStateFromCatch(error) { + return {error}; + } + render() { + advanceTimeBy(2); + return this.state.error === null ? ( + this.props.children + ) : ( + + ); + } + } + + ReactTestRenderer.create( + + + + + + , + ); + + expect(callback).toHaveBeenCalledTimes(1); + + // Callbacks bubble (reverse order). + let [mountCall] = callback.mock.calls; + + // The initial mount includes the ErrorBoundary's error state, + // But i also spends "actual" time rendering UI that fails and isn't included. + expect(mountCall[1]).toBe('mount'); + // "actual" time includes: 2 (ErrorBoundary) + 5 (AdvanceTime) + 10 (ThrowsError) + // Then the re-render: 2 (ErrorBoundary) + 20 (AdvanceTime) + // If replayFailedUnitOfWorkWithInvokeGuardedCallback is enbaled, ThrowsError is replayed. + expect(mountCall[2]).toBe(flagEnabled && __DEV__ ? 49 : 39); + // "base" time includes: 2 (ErrorBoundary) + 20 (AdvanceTime) + expect(mountCall[3]).toBe(22); + }); + }); + }); + }); + + it('reflects the most recently rendered id value', () => { + const callback = jest.fn(); + + const renderer = ReactTestRenderer.create( + + + , + ); + + expect(callback).toHaveBeenCalledTimes(1); + + renderer.update( + + + , + ); + + expect(callback).toHaveBeenCalledTimes(2); + + const [mountCall, updateCall] = callback.mock.calls; + + expect(mountCall[0]).toBe('one'); + expect(mountCall[1]).toBe('mount'); + expect(mountCall[2]).toBe(2); // "actual" time + expect(mountCall[3]).toBe(2); // "base" time + + expect(updateCall[0]).toBe('two'); + expect(updateCall[1]).toBe('update'); + expect(updateCall[2]).toBe(1); // "actual" time + expect(updateCall[3]).toBe(1); // "base" time + }); + }); +}); diff --git a/packages/react/src/__tests__/__snapshots__/ReactProfiler-test.internal.js.snap b/packages/react/src/__tests__/__snapshots__/ReactProfiler-test.internal.js.snap new file mode 100644 index 00000000000..0022e5abd34 --- /dev/null +++ b/packages/react/src/__tests__/__snapshots__/ReactProfiler-test.internal.js.snap @@ -0,0 +1,65 @@ +// Jest Snapshot v1, https://goo.gl/fbAQLP + +exports[`Profiler works in profiling and non-profiling bundles enableProfilerTimer disabled should render children 1`] = ` +
+ + outside span + + + inside span + + + functional component + +
+`; + +exports[`Profiler works in profiling and non-profiling bundles enableProfilerTimer disabled should support an empty Profiler (with no children) 1`] = `null`; + +exports[`Profiler works in profiling and non-profiling bundles enableProfilerTimer disabled should support an empty Profiler (with no children) 2`] = `
`; + +exports[`Profiler works in profiling and non-profiling bundles enableProfilerTimer disabled should support nested Profilers 1`] = ` +Array [ +
+ outer functional component +
, + + inner class component + , + + inner span + , +] +`; + +exports[`Profiler works in profiling and non-profiling bundles enableProfilerTimer enabled should render children 1`] = ` +
+ + outside span + + + inside span + + + functional component + +
+`; + +exports[`Profiler works in profiling and non-profiling bundles enableProfilerTimer enabled should support an empty Profiler (with no children) 1`] = `null`; + +exports[`Profiler works in profiling and non-profiling bundles enableProfilerTimer enabled should support an empty Profiler (with no children) 2`] = `
`; + +exports[`Profiler works in profiling and non-profiling bundles enableProfilerTimer enabled should support nested Profilers 1`] = ` +Array [ +
+ outer functional component +
, + + inner class component + , + + inner span + , +] +`; diff --git a/packages/shared/ReactFeatureFlags.js b/packages/shared/ReactFeatureFlags.js index 955668d13e4..614a1b6cc7e 100644 --- a/packages/shared/ReactFeatureFlags.js +++ b/packages/shared/ReactFeatureFlags.js @@ -37,6 +37,9 @@ export const replayFailedUnitOfWorkWithInvokeGuardedCallback = __DEV__; // Warn about deprecated, async-unsafe lifecycles; relates to RFC #6: export const warnAboutDeprecatedLifecycles = false; +// Gather advanced timing metrics for Profiler subtrees. +export const enableProfilerTimer = false; + // Only used in www builds. export function addUserTimingListener() { invariant(false, 'Not implemented.'); diff --git a/packages/shared/ReactSymbols.js b/packages/shared/ReactSymbols.js index 12e0fdddad9..672e51de8ee 100644 --- a/packages/shared/ReactSymbols.js +++ b/packages/shared/ReactSymbols.js @@ -27,6 +27,9 @@ export const REACT_FRAGMENT_TYPE = hasSymbol export const REACT_STRICT_MODE_TYPE = hasSymbol ? Symbol.for('react.strict_mode') : 0xeacc; +export const REACT_PROFILER_TYPE = hasSymbol + ? Symbol.for('react.profile_root') + : 0xeacc; export const REACT_PROVIDER_TYPE = hasSymbol ? Symbol.for('react.provider') : 0xeacd; diff --git a/packages/shared/ReactTypeOfWork.js b/packages/shared/ReactTypeOfWork.js index 573b75aabc0..1c672bb4b55 100644 --- a/packages/shared/ReactTypeOfWork.js +++ b/packages/shared/ReactTypeOfWork.js @@ -22,7 +22,8 @@ export type TypeOfWork = | 11 | 12 | 13 - | 14; + | 14 + | 15; export const IndeterminateComponent = 0; // Before we know whether it is functional or class export const FunctionalComponent = 1; @@ -39,3 +40,4 @@ export const Mode = 11; export const ContextConsumer = 12; export const ContextProvider = 13; export const ForwardRef = 14; +export const Profiler = 15; diff --git a/packages/shared/forks/ReactFeatureFlags.native-fabric-fb.js b/packages/shared/forks/ReactFeatureFlags.native-fabric-fb.js index e2fd4379995..7eb809c952e 100644 --- a/packages/shared/forks/ReactFeatureFlags.native-fabric-fb.js +++ b/packages/shared/forks/ReactFeatureFlags.native-fabric-fb.js @@ -18,6 +18,7 @@ export const enableUserTimingAPI = __DEV__; export const enableGetDerivedStateFromCatch = false; export const warnAboutDeprecatedLifecycles = false; export const replayFailedUnitOfWorkWithInvokeGuardedCallback = __DEV__; +export const enableProfilerTimer = __DEV__; // React Fabric uses persistent reconciler. export const enableMutatingReconciler = false; diff --git a/packages/shared/forks/ReactFeatureFlags.native-fabric-oss.js b/packages/shared/forks/ReactFeatureFlags.native-fabric-oss.js index c6a4862d85f..c6b30c6532f 100644 --- a/packages/shared/forks/ReactFeatureFlags.native-fabric-oss.js +++ b/packages/shared/forks/ReactFeatureFlags.native-fabric-oss.js @@ -18,6 +18,7 @@ export const enableUserTimingAPI = __DEV__; export const enableGetDerivedStateFromCatch = false; export const warnAboutDeprecatedLifecycles = false; export const replayFailedUnitOfWorkWithInvokeGuardedCallback = __DEV__; +export const enableProfilerTimer = false; // React Fabric uses persistent reconciler. export const enableMutatingReconciler = false; diff --git a/packages/shared/forks/ReactFeatureFlags.native-fb.js b/packages/shared/forks/ReactFeatureFlags.native-fb.js index 3026a69fc6c..51e2133a677 100644 --- a/packages/shared/forks/ReactFeatureFlags.native-fb.js +++ b/packages/shared/forks/ReactFeatureFlags.native-fb.js @@ -19,6 +19,7 @@ export const { debugRenderPhaseSideEffectsForStrictMode, warnAboutDeprecatedLifecycles, replayFailedUnitOfWorkWithInvokeGuardedCallback, + enableProfilerTimer, } = require('ReactFeatureFlags'); // The rest of the flags are static for better dead code elimination. diff --git a/packages/shared/forks/ReactFeatureFlags.native-oss.js b/packages/shared/forks/ReactFeatureFlags.native-oss.js index a238ca16885..5e03310dc08 100644 --- a/packages/shared/forks/ReactFeatureFlags.native-oss.js +++ b/packages/shared/forks/ReactFeatureFlags.native-oss.js @@ -21,6 +21,7 @@ export const enablePersistentReconciler = false; export const enableUserTimingAPI = __DEV__; export const replayFailedUnitOfWorkWithInvokeGuardedCallback = __DEV__; export const warnAboutDeprecatedLifecycles = false; +export const enableProfilerTimer = false; // Only used in www builds. export function addUserTimingListener() { diff --git a/packages/shared/forks/ReactFeatureFlags.persistent.js b/packages/shared/forks/ReactFeatureFlags.persistent.js index 57d7c6bf531..780c62db4da 100644 --- a/packages/shared/forks/ReactFeatureFlags.persistent.js +++ b/packages/shared/forks/ReactFeatureFlags.persistent.js @@ -18,6 +18,7 @@ export const enableUserTimingAPI = __DEV__; export const enableGetDerivedStateFromCatch = false; export const warnAboutDeprecatedLifecycles = false; export const replayFailedUnitOfWorkWithInvokeGuardedCallback = __DEV__; +export const enableProfilerTimer = false; // react-reconciler/persistent entry point // uses a persistent reconciler. diff --git a/packages/shared/forks/ReactFeatureFlags.test-renderer.js b/packages/shared/forks/ReactFeatureFlags.test-renderer.js index 000f950a4f7..486aecfa68c 100644 --- a/packages/shared/forks/ReactFeatureFlags.test-renderer.js +++ b/packages/shared/forks/ReactFeatureFlags.test-renderer.js @@ -21,6 +21,7 @@ export const replayFailedUnitOfWorkWithInvokeGuardedCallback = false; export const enableMutatingReconciler = true; export const enableNoopReconciler = false; export const enablePersistentReconciler = false; +export const enableProfilerTimer = false; // Only used in www builds. export function addUserTimingListener() { diff --git a/packages/shared/forks/ReactFeatureFlags.www.js b/packages/shared/forks/ReactFeatureFlags.www.js index df3560c6fba..523e1604a65 100644 --- a/packages/shared/forks/ReactFeatureFlags.www.js +++ b/packages/shared/forks/ReactFeatureFlags.www.js @@ -17,6 +17,7 @@ export const { enableGetDerivedStateFromCatch, replayFailedUnitOfWorkWithInvokeGuardedCallback, warnAboutDeprecatedLifecycles, + enableProfilerTimer, } = require('ReactFeatureFlags'); // The rest of the flags are static for better dead code elimination. diff --git a/packages/shared/getComponentName.js b/packages/shared/getComponentName.js index 23e10d1a73a..ed448d81520 100644 --- a/packages/shared/getComponentName.js +++ b/packages/shared/getComponentName.js @@ -10,11 +10,14 @@ import type {Fiber} from 'react-reconciler/src/ReactFiber'; import { + REACT_ASYNC_MODE_TYPE, REACT_CALL_TYPE, + REACT_FORWARD_REF_TYPE, REACT_FRAGMENT_TYPE, REACT_RETURN_TYPE, REACT_PORTAL_TYPE, - REACT_FORWARD_REF_TYPE, + REACT_PROFILER_TYPE, + REACT_STRICT_MODE_TYPE, } from 'shared/ReactSymbols'; function getComponentName(fiber: Fiber): string | null { @@ -26,14 +29,20 @@ function getComponentName(fiber: Fiber): string | null { return type; } switch (type) { + case REACT_ASYNC_MODE_TYPE: + return 'AsyncMode'; + case REACT_CALL_TYPE: + return 'ReactCall'; case REACT_FRAGMENT_TYPE: return 'ReactFragment'; case REACT_PORTAL_TYPE: return 'ReactPortal'; - case REACT_CALL_TYPE: - return 'ReactCall'; + case REACT_PROFILER_TYPE: + return `Profiler(${fiber.pendingProps.id})`; case REACT_RETURN_TYPE: return 'ReactReturn'; + case REACT_STRICT_MODE_TYPE: + return 'StrictMode'; } if (typeof type === 'object' && type !== null) { switch (type.$$typeof) { diff --git a/packages/shared/isValidElementType.js b/packages/shared/isValidElementType.js index 7a333c8c11a..c9a759d5026 100644 --- a/packages/shared/isValidElementType.js +++ b/packages/shared/isValidElementType.js @@ -8,12 +8,13 @@ */ import { - REACT_FRAGMENT_TYPE, REACT_ASYNC_MODE_TYPE, - REACT_STRICT_MODE_TYPE, - REACT_PROVIDER_TYPE, REACT_CONTEXT_TYPE, REACT_FORWARD_REF_TYPE, + REACT_FRAGMENT_TYPE, + REACT_PROFILER_TYPE, + REACT_PROVIDER_TYPE, + REACT_STRICT_MODE_TYPE, } from 'shared/ReactSymbols'; export default function isValidElementType(type: mixed) { @@ -23,6 +24,7 @@ export default function isValidElementType(type: mixed) { // Note: its typeof might be other than 'symbol' or 'number' if it's a polyfill. type === REACT_FRAGMENT_TYPE || type === REACT_ASYNC_MODE_TYPE || + type === REACT_PROFILER_TYPE || type === REACT_STRICT_MODE_TYPE || (typeof type === 'object' && type !== null &&