From 27da2832687076f8196cce0f0cfe6fd83297ee5e Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Sat, 25 Jan 2020 09:21:46 -0800 Subject: [PATCH 1/3] Implemented Profiler onCommit() and onPostCommit() hooks --- packages/react-reconciler/src/ReactFiber.js | 16 +- .../src/ReactFiberBeginWork.js | 12 + .../src/ReactFiberCommitWork.js | 236 +- .../src/ReactFiberWorkLoop.js | 67 +- .../src/ReactProfilerTimer.js | 72 + .../__tests__/ReactProfiler-test.internal.js | 3377 ++++++++++++----- 6 files changed, 2721 insertions(+), 1059 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiber.js b/packages/react-reconciler/src/ReactFiber.js index 35a6c1e6e77a..db40ba45dee7 100644 --- a/packages/react-reconciler/src/ReactFiber.js +++ b/packages/react-reconciler/src/ReactFiber.js @@ -813,13 +813,8 @@ function createFiberFromProfiler( key: null | string, ): Fiber { if (__DEV__) { - if ( - typeof pendingProps.id !== 'string' || - typeof pendingProps.onRender !== 'function' - ) { - console.error( - 'Profiler must specify an "id" string and "onRender" function as props', - ); + if (typeof pendingProps.id !== 'string') { + console.error('Profiler must specify an "id" as a prop'); } } @@ -829,6 +824,13 @@ function createFiberFromProfiler( fiber.type = REACT_PROFILER_TYPE; fiber.expirationTime = expirationTime; + if (enableProfilerTimer) { + fiber.stateNode = { + effectDuration: 0, + passiveEffectDuration: 0, + }; + } + return fiber; } diff --git a/packages/react-reconciler/src/ReactFiberBeginWork.js b/packages/react-reconciler/src/ReactFiberBeginWork.js index 8eb9f9ffb950..454ef8cf8a77 100644 --- a/packages/react-reconciler/src/ReactFiberBeginWork.js +++ b/packages/react-reconciler/src/ReactFiberBeginWork.js @@ -587,6 +587,12 @@ function updateProfiler( ) { if (enableProfilerTimer) { workInProgress.effectTag |= Update; + + // Reset effect durations for the next eventual effect phase. + // These are reset during render to allow the DevTools commit hook a chance to read them, + const stateNode = workInProgress.stateNode; + stateNode.effectDuration = 0; + stateNode.passiveEffectDuration = 0; } const nextProps = workInProgress.pendingProps; const nextChildren = nextProps.children; @@ -2972,6 +2978,12 @@ function beginWork( if (hasChildWork) { workInProgress.effectTag |= Update; } + + // Reset effect durations for the next eventual effect phase. + // These are reset during render to allow the DevTools commit hook a chance to read them, + const stateNode = workInProgress.stateNode; + stateNode.effectDuration = 0; + stateNode.passiveEffectDuration = 0; } break; case SuspenseComponent: { diff --git a/packages/react-reconciler/src/ReactFiberCommitWork.js b/packages/react-reconciler/src/ReactFiberCommitWork.js index 857928aa4c3d..bfb13df239e2 100644 --- a/packages/react-reconciler/src/ReactFiberCommitWork.js +++ b/packages/react-reconciler/src/ReactFiberCommitWork.js @@ -76,7 +76,14 @@ import {startPhaseTimer, stopPhaseTimer} from './ReactDebugFiberPerf'; import {getStackByFiberInDevAndProd} from './ReactCurrentFiber'; import {logCapturedError} from './ReactFiberErrorLogger'; import {resolveDefaultProps} from './ReactFiberLazyComponent'; -import {getCommitTime} from './ReactProfilerTimer'; +import { + getCommitTime, + recordLayoutEffectDuration, + recordPassiveEffectDuration, + startLayoutEffectTimer, + startPassiveEffectTimer, +} from './ReactProfilerTimer'; +import {ProfileMode} from './ReactTypeOfMode'; import {commitUpdateQueue} from './ReactUpdateQueue'; import { getPublicInstance, @@ -113,6 +120,7 @@ import { markCommitTimeOfFallback, enqueuePendingPassiveHookEffectMount, enqueuePendingPassiveHookEffectUnmount, + enqueuePendingPassiveProfilerEffect, } from './ReactFiberWorkLoop'; import { NoEffect as NoHookEffect, @@ -175,7 +183,16 @@ const callComponentWillUnmountWithTimer = function(current, instance) { startPhaseTimer(current, 'componentWillUnmount'); instance.props = current.memoizedProps; instance.state = current.memoizedState; - instance.componentWillUnmount(); + if (enableProfilerTimer && current.mode & ProfileMode) { + try { + startLayoutEffectTimer(); + instance.componentWillUnmount(); + } finally { + recordLayoutEffectDuration(current); + } + } else { + instance.componentWillUnmount(); + } stopPhaseTimer(); }; @@ -430,8 +447,27 @@ export function commitPassiveHookEffects(finishedWork: Fiber): void { // TODO (#17945) We should call all passive destroy functions (for all fibers) // before calling any create functions. The current approach only serializes // these for a single fiber. - commitHookEffectListUnmount(HookPassive | HookHasEffect, finishedWork); - commitHookEffectListMount(HookPassive | HookHasEffect, finishedWork); + if (enableProfilerTimer && finishedWork.mode & ProfileMode) { + try { + startPassiveEffectTimer(); + commitHookEffectListUnmount( + HookPassive | HookHasEffect, + finishedWork, + ); + commitHookEffectListMount( + HookPassive | HookHasEffect, + finishedWork, + ); + } finally { + recordPassiveEffectDuration(finishedWork); + } + } else { + commitHookEffectListUnmount( + HookPassive | HookHasEffect, + finishedWork, + ); + commitHookEffectListMount(HookPassive | HookHasEffect, finishedWork); + } break; } default: @@ -440,6 +476,61 @@ export function commitPassiveHookEffects(finishedWork: Fiber): void { } } +export function commitPassiveEffectDurations( + finishedRoot: FiberRoot, + finishedWork: Fiber, +): void { + if (enableProfilerTimer) { + // Only Profilers with work in their subtree will have an Update effect scheduled. + if ((finishedWork.effectTag & Update) !== NoEffect) { + switch (finishedWork.tag) { + case Profiler: { + const {passiveEffectDuration} = finishedWork.stateNode; + const {id, onPostCommit} = finishedWork.memoizedProps; + + // This value will still reflect the previous commit phase. + // It does not get reset until the start of the next commit phase. + const commitTime = getCommitTime(); + + if (typeof onPostCommit === 'function') { + if (enableSchedulerTracing) { + onPostCommit( + id, + finishedWork.alternate === null ? 'mount' : 'update', + passiveEffectDuration, + commitTime, + finishedRoot.memoizedInteractions, + ); + } else { + onPostCommit( + id, + finishedWork.alternate === null ? 'mount' : 'update', + passiveEffectDuration, + commitTime, + ); + } + } + + // Bubble times to the next nearest ancestor Profiler. + // After we process that Profiler, we'll bubble further up. + let parentFiber = finishedWork.return; + while (parentFiber !== null) { + if (parentFiber.tag === Profiler) { + const parentStateNode = parentFiber.stateNode; + parentStateNode.passiveEffectDuration += passiveEffectDuration; + break; + } + parentFiber = parentFiber.return; + } + break; + } + default: + break; + } + } + } +} + function commitLifeCycles( finishedRoot: FiberRoot, current: Fiber | null, @@ -455,7 +546,16 @@ function commitLifeCycles( // This is done to prevent sibling component effects from interfering with each other, // e.g. a destroy function in one component should never override a ref set // by a create function in another component during the same commit. - commitHookEffectListMount(HookLayout | HookHasEffect, finishedWork); + if (enableProfilerTimer && finishedWork.mode & ProfileMode) { + try { + startLayoutEffectTimer(); + commitHookEffectListMount(HookLayout | HookHasEffect, finishedWork); + } finally { + recordLayoutEffectDuration(finishedWork); + } + } else { + commitHookEffectListMount(HookLayout | HookHasEffect, finishedWork); + } if (runAllPassiveEffectDestroysBeforeCreates) { schedulePassiveEffects(finishedWork); @@ -497,7 +597,16 @@ function commitLifeCycles( } } } - instance.componentDidMount(); + if (enableProfilerTimer && finishedWork.mode & ProfileMode) { + try { + startLayoutEffectTimer(); + instance.componentDidMount(); + } finally { + recordLayoutEffectDuration(finishedWork); + } + } else { + instance.componentDidMount(); + } stopPhaseTimer(); } else { const prevProps = @@ -536,11 +645,24 @@ function commitLifeCycles( } } } - instance.componentDidUpdate( - prevProps, - prevState, - instance.__reactInternalSnapshotBeforeUpdate, - ); + if (enableProfilerTimer && finishedWork.mode & ProfileMode) { + try { + startLayoutEffectTimer(); + instance.componentDidUpdate( + prevProps, + prevState, + instance.__reactInternalSnapshotBeforeUpdate, + ); + } finally { + recordLayoutEffectDuration(finishedWork); + } + } else { + instance.componentDidUpdate( + prevProps, + prevState, + instance.__reactInternalSnapshotBeforeUpdate, + ); + } stopPhaseTimer(); } } @@ -623,7 +745,10 @@ function commitLifeCycles( } case Profiler: { if (enableProfilerTimer) { - const onRender = finishedWork.memoizedProps.onRender; + const {onCommit, onRender} = finishedWork.memoizedProps; + const {effectDuration} = finishedWork.stateNode; + + const commitTime = getCommitTime(); if (typeof onRender === 'function') { if (enableSchedulerTracing) { @@ -633,7 +758,7 @@ function commitLifeCycles( finishedWork.actualDuration, finishedWork.treeBaseDuration, finishedWork.actualStartTime, - getCommitTime(), + commitTime, finishedRoot.memoizedInteractions, ); } else { @@ -643,10 +768,46 @@ function commitLifeCycles( finishedWork.actualDuration, finishedWork.treeBaseDuration, finishedWork.actualStartTime, - getCommitTime(), + commitTime, ); } } + + if (typeof onCommit === 'function') { + if (enableSchedulerTracing) { + onCommit( + finishedWork.memoizedProps.id, + current === null ? 'mount' : 'update', + effectDuration, + commitTime, + finishedRoot.memoizedInteractions, + ); + } else { + onCommit( + finishedWork.memoizedProps.id, + current === null ? 'mount' : 'update', + effectDuration, + commitTime, + ); + } + } + + // Schedule a passive effect for this Profiler to call onPostCommit hooks. + // This effect should be scheduled even if there is no onPostCommit callback for this Profiler, + // because the effect is also where times bubble to parent Profilers. + enqueuePendingPassiveProfilerEffect(finishedWork); + + // Propagate layout effect durations to the next nearest Profiler ancestor. + // Do not reset these values until the next render so DevTools has a chance to read them first. + let parentFiber = finishedWork.return; + while (parentFiber !== null) { + if (parentFiber.tag === Profiler) { + const parentStateNode = parentFiber.stateNode; + parentStateNode.effectDuration += effectDuration; + break; + } + parentFiber = parentFiber.return; + } } return; } @@ -797,7 +958,13 @@ function commitUnmount( if ((tag & HookPassive) !== NoHookEffect) { enqueuePendingPassiveHookEffectUnmount(current, effect); } else { - safelyCallDestroy(current, destroy); + if (enableProfilerTimer && current.mode & ProfileMode) { + startLayoutEffectTimer(); + safelyCallDestroy(current, destroy); + recordLayoutEffectDuration(current); + } else { + safelyCallDestroy(current, destroy); + } } } effect = effect.next; @@ -822,9 +989,19 @@ function commitUnmount( runWithPriority(priorityLevel, () => { let effect = firstEffect; do { - const destroy = effect.destroy; + const {destroy, tag} = effect; if (destroy !== undefined) { - safelyCallDestroy(current, destroy); + if (enableProfilerTimer && current.mode & ProfileMode) { + if ((tag & HookPassive) !== NoHookEffect) { + safelyCallDestroy(current, destroy); + } else { + startLayoutEffectTimer(); + safelyCallDestroy(current, destroy); + recordLayoutEffectDuration(current); + } + } else { + safelyCallDestroy(current, destroy); + } } effect = effect.next; } while (effect !== firstEffect); @@ -1366,7 +1543,19 @@ function commitWork(current: Fiber | null, finishedWork: Fiber): void { // This prevents sibling component effects from interfering with each other, // e.g. a destroy function in one component should never override a ref set // by a create function in another component during the same commit. - commitHookEffectListUnmount(HookLayout | HookHasEffect, finishedWork); + if (enableProfilerTimer && finishedWork.mode & ProfileMode) { + try { + startLayoutEffectTimer(); + commitHookEffectListUnmount( + HookLayout | HookHasEffect, + finishedWork, + ); + } finally { + recordLayoutEffectDuration(finishedWork); + } + } else { + commitHookEffectListUnmount(HookLayout | HookHasEffect, finishedWork); + } return; } case Profiler: { @@ -1409,7 +1598,16 @@ function commitWork(current: Fiber | null, finishedWork: Fiber): void { // This prevents sibling component effects from interfering with each other, // e.g. a destroy function in one component should never override a ref set // by a create function in another component during the same commit. - commitHookEffectListUnmount(HookLayout | HookHasEffect, finishedWork); + if (enableProfilerTimer && finishedWork.mode & ProfileMode) { + try { + startLayoutEffectTimer(); + commitHookEffectListUnmount(HookLayout | HookHasEffect, finishedWork); + } finally { + recordLayoutEffectDuration(finishedWork); + } + } else { + commitHookEffectListUnmount(HookLayout | HookHasEffect, finishedWork); + } return; } case ClassComponent: { diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.js b/packages/react-reconciler/src/ReactFiberWorkLoop.js index 3c2427594a79..be380d2c3c28 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.js +++ b/packages/react-reconciler/src/ReactFiberWorkLoop.js @@ -139,6 +139,7 @@ import { commitDeletion, commitDetachRef, commitAttachRef, + commitPassiveEffectDurations, commitResetTextContent, } from './ReactFiberCommitWork'; import {enqueueUpdate} from './ReactUpdateQueue'; @@ -148,6 +149,8 @@ import {createCapturedValue} from './ReactCapturedValue'; import { recordCommitTime, + recordPassiveEffectDuration, + startPassiveEffectTimer, startProfilerTimer, stopProfilerTimerIfRunningAndRecordDelta, } from './ReactProfilerTimer'; @@ -261,6 +264,7 @@ let pendingPassiveEffectsRenderPriority: ReactPriorityLevel = NoPriority; let pendingPassiveEffectsExpirationTime: ExpirationTime = NoWork; let pendingPassiveHookEffectsMount: Array = []; let pendingPassiveHookEffectsUnmount: Array = []; +let pendingPassiveProfilerEffects: Array = []; let rootsWithPendingDiscreteUpdates: Map< FiberRoot, @@ -2179,6 +2183,19 @@ export function flushPassiveEffects() { } } +export function enqueuePendingPassiveProfilerEffect(fiber: Fiber): void { + if (enableProfilerTimer) { + pendingPassiveProfilerEffects.push(fiber); + if (!rootDoesHavePassiveEffects) { + rootDoesHavePassiveEffects = true; + scheduleCallback(NormalPriority, () => { + flushPassiveEffects(); + return null; + }); + } + } +} + export function enqueuePendingPassiveHookEffectMount( fiber: Fiber, effect: HookEffect, @@ -2220,6 +2237,7 @@ function flushPassiveEffectsImpl() { if (rootWithPendingPassiveEffects === null) { return false; } + const root = rootWithPendingPassiveEffects; const expirationTime = pendingPassiveEffectsExpirationTime; rootWithPendingPassiveEffects = null; @@ -2252,7 +2270,13 @@ function flushPassiveEffectsImpl() { if (typeof destroy === 'function') { if (__DEV__) { setCurrentDebugFiberInDEV(fiber); - invokeGuardedCallback(null, destroy, null); + if (enableProfilerTimer && fiber.mode & ProfileMode) { + startPassiveEffectTimer(); + invokeGuardedCallback(null, destroy, null); + recordPassiveEffectDuration(fiber); + } else { + invokeGuardedCallback(null, destroy, null); + } if (hasCaughtError()) { invariant(fiber !== null, 'Should be working on an effect.'); const error = clearCaughtError(); @@ -2261,7 +2285,16 @@ function flushPassiveEffectsImpl() { resetCurrentDebugFiberInDEV(); } else { try { - destroy(); + if (enableProfilerTimer && fiber.mode & ProfileMode) { + try { + startPassiveEffectTimer(); + destroy(); + } finally { + recordPassiveEffectDuration(fiber); + } + } else { + destroy(); + } } catch (error) { invariant(fiber !== null, 'Should be working on an effect.'); captureCommitPhaseError(fiber, error); @@ -2269,7 +2302,6 @@ function flushPassiveEffectsImpl() { } } } - // Second pass: Create new passive effects. let mountEffects = pendingPassiveHookEffectsMount; pendingPassiveHookEffectsMount = []; @@ -2278,7 +2310,13 @@ function flushPassiveEffectsImpl() { const fiber = ((mountEffects[i + 1]: any): Fiber); if (__DEV__) { setCurrentDebugFiberInDEV(fiber); - invokeGuardedCallback(null, invokePassiveEffectCreate, null, effect); + if (enableProfilerTimer && fiber.mode & ProfileMode) { + startPassiveEffectTimer(); + invokeGuardedCallback(null, invokePassiveEffectCreate, null, effect); + recordPassiveEffectDuration(fiber); + } else { + invokeGuardedCallback(null, invokePassiveEffectCreate, null, effect); + } if (hasCaughtError()) { invariant(fiber !== null, 'Should be working on an effect.'); const error = clearCaughtError(); @@ -2288,7 +2326,16 @@ function flushPassiveEffectsImpl() { } else { try { const create = effect.create; - effect.destroy = create(); + if (enableProfilerTimer && fiber.mode & ProfileMode) { + try { + startPassiveEffectTimer(); + effect.destroy = create(); + } finally { + recordPassiveEffectDuration(fiber); + } + } else { + effect.destroy = create(); + } } catch (error) { invariant(fiber !== null, 'Should be working on an effect.'); captureCommitPhaseError(fiber, error); @@ -2318,6 +2365,7 @@ function flushPassiveEffectsImpl() { captureCommitPhaseError(effect, error); } } + const nextNextEffect = effect.nextEffect; // Remove nextEffect pointer to assist GC effect.nextEffect = null; @@ -2325,6 +2373,15 @@ function flushPassiveEffectsImpl() { } } + if (enableProfilerTimer) { + let profilerEffects = pendingPassiveProfilerEffects; + pendingPassiveProfilerEffects = []; + for (let i = 0; i < profilerEffects.length; i++) { + const fiber = ((profilerEffects[i]: any): Fiber); + commitPassiveEffectDurations(root, fiber); + } + } + if (enableSchedulerTracing) { popInteractions(((prevInteractions: any): Set)); finishPendingInteractions(root, expirationTime); diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js index c26f66d96924..7e51418bbcdf 100644 --- a/packages/react-reconciler/src/ReactProfilerTimer.js +++ b/packages/react-reconciler/src/ReactProfilerTimer.js @@ -10,6 +10,7 @@ import type {Fiber} from './ReactFiber'; import {enableProfilerTimer} from 'shared/ReactFeatureFlags'; +import {Profiler} from 'shared/ReactWorkTags'; // Intentionally not named imports because Rollup would use dynamic dispatch for // CommonJS interop named imports. @@ -27,7 +28,9 @@ export type ProfilerTimer = { }; let commitTime: number = 0; +let layoutEffectStartTime: number = -1; let profilerStartTime: number = -1; +let passiveEffectStartTime: number = -1; function getCommitTime(): number { return commitTime; @@ -77,9 +80,78 @@ function stopProfilerTimerIfRunningAndRecordDelta( } } +function recordLayoutEffectDuration(fiber: Fiber): void { + if (!enableProfilerTimer) { + return; + } + + if (layoutEffectStartTime >= 0) { + const elapsedTime = now() - layoutEffectStartTime; + + layoutEffectStartTime = -1; + + // Store duration on the next nearest Profiler ancestor. + let parentFiber = fiber.return; + while (parentFiber !== null) { + if (parentFiber.tag === Profiler) { + const parentStateNode = parentFiber.stateNode; + parentStateNode.effectDuration += elapsedTime; + break; + } + parentFiber = parentFiber.return; + } + } +} + +function recordPassiveEffectDuration(fiber: Fiber): void { + if (!enableProfilerTimer) { + return; + } + + if (passiveEffectStartTime >= 0) { + const elapsedTime = now() - passiveEffectStartTime; + + passiveEffectStartTime = -1; + + // Store duration on the next nearest Profiler ancestor. + let parentFiber = fiber.return; + while (parentFiber !== null) { + if (parentFiber.tag === Profiler) { + const parentStateNode = parentFiber.stateNode; + if (parentStateNode !== null) { + // Detached fibers have their state node cleared out. + // In this case, the return pointer is also cleared out, + // so we won't be able to report the time spent in this Profiler's subtree. + parentStateNode.passiveEffectDuration += elapsedTime; + } + break; + } + parentFiber = parentFiber.return; + } + } +} + +function startLayoutEffectTimer(): void { + if (!enableProfilerTimer) { + return; + } + layoutEffectStartTime = now(); +} + +function startPassiveEffectTimer(): void { + if (!enableProfilerTimer) { + return; + } + passiveEffectStartTime = now(); +} + export { getCommitTime, recordCommitTime, + recordLayoutEffectDuration, + recordPassiveEffectDuration, + startLayoutEffectTimer, + startPassiveEffectTimer, startProfilerTimer, stopProfilerTimerIfRunning, stopProfilerTimerIfRunningAndRecordDelta, diff --git a/packages/react/src/__tests__/ReactProfiler-test.internal.js b/packages/react/src/__tests__/ReactProfiler-test.internal.js index ad47793c8259..1f693beebccc 100644 --- a/packages/react/src/__tests__/ReactProfiler-test.internal.js +++ b/packages/react/src/__tests__/ReactProfiler-test.internal.js @@ -24,6 +24,7 @@ let TextResource; let resourcePromise; function loadModules({ + deferPassiveEffectCleanupDuringUnmount = false, enableProfilerTimer = true, enableSchedulerTracing = true, replayFailedUnitOfWorkWithInvokeGuardedCallback = false, @@ -31,6 +32,7 @@ function loadModules({ } = {}) { ReactFeatureFlags = require('shared/ReactFeatureFlags'); ReactFeatureFlags.debugRenderPhaseSideEffectsForStrictMode = false; + ReactFeatureFlags.deferPassiveEffectCleanupDuringUnmount = deferPassiveEffectCleanupDuringUnmount; ReactFeatureFlags.enableProfilerTimer = enableProfilerTimer; ReactFeatureFlags.enableSchedulerTracing = enableSchedulerTracing; ReactFeatureFlags.replayFailedUnitOfWorkWithInvokeGuardedCallback = replayFailedUnitOfWorkWithInvokeGuardedCallback; @@ -120,10 +122,9 @@ describe('Profiler', () => { it('should warn if required params are missing', () => { expect(() => { ReactTestRenderer.create(); - }).toErrorDev( - 'Profiler must specify an "id" string and "onRender" function as props', - {withoutStack: true}, - ); + }).toErrorDev('Profiler must specify an "id" as a prop', { + withoutStack: true, + }); }); } @@ -182,1084 +183,2282 @@ describe('Profiler', () => { }); }); - [true, false].forEach(enableSchedulerTracing => { - describe('onRender callback', () => { - beforeEach(() => { - jest.resetModules(); + [true, false].forEach(deferPassiveEffectCleanupDuringUnmount => { + [true, false].forEach(enableSchedulerTracing => { + describe(`onRender enableSchedulerTracing:${ + enableSchedulerTracing ? 'enabled' : 'disabled' + } deferPassiveEffectCleanupDuringUnmount:${ + deferPassiveEffectCleanupDuringUnmount ? 'enabled' : 'disabled' + }`, () => { + beforeEach(() => { + jest.resetModules(); + + loadModules({ + deferPassiveEffectCleanupDuringUnmount, + enableSchedulerTracing, + }); + }); - loadModules({enableSchedulerTracing}); - }); + it('should handle errors thrown', () => { + const callback = jest.fn(id => { + if (id === 'throw') { + throw Error('expected'); + } + }); - it('should handle errors thrown', () => { - const callback = jest.fn(id => { - if (id === 'throw') { - throw Error('expected'); + let didMount = false; + class ClassComponent extends React.Component { + componentDidMount() { + didMount = true; + } + render() { + return this.props.children; + } } + + // Errors thrown from onRender should not break the commit phase, + // Or prevent other lifecycles from being called. + expect(() => + ReactTestRenderer.create( + + + +
+ + + , + ), + ).toThrow('expected'); + expect(didMount).toBe(true); + expect(callback).toHaveBeenCalledTimes(2); }); - let didMount = false; - class ClassComponent extends React.Component { - componentDidMount() { - didMount = true; - } - render() { - return this.props.children; - } - } + it('is not invoked until the commit phase', () => { + const callback = jest.fn(); - // Errors thrown from onRender should not break the commit phase, - // Or prevent other lifecycles from being called. - expect(() => - ReactTestRenderer.create( - - - -
- - - , - ), - ).toThrow('expected'); - expect(didMount).toBe(true); - expect(callback).toHaveBeenCalledTimes(2); - }); + const Yield = ({value}) => { + Scheduler.unstable_yieldValue(value); + return null; + }; - it('is not invoked until the commit phase', () => { - const callback = jest.fn(); + ReactTestRenderer.create( + + + + , + { + unstable_isConcurrent: true, + }, + ); - const Yield = ({value}) => { - Scheduler.unstable_yieldValue(value); - return null; - }; + // Times are logged until a render is committed. + expect(Scheduler).toFlushAndYieldThrough(['first']); + expect(callback).toHaveBeenCalledTimes(0); + expect(Scheduler).toFlushAndYield(['last']); + expect(callback).toHaveBeenCalledTimes(1); + }); - ReactTestRenderer.create( - - - - , - { - unstable_isConcurrent: true, - }, - ); + it('does not record times for components outside of Profiler tree', () => { + // Mock the Scheduler module so we can track how many times the current + // time is read + jest.mock('scheduler', obj => { + const ActualScheduler = require.requireActual( + 'scheduler/unstable_mock', + ); + return { + ...ActualScheduler, + unstable_now: function mockUnstableNow() { + ActualScheduler.unstable_yieldValue('read current time'); + return ActualScheduler.unstable_now(); + }, + }; + }); - // Times are logged until a render is committed. - expect(Scheduler).toFlushAndYieldThrough(['first']); - expect(callback).toHaveBeenCalledTimes(0); - expect(Scheduler).toFlushAndYield(['last']); - expect(callback).toHaveBeenCalledTimes(1); - }); + jest.resetModules(); - it('does not record times for components outside of Profiler tree', () => { - // Mock the Scheduler module so we can track how many times the current - // time is read - jest.mock('scheduler', obj => { - const ActualScheduler = require.requireActual( - 'scheduler/unstable_mock', - ); - return { - ...ActualScheduler, - unstable_now: function mockUnstableNow() { - ActualScheduler.unstable_yieldValue('read current time'); - return ActualScheduler.unstable_now(); - }, - }; - }); + loadModules({enableSchedulerTracing}); - jest.resetModules(); + // Clear yields in case the current time is read during initialization. + Scheduler.unstable_clearYields(); - loadModules({enableSchedulerTracing}); + ReactTestRenderer.create( +
+ + + + + +
, + ); - // Clear yields in case the current time is read during initialization. - Scheduler.unstable_clearYields(); + // Should be called two times: + // 2. To compute the update expiration time + // 3. To record the commit time + // No additional calls from ProfilerTimer are expected. + expect(Scheduler).toHaveYielded([ + 'read current time', + 'read current time', + ]); - ReactTestRenderer.create( -
- - - - - -
, - ); + // Restore original mock + jest.mock('scheduler', () => + require.requireActual('scheduler/unstable_mock'), + ); + }); - // Should be called two times: - // 2. To compute the update expiration time - // 3. To record the commit time - // No additional calls from ProfilerTimer are expected. - expect(Scheduler).toHaveYielded([ - 'read current time', - 'read current time', - ]); + it('does not report work done on a sibling', () => { + const callback = jest.fn(); - // Restore original mock - jest.mock('scheduler', () => - require.requireActual('scheduler/unstable_mock'), - ); - }); + const DoesNotUpdate = React.memo( + function DoesNotUpdateInner() { + Scheduler.unstable_advanceTime(10); + return null; + }, + () => true, + ); - it('does not report work done on a sibling', () => { - const callback = jest.fn(); + let updateProfilerSibling; - const DoesNotUpdate = React.memo( - function DoesNotUpdateInner() { - Scheduler.unstable_advanceTime(10); + function ProfilerSibling() { + const [count, setCount] = React.useState(0); + updateProfilerSibling = () => setCount(count + 1); return null; - }, - () => true, - ); - - let updateProfilerSibling; + } - function ProfilerSibling() { - const [count, setCount] = React.useState(0); - updateProfilerSibling = () => setCount(count + 1); - return null; - } + function App() { + return ( + + + + + + + ); + } - function App() { - return ( - - - - - - - ); - } + const renderer = ReactTestRenderer.create(); - const renderer = ReactTestRenderer.create(); + expect(callback).toHaveBeenCalledTimes(1); - expect(callback).toHaveBeenCalledTimes(1); + let call = callback.mock.calls[0]; - let call = callback.mock.calls[0]; + expect(call).toHaveLength(enableSchedulerTracing ? 7 : 6); + expect(call[0]).toBe('test'); + expect(call[1]).toBe('mount'); + expect(call[2]).toBe(10); // actual time + expect(call[3]).toBe(10); // base time + expect(call[4]).toBe(0); // start time + expect(call[5]).toBe(10); // commit time + expect(call[6]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events - expect(call).toHaveLength(enableSchedulerTracing ? 7 : 6); - expect(call[0]).toBe('test'); - expect(call[1]).toBe('mount'); - expect(call[2]).toBe(10); // actual time - expect(call[3]).toBe(10); // base time - expect(call[4]).toBe(0); // start time - expect(call[5]).toBe(10); // commit time - expect(call[6]).toEqual(enableSchedulerTracing ? new Set() : undefined); // interaction events + callback.mockReset(); - callback.mockReset(); + Scheduler.unstable_advanceTime(20); // 10 -> 30 - Scheduler.unstable_advanceTime(20); // 10 -> 30 + // Updating a parent should report a re-render, + // since React technically did a little bit of work between the Profiler and the bailed out subtree. + renderer.update(); - // Updating a parent should report a re-render, - // since React technically did a little bit of work between the Profiler and the bailed out subtree. - renderer.update(); + expect(callback).toHaveBeenCalledTimes(1); - expect(callback).toHaveBeenCalledTimes(1); + call = callback.mock.calls[0]; - call = callback.mock.calls[0]; + expect(call).toHaveLength(enableSchedulerTracing ? 7 : 6); + expect(call[0]).toBe('test'); + expect(call[1]).toBe('update'); + expect(call[2]).toBe(0); // actual time + expect(call[3]).toBe(10); // base time + expect(call[4]).toBe(30); // start time + expect(call[5]).toBe(30); // commit time + expect(call[6]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events - expect(call).toHaveLength(enableSchedulerTracing ? 7 : 6); - expect(call[0]).toBe('test'); - expect(call[1]).toBe('update'); - expect(call[2]).toBe(0); // actual time - expect(call[3]).toBe(10); // base time - expect(call[4]).toBe(30); // start time - expect(call[5]).toBe(30); // commit time - expect(call[6]).toEqual(enableSchedulerTracing ? new Set() : undefined); // interaction events + callback.mockReset(); - callback.mockReset(); + Scheduler.unstable_advanceTime(20); // 30 -> 50 - Scheduler.unstable_advanceTime(20); // 30 -> 50 + // Updating a sibling should not report a re-render. + ReactTestRenderer.act(updateProfilerSibling); - // Updating a sibling should not report a re-render. - ReactTestRenderer.act(updateProfilerSibling); + expect(callback).not.toHaveBeenCalled(); + }); - expect(callback).not.toHaveBeenCalled(); - }); + it('logs render times for both mount and update', () => { + const callback = jest.fn(); - it('logs render times for both mount and update', () => { - const callback = jest.fn(); + Scheduler.unstable_advanceTime(5); // 0 -> 5 - Scheduler.unstable_advanceTime(5); // 0 -> 5 + const renderer = ReactTestRenderer.create( + + + , + ); - const renderer = ReactTestRenderer.create( - - - , - ); + expect(callback).toHaveBeenCalledTimes(1); - expect(callback).toHaveBeenCalledTimes(1); + let [call] = callback.mock.calls; - let [call] = callback.mock.calls; + expect(call).toHaveLength(enableSchedulerTracing ? 7 : 6); + expect(call[0]).toBe('test'); + expect(call[1]).toBe('mount'); + expect(call[2]).toBe(10); // actual time + expect(call[3]).toBe(10); // base time + expect(call[4]).toBe(5); // start time + expect(call[5]).toBe(15); // commit time + expect(call[6]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events - expect(call).toHaveLength(enableSchedulerTracing ? 7 : 6); - expect(call[0]).toBe('test'); - expect(call[1]).toBe('mount'); - expect(call[2]).toBe(10); // actual time - expect(call[3]).toBe(10); // base time - expect(call[4]).toBe(5); // start time - expect(call[5]).toBe(15); // commit time - expect(call[6]).toEqual(enableSchedulerTracing ? new Set() : undefined); // interaction events + callback.mockReset(); - callback.mockReset(); + Scheduler.unstable_advanceTime(20); // 15 -> 35 - Scheduler.unstable_advanceTime(20); // 15 -> 35 + renderer.update( + + + , + ); - renderer.update( - - - , - ); + expect(callback).toHaveBeenCalledTimes(1); - expect(callback).toHaveBeenCalledTimes(1); + [call] = callback.mock.calls; - [call] = callback.mock.calls; + expect(call).toHaveLength(enableSchedulerTracing ? 7 : 6); + expect(call[0]).toBe('test'); + expect(call[1]).toBe('update'); + expect(call[2]).toBe(10); // actual time + expect(call[3]).toBe(10); // base time + expect(call[4]).toBe(35); // start time + expect(call[5]).toBe(45); // commit time + expect(call[6]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events - expect(call).toHaveLength(enableSchedulerTracing ? 7 : 6); - expect(call[0]).toBe('test'); - expect(call[1]).toBe('update'); - expect(call[2]).toBe(10); // actual time - expect(call[3]).toBe(10); // base time - expect(call[4]).toBe(35); // start time - expect(call[5]).toBe(45); // commit time - expect(call[6]).toEqual(enableSchedulerTracing ? new Set() : undefined); // interaction events + callback.mockReset(); - callback.mockReset(); + Scheduler.unstable_advanceTime(20); // 45 -> 65 - Scheduler.unstable_advanceTime(20); // 45 -> 65 + renderer.update( + + + , + ); - renderer.update( - - - , - ); + expect(callback).toHaveBeenCalledTimes(1); - expect(callback).toHaveBeenCalledTimes(1); + [call] = callback.mock.calls; + + expect(call).toHaveLength(enableSchedulerTracing ? 7 : 6); + expect(call[0]).toBe('test'); + expect(call[1]).toBe('update'); + expect(call[2]).toBe(4); // actual time + expect(call[3]).toBe(4); // base time + expect(call[4]).toBe(65); // start time + expect(call[5]).toBe(69); // commit time + expect(call[6]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + }); - [call] = callback.mock.calls; + it('includes render times of nested Profilers in their parent times', () => { + const callback = jest.fn(); - expect(call).toHaveLength(enableSchedulerTracing ? 7 : 6); - expect(call[0]).toBe('test'); - expect(call[1]).toBe('update'); - expect(call[2]).toBe(4); // actual time - expect(call[3]).toBe(4); // base time - expect(call[4]).toBe(65); // start time - expect(call[5]).toBe(69); // commit time - expect(call[6]).toEqual(enableSchedulerTracing ? new Set() : undefined); // interaction events - }); + Scheduler.unstable_advanceTime(5); // 0 -> 5 - it('includes render times of nested Profilers in their parent times', () => { - const callback = jest.fn(); + ReactTestRenderer.create( + + + + + + + + + , + ); - Scheduler.unstable_advanceTime(5); // 0 -> 5 + expect(callback).toHaveBeenCalledTimes(2); - ReactTestRenderer.create( - - - - - - - - - , - ); + // 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(childCall[4]).toBe(15); // start time + expect(childCall[5]).toBe(35); // commit time + expect(parentCall[2]).toBe(30); // actual time + expect(parentCall[3]).toBe(30); // base time + expect(parentCall[4]).toBe(5); // start time + expect(parentCall[5]).toBe(35); // commit time + }); - 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(childCall[4]).toBe(15); // start time - expect(childCall[5]).toBe(35); // commit time - expect(parentCall[2]).toBe(30); // actual time - expect(parentCall[3]).toBe(30); // base time - expect(parentCall[4]).toBe(5); // start time - expect(parentCall[5]).toBe(35); // commit time - }); + it('traces sibling Profilers separately', () => { + const callback = jest.fn(); - it('traces sibling Profilers separately', () => { - const callback = jest.fn(); + Scheduler.unstable_advanceTime(5); // 0 -> 5 - Scheduler.unstable_advanceTime(5); // 0 -> 5 + ReactTestRenderer.create( + + + + + + + + , + ); - ReactTestRenderer.create( - - - - - - - - , - ); + expect(callback).toHaveBeenCalledTimes(2); - 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(firstCall[4]).toBe(5); // start time - expect(firstCall[5]).toBe(30); // commit time - expect(secondCall[2]).toBe(5); // actual time - expect(secondCall[3]).toBe(5); // base time - expect(secondCall[4]).toBe(25); // start time - expect(secondCall[5]).toBe(30); // commit time - }); + 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(firstCall[4]).toBe(5); // start time + expect(firstCall[5]).toBe(30); // commit time + expect(secondCall[2]).toBe(5); // actual time + expect(secondCall[3]).toBe(5); // base time + expect(secondCall[4]).toBe(25); // start time + expect(secondCall[5]).toBe(30); // commit time + }); - it('does not include time spent outside of profile root', () => { - const callback = jest.fn(); + it('does not include time spent outside of profile root', () => { + const callback = jest.fn(); - Scheduler.unstable_advanceTime(5); // 0 -> 5 + Scheduler.unstable_advanceTime(5); // 0 -> 5 - ReactTestRenderer.create( - - - - - - - , - ); + ReactTestRenderer.create( + + + + + + + , + ); - expect(callback).toHaveBeenCalledTimes(1); + 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 - expect(call[4]).toBe(25); // start time - expect(call[5]).toBe(50); // commit time - }); + const [call] = callback.mock.calls; + expect(call[0]).toBe('test'); + expect(call[2]).toBe(5); // actual time + expect(call[3]).toBe(5); // base time + expect(call[4]).toBe(25); // start time + expect(call[5]).toBe(50); // commit time + }); - it('is not called when blocked by sCU false', () => { - const callback = jest.fn(); + 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; + let instance; + class Updater extends React.Component { + state = {}; + render() { + instance = this; + return this.props.children; + } } - } - const renderer = ReactTestRenderer.create( - - - -
- - - , - ); + const renderer = ReactTestRenderer.create( + + + +
+ + + , + ); - // All profile callbacks are called for initial render - expect(callback).toHaveBeenCalledTimes(2); + // All profile callbacks are called for initial render + expect(callback).toHaveBeenCalledTimes(2); - callback.mockReset(); + callback.mockReset(); - renderer.unstable_flushSync(() => { - instance.setState({ - count: 1, + renderer.unstable_flushSync(() => { + instance.setState({ + count: 1, + }); }); - }); - // Only call onRender for paths that have re-rendered. - // Since the Updater's props didn't change, - // React does not re-render its children. - expect(callback).toHaveBeenCalledTimes(1); - expect(callback.mock.calls[0][0]).toBe('outer'); - }); + // Only call onRender for paths that have re-rendered. + // Since the Updater's props didn't change, + // React does not re-render its children. + expect(callback).toHaveBeenCalledTimes(1); + expect(callback.mock.calls[0][0]).toBe('outer'); + }); - it('decreases actual time but not base time when sCU prevents an update', () => { - const callback = jest.fn(); + it('decreases actual time but not base time when sCU prevents an update', () => { + const callback = jest.fn(); - Scheduler.unstable_advanceTime(5); // 0 -> 5 + Scheduler.unstable_advanceTime(5); // 0 -> 5 - const renderer = ReactTestRenderer.create( - - - - - , - ); + const renderer = ReactTestRenderer.create( + + + + + , + ); - expect(callback).toHaveBeenCalledTimes(1); + expect(callback).toHaveBeenCalledTimes(1); - Scheduler.unstable_advanceTime(30); // 28 -> 58 + Scheduler.unstable_advanceTime(30); // 28 -> 58 - renderer.update( - - - - - , - ); + renderer.update( + + + + + , + ); - expect(callback).toHaveBeenCalledTimes(2); + expect(callback).toHaveBeenCalledTimes(2); - const [mountCall, updateCall] = callback.mock.calls; + const [mountCall, updateCall] = callback.mock.calls; - expect(mountCall[1]).toBe('mount'); - expect(mountCall[2]).toBe(23); // actual time - expect(mountCall[3]).toBe(23); // base time - expect(mountCall[4]).toBe(5); // start time - expect(mountCall[5]).toBe(28); // commit time + expect(mountCall[1]).toBe('mount'); + expect(mountCall[2]).toBe(23); // actual time + expect(mountCall[3]).toBe(23); // base time + expect(mountCall[4]).toBe(5); // start time + expect(mountCall[5]).toBe(28); // commit time - expect(updateCall[1]).toBe('update'); - expect(updateCall[2]).toBe(4); // actual time - expect(updateCall[3]).toBe(17); // base time - expect(updateCall[4]).toBe(58); // start time - expect(updateCall[5]).toBe(62); // commit time - }); + expect(updateCall[1]).toBe('update'); + expect(updateCall[2]).toBe(4); // actual time + expect(updateCall[3]).toBe(17); // base time + expect(updateCall[4]).toBe(58); // start time + expect(updateCall[5]).toBe(62); // commit time + }); - it('includes time spent in render phase lifecycles', () => { - class WithLifecycles extends React.Component { - state = {}; - static getDerivedStateFromProps() { - Scheduler.unstable_advanceTime(3); - return null; - } - shouldComponentUpdate() { - Scheduler.unstable_advanceTime(7); - return true; - } - render() { - Scheduler.unstable_advanceTime(5); - return null; + it('includes time spent in render phase lifecycles', () => { + class WithLifecycles extends React.Component { + state = {}; + static getDerivedStateFromProps() { + Scheduler.unstable_advanceTime(3); + return null; + } + shouldComponentUpdate() { + Scheduler.unstable_advanceTime(7); + return true; + } + render() { + Scheduler.unstable_advanceTime(5); + return null; + } } - } - - const callback = jest.fn(); - - Scheduler.unstable_advanceTime(5); // 0 -> 5 - const renderer = ReactTestRenderer.create( - - - , - ); + const callback = jest.fn(); - Scheduler.unstable_advanceTime(15); // 13 -> 28 + Scheduler.unstable_advanceTime(5); // 0 -> 5 - renderer.update( - - - , - ); + const renderer = ReactTestRenderer.create( + + + , + ); - expect(callback).toHaveBeenCalledTimes(2); + Scheduler.unstable_advanceTime(15); // 13 -> 28 - const [mountCall, updateCall] = callback.mock.calls; + renderer.update( + + + , + ); - expect(mountCall[1]).toBe('mount'); - expect(mountCall[2]).toBe(8); // actual time - expect(mountCall[3]).toBe(8); // base time - expect(mountCall[4]).toBe(5); // start time - expect(mountCall[5]).toBe(13); // commit time + expect(callback).toHaveBeenCalledTimes(2); - expect(updateCall[1]).toBe('update'); - expect(updateCall[2]).toBe(15); // actual time - expect(updateCall[3]).toBe(15); // base time - expect(updateCall[4]).toBe(28); // start time - expect(updateCall[5]).toBe(43); // commit time - }); + const [mountCall, updateCall] = callback.mock.calls; - describe('with regard to interruptions', () => { - it('should accumulate actual time after a scheduling interruptions', () => { - const callback = jest.fn(); + expect(mountCall[1]).toBe('mount'); + expect(mountCall[2]).toBe(8); // actual time + expect(mountCall[3]).toBe(8); // base time + expect(mountCall[4]).toBe(5); // start time + expect(mountCall[5]).toBe(13); // commit time - const Yield = ({renderTime}) => { - Scheduler.unstable_advanceTime(renderTime); - Scheduler.unstable_yieldValue('Yield:' + renderTime); - return null; - }; + expect(updateCall[1]).toBe('update'); + expect(updateCall[2]).toBe(15); // actual time + expect(updateCall[3]).toBe(15); // base time + expect(updateCall[4]).toBe(28); // start time + expect(updateCall[5]).toBe(43); // commit time + }); - Scheduler.unstable_advanceTime(5); // 0 -> 5 + describe('with regard to interruptions', () => { + it('should accumulate actual time after a scheduling interruptions', () => { + const callback = jest.fn(); - // Render partially, but run out of time before completing. - ReactTestRenderer.create( - - - - , - {unstable_isConcurrent: true}, - ); - expect(Scheduler).toFlushAndYieldThrough(['Yield:2']); - expect(callback).toHaveBeenCalledTimes(0); + const Yield = ({renderTime}) => { + Scheduler.unstable_advanceTime(renderTime); + Scheduler.unstable_yieldValue('Yield:' + renderTime); + return null; + }; - // Resume render for remaining children. - expect(Scheduler).toFlushAndYield(['Yield:3']); + Scheduler.unstable_advanceTime(5); // 0 -> 5 - // Verify that logged times include both durations above. - expect(callback).toHaveBeenCalledTimes(1); - const [call] = callback.mock.calls; - expect(call[2]).toBe(5); // actual time - expect(call[3]).toBe(5); // base time - expect(call[4]).toBe(5); // start time - expect(call[5]).toBe(10); // commit time + // Render partially, but run out of time before completing. + ReactTestRenderer.create( + + + + , + {unstable_isConcurrent: true}, + ); + expect(Scheduler).toFlushAndYieldThrough(['Yield:2']); + expect(callback).toHaveBeenCalledTimes(0); + + // Resume render for remaining children. + expect(Scheduler).toFlushAndYield(['Yield:3']); + + // Verify that logged times include both durations above. + expect(callback).toHaveBeenCalledTimes(1); + const [call] = callback.mock.calls; + expect(call[2]).toBe(5); // actual time + expect(call[3]).toBe(5); // base time + expect(call[4]).toBe(5); // start time + expect(call[5]).toBe(10); // commit time + }); + + it('should not include time between frames', () => { + const callback = jest.fn(); + + const Yield = ({renderTime}) => { + Scheduler.unstable_advanceTime(renderTime); + Scheduler.unstable_yieldValue('Yield:' + renderTime); + return null; + }; + + Scheduler.unstable_advanceTime(5); // 0 -> 5 + + // Render partially, but don't finish. + // This partial render should take 5ms of simulated time. + ReactTestRenderer.create( + + + + + + + , + {unstable_isConcurrent: true}, + ); + expect(Scheduler).toFlushAndYieldThrough(['Yield:5']); + expect(callback).toHaveBeenCalledTimes(0); + + // Simulate time moving forward while frame is paused. + Scheduler.unstable_advanceTime(50); // 10 -> 60 + + // Flush the remaining work, + // Which should take an additional 10ms of simulated time. + expect(Scheduler).toFlushAndYield(['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(innerCall[4]).toBe(70); // start time + expect(innerCall[5]).toBe(87); // commit time + expect(outerCall[0]).toBe('outer'); + expect(outerCall[2]).toBe(32); // actual time + expect(outerCall[3]).toBe(32); // base time + expect(outerCall[4]).toBe(5); // start time + expect(outerCall[5]).toBe(87); // commit time + }); + + it('should report the expected times when a high-pri update replaces a mount in-progress', () => { + const callback = jest.fn(); + + const Yield = ({renderTime}) => { + Scheduler.unstable_advanceTime(renderTime); + Scheduler.unstable_yieldValue('Yield:' + renderTime); + return null; + }; + + Scheduler.unstable_advanceTime(5); // 0 -> 5 + + // Render a partially update, but don't finish. + // This partial render should take 10ms of simulated time. + const renderer = ReactTestRenderer.create( + + + + , + {unstable_isConcurrent: true}, + ); + expect(Scheduler).toFlushAndYieldThrough(['Yield:10']); + expect(callback).toHaveBeenCalledTimes(0); + + // Simulate time moving forward while frame is paused. + Scheduler.unstable_advanceTime(100); // 15 -> 115 + + // Interrupt with higher priority work. + // The interrupted work simulates an additional 5ms of time. + renderer.unstable_flushSync(() => { + renderer.update( + + + , + ); + }); + expect(Scheduler).toHaveYielded(['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 + expect(call[4]).toBe(115); // start time + expect(call[5]).toBe(120); // commit time + + callback.mockReset(); + + // Verify no more unexpected callbacks from low priority work + expect(Scheduler).toFlushWithoutYielding(); + 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}) => { + Scheduler.unstable_advanceTime(renderTime); + Scheduler.unstable_yieldValue('Yield:' + renderTime); + return null; + }; + + Scheduler.unstable_advanceTime(5); // 0 -> 5 + + const renderer = ReactTestRenderer.create( + + + + , + {unstable_isConcurrent: true}, + ); + + // Render everything initially. + // This should take 21 seconds of actual and base time. + expect(Scheduler).toFlushAndYield(['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 + expect(call[4]).toBe(5); // start time + expect(call[5]).toBe(26); // commit time + + callback.mockReset(); + + Scheduler.unstable_advanceTime(30); // 26 -> 56 + + // Render a partially update, but don't finish. + // This partial render should take 3ms of simulated time. + renderer.update( + + + + + , + ); + expect(Scheduler).toFlushAndYieldThrough(['Yield:3']); + expect(callback).toHaveBeenCalledTimes(0); + + // Simulate time moving forward while frame is paused. + Scheduler.unstable_advanceTime(100); // 59 -> 159 + + // Render another 5ms of simulated time. + expect(Scheduler).toFlushAndYieldThrough(['Yield:5']); + expect(callback).toHaveBeenCalledTimes(0); + + // Simulate time moving forward while frame is paused. + Scheduler.unstable_advanceTime(100); // 164 -> 264 + + // Interrupt with higher priority work. + // The interrupted work simulates an additional 11ms of time. + renderer.unstable_flushSync(() => { + renderer.update( + + + , + ); + }); + expect(Scheduler).toHaveYielded(['Yield:11']); + + // The actual time should include only the most recent render, + // Because this lets us avoid a lot of commit phase reset complexity. + // The base time includes only the final rendered tree times. + expect(callback).toHaveBeenCalledTimes(1); + call = callback.mock.calls[0]; + expect(call[2]).toBe(11); // actual time + expect(call[3]).toBe(11); // base time + expect(call[4]).toBe(264); // start time + expect(call[5]).toBe(275); // commit time + + // Verify no more unexpected callbacks from low priority work + expect(Scheduler).toFlushAndYield([]); + 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}) => { + Scheduler.unstable_advanceTime(renderTime); + Scheduler.unstable_yieldValue('Yield:' + renderTime); + return null; + }; + + let first; + class FirstComponent extends React.Component { + state = {renderTime: 1}; + render() { + first = this; + Scheduler.unstable_advanceTime(this.state.renderTime); + Scheduler.unstable_yieldValue( + 'FirstComponent:' + this.state.renderTime, + ); + return ; + } + } + let second; + class SecondComponent extends React.Component { + state = {renderTime: 2}; + render() { + second = this; + Scheduler.unstable_advanceTime(this.state.renderTime); + Scheduler.unstable_yieldValue( + 'SecondComponent:' + this.state.renderTime, + ); + return ; + } + } + + Scheduler.unstable_advanceTime(5); // 0 -> 5 + + const renderer = ReactTestRenderer.create( + + + + , + {unstable_isConcurrent: 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(Scheduler).toFlushAndYield([ + '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 + expect(call[4]).toBe(5); // start time + expect(call[5]).toBe(19); // commit time + + callback.mockClear(); + + Scheduler.unstable_advanceTime(100); // 19 -> 119 + + // Render a partially update, but don't finish. + // This partial render will take 10ms of actual render time. + first.setState({renderTime: 10}); + expect(Scheduler).toFlushAndYieldThrough(['FirstComponent:10']); + expect(callback).toHaveBeenCalledTimes(0); + + // Simulate time moving forward while frame is paused. + Scheduler.unstable_advanceTime(100); // 129 -> 229 + + // Interrupt with higher priority work. + // This simulates a total of 37ms of actual render time. + renderer.unstable_flushSync(() => + second.setState({renderTime: 30}), + ); + expect(Scheduler).toHaveYielded(['SecondComponent:30', 'Yield:7']); + + // The actual time should include only the most recent render (37ms), + // Because this greatly simplifies the commit phase logic. + // 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(37); // actual time + expect(call[3]).toBe(42); // base time + expect(call[4]).toBe(229); // start time + expect(call[5]).toBe(266); // commit time + + callback.mockClear(); + + // Simulate time moving forward while frame is paused. + Scheduler.unstable_advanceTime(100); // 266 -> 366 + + // 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(Scheduler).toFlushAndYield(['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 + expect(call[4]).toBe(366); // start time + expect(call[5]).toBe(380); // commit time + }); + + [true, false].forEach( + replayFailedUnitOfWorkWithInvokeGuardedCallback => { + describe(`replayFailedUnitOfWorkWithInvokeGuardedCallback ${ + replayFailedUnitOfWorkWithInvokeGuardedCallback + ? 'enabled' + : 'disabled' + }`, () => { + beforeEach(() => { + jest.resetModules(); + + loadModules({ + replayFailedUnitOfWorkWithInvokeGuardedCallback, + }); + }); + + it('should accumulate actual time after an error handled by componentDidCatch()', () => { + const callback = jest.fn(); + + const ThrowsError = () => { + Scheduler.unstable_advanceTime(3); + throw Error('expected error'); + }; + + class ErrorBoundary extends React.Component { + state = {error: null}; + componentDidCatch(error) { + this.setState({error}); + } + render() { + Scheduler.unstable_advanceTime(2); + return this.state.error === null ? ( + this.props.children + ) : ( + + ); + } + } + + Scheduler.unstable_advanceTime(5); // 0 -> 5 + + 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 2) + // But it spends time rendering all of the failed subtree also. + expect(mountCall[1]).toBe('mount'); + // actual time includes: 2 (ErrorBoundary) + 9 (AdvanceTime) + 3 (ThrowsError) + // We don't count the time spent in replaying the failed unit of work (ThrowsError) + expect(mountCall[2]).toBe(14); + // base time includes: 2 (ErrorBoundary) + // Since the tree is empty for the initial commit + expect(mountCall[3]).toBe(2); + // start time + expect(mountCall[4]).toBe(5); + // commit time: 5 initially + 14 of work + // Add an additional 3 (ThrowsError) if we replayed the failed work + expect(mountCall[5]).toBe( + __DEV__ && replayFailedUnitOfWorkWithInvokeGuardedCallback + ? 22 + : 19, + ); + + // 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); + // start time + expect(updateCall[4]).toBe( + __DEV__ && replayFailedUnitOfWorkWithInvokeGuardedCallback + ? 22 + : 19, + ); + // commit time: 19 (startTime) + 2 (ErrorBoundary) + 20 (AdvanceTime) + // Add an additional 3 (ThrowsError) if we replayed the failed work + expect(updateCall[5]).toBe( + __DEV__ && replayFailedUnitOfWorkWithInvokeGuardedCallback + ? 44 + : 41, + ); + }); + + it('should accumulate actual time after an error handled by getDerivedStateFromError()', () => { + const callback = jest.fn(); + + const ThrowsError = () => { + Scheduler.unstable_advanceTime(10); + throw Error('expected error'); + }; + + class ErrorBoundary extends React.Component { + state = {error: null}; + static getDerivedStateFromError(error) { + return {error}; + } + render() { + Scheduler.unstable_advanceTime(2); + return this.state.error === null ? ( + this.props.children + ) : ( + + ); + } + } + + Scheduler.unstable_advanceTime(5); // 0 -> 5 + + 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 it 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) + // We don't count the time spent in replaying the failed unit of work (ThrowsError) + expect(mountCall[2]).toBe(39); + // base time includes: 2 (ErrorBoundary) + 20 (AdvanceTime) + expect(mountCall[3]).toBe(22); + // start time + expect(mountCall[4]).toBe(5); + // commit time + expect(mountCall[5]).toBe( + __DEV__ && replayFailedUnitOfWorkWithInvokeGuardedCallback + ? 54 + : 44, + ); + }); + + it('should reset the fiber stack correct after a "complete" phase error', () => { + jest.resetModules(); + + loadModules({ + useNoopRenderer: true, + replayFailedUnitOfWorkWithInvokeGuardedCallback, + }); + + // Simulate a renderer error during the "complete" phase. + // This mimics behavior like React Native's View/Text nesting validation. + ReactNoop.render( + + hi + , + ); + expect(Scheduler).toFlushAndThrow('Error in host config.'); + + // A similar case we've seen caused by an invariant in ReactDOM. + // It didn't reproduce without a host component inside. + ReactNoop.render( + + + hi + + , + ); + expect(Scheduler).toFlushAndThrow('Error in host config.'); + + // So long as the profiler timer's fiber stack is reset correctly, + // Subsequent renders should not error. + ReactNoop.render( + + hi + , + ); + expect(Scheduler).toFlushWithoutYielding(); + }); + }); + }, + ); }); - it('should not include time between frames', () => { + it('reflects the most recently rendered id value', () => { const callback = jest.fn(); - const Yield = ({renderTime}) => { - Scheduler.unstable_advanceTime(renderTime); - Scheduler.unstable_yieldValue('Yield:' + renderTime); + Scheduler.unstable_advanceTime(5); // 0 -> 5 + + const renderer = ReactTestRenderer.create( + + + , + ); + + expect(callback).toHaveBeenCalledTimes(1); + + Scheduler.unstable_advanceTime(20); // 7 -> 27 + + 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(mountCall[4]).toBe(5); // start 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 + expect(updateCall[4]).toBe(27); // start time + }); + + it('should not be called until after mutations', () => { + let classComponentMounted = false; + const callback = jest.fn( + ( + id, + phase, + actualDuration, + baseDuration, + startTime, + commitTime, + ) => { + // Don't call this hook until after mutations + expect(classComponentMounted).toBe(true); + // But the commit time should reflect pre-mutation + expect(commitTime).toBe(2); + }, + ); + + class ClassComponent extends React.Component { + componentDidMount() { + Scheduler.unstable_advanceTime(5); + classComponentMounted = true; + } + render() { + Scheduler.unstable_advanceTime(2); + return null; + } + } + + ReactTestRenderer.create( + + + , + ); + + expect(callback).toHaveBeenCalledTimes(1); + }); + }); + + describe(`onCommit enableSchedulerTracing:${ + enableSchedulerTracing ? 'enabled' : 'disabled' + } deferPassiveEffectCleanupDuringUnmount:${ + deferPassiveEffectCleanupDuringUnmount ? 'enabled' : 'disabled' + }`, () => { + beforeEach(() => { + jest.resetModules(); + + loadModules({ + deferPassiveEffectCleanupDuringUnmount, + enableSchedulerTracing, + }); + }); + + it('should report time spent in layout effects and commit lifecycles', () => { + const callback = jest.fn(); + + const ComponetWithEffects = () => { + React.useLayoutEffect(() => { + Scheduler.unstable_advanceTime(10); + return () => { + Scheduler.unstable_advanceTime(100); + }; + }, []); + React.useLayoutEffect(() => { + Scheduler.unstable_advanceTime(1000); + return () => { + Scheduler.unstable_advanceTime(10000); + }; + }); + React.useEffect(() => { + // This passive effect is here to verify that its time isn't reported. + Scheduler.unstable_advanceTime(5); + return () => { + Scheduler.unstable_advanceTime(7); + }; + }); return null; }; - Scheduler.unstable_advanceTime(5); // 0 -> 5 + class ComponentWithCommitHooks extends React.Component { + componentDidMount() { + Scheduler.unstable_advanceTime(100000); + } + componentDidUpdate() { + Scheduler.unstable_advanceTime(1000000); + } + render() { + return null; + } + } - // Render partially, but don't finish. - // This partial render should take 5ms of simulated time. - ReactTestRenderer.create( - - - - - - + Scheduler.unstable_advanceTime(1); + + const renderer = ReactTestRenderer.create( + + + , - {unstable_isConcurrent: true}, ); - expect(Scheduler).toFlushAndYieldThrough(['Yield:5']); - expect(callback).toHaveBeenCalledTimes(0); - // Simulate time moving forward while frame is paused. - Scheduler.unstable_advanceTime(50); // 10 -> 60 + expect(callback).toHaveBeenCalledTimes(1); + + let call = callback.mock.calls[0]; + + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('mount-test'); + expect(call[1]).toBe('mount'); + expect(call[2]).toBe(101010); // durations + expect(call[3]).toBe(1); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + + Scheduler.unstable_advanceTime(1); + + renderer.update( + + + + , + ); + + expect(callback).toHaveBeenCalledTimes(2); + + call = callback.mock.calls[1]; + + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('update-test'); + expect(call[1]).toBe('update'); + expect(call[2]).toBe(1011000); // durations + expect(call[3]).toBe(101017); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + + Scheduler.unstable_advanceTime(1); + + renderer.update( + , + ); + + expect(callback).toHaveBeenCalledTimes(3); + + call = callback.mock.calls[2]; + + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('unmount-test'); + expect(call[1]).toBe('update'); + expect(call[2]).toBe(10100); // durations + expect(call[3]).toBe(1112030); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + }); + + it('should report time spent in layout effects and commit lifecycles with cascading renders', () => { + const callback = jest.fn(); + + const ComponetWithEffects = ({shouldCascade}) => { + const [didCascade, setDidCascade] = React.useState(false); + React.useLayoutEffect(() => { + if (shouldCascade && !didCascade) { + setDidCascade(true); + } + Scheduler.unstable_advanceTime(didCascade ? 30 : 10); + return () => { + Scheduler.unstable_advanceTime(100); + }; + }, [didCascade, shouldCascade]); + return null; + }; + + class ComponentWithCommitHooks extends React.Component { + state = { + didCascade: false, + }; + componentDidMount() { + Scheduler.unstable_advanceTime(1000); + } + componentDidUpdate() { + Scheduler.unstable_advanceTime(10000); + if (this.props.shouldCascade && !this.state.didCascade) { + this.setState({didCascade: true}); + } + } + render() { + return null; + } + } + + Scheduler.unstable_advanceTime(1); + + const renderer = ReactTestRenderer.create( + + + + , + ); + + expect(callback).toHaveBeenCalledTimes(2); + + let call = callback.mock.calls[0]; + + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('mount-test'); + expect(call[1]).toBe('mount'); + expect(call[2]).toBe(1010); // durations + expect(call[3]).toBe(1); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + + call = callback.mock.calls[1]; + + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('mount-test'); + expect(call[1]).toBe('update'); + expect(call[2]).toBe(130); // durations + expect(call[3]).toBe(1011); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + + Scheduler.unstable_advanceTime(1); + + renderer.update( + + + + , + ); + + expect(callback).toHaveBeenCalledTimes(4); + + call = callback.mock.calls[2]; + + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('update-test'); + expect(call[1]).toBe('update'); + expect(call[2]).toBe(10130); // durations + expect(call[3]).toBe(1142); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + + call = callback.mock.calls[3]; + + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('update-test'); + expect(call[1]).toBe('update'); + expect(call[2]).toBe(10000); // durations + expect(call[3]).toBe(11272); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + }); + + it('should bubble time spent in layout effects to higher profilers', () => { + const callback = jest.fn(); + + const ComponetWithEffects = ({ + cleanupDuration, + duration, + setCountRef, + }) => { + const setCount = React.useState(0)[1]; + if (setCountRef != null) { + setCountRef.current = setCount; + } + React.useLayoutEffect(() => { + Scheduler.unstable_advanceTime(duration); + return () => { + Scheduler.unstable_advanceTime(cleanupDuration); + }; + }); + Scheduler.unstable_advanceTime(1); + return null; + }; + + const setCountRef = React.createRef(null); + + let renderer = null; + ReactTestRenderer.act(() => { + renderer = ReactTestRenderer.create( + + + + + + + + , + ); + }); + + expect(callback).toHaveBeenCalledTimes(1); + + let call = callback.mock.calls[0]; + + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('root-mount'); + expect(call[1]).toBe('mount'); + expect(call[2]).toBe(1010); // durations + expect(call[3]).toBe(2); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + + ReactTestRenderer.act(() => setCountRef.current(count => count + 1)); + + expect(callback).toHaveBeenCalledTimes(2); + + call = callback.mock.calls[1]; + + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('root-mount'); + expect(call[1]).toBe('update'); + expect(call[2]).toBe(110); // durations + expect(call[3]).toBe(1013); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + + ReactTestRenderer.act(() => { + renderer.update( + + + + + , + ); + }); + + expect(callback).toHaveBeenCalledTimes(3); + + call = callback.mock.calls[2]; + + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('root-update'); + expect(call[1]).toBe('update'); + expect(call[2]).toBe(1100); // durations + expect(call[3]).toBe(1124); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + }); + + it('should properly report time in layout effects even when there are errors', () => { + const callback = jest.fn(); + + class ErrorBoundary extends React.Component { + state = {error: null}; + static getDerivedStateFromError(error) { + return {error}; + } + render() { + return this.state.error === null + ? this.props.children + : this.props.fallback; + } + } + + const ComponetWithEffects = ({ + cleanupDuration, + duration, + effectDuration, + shouldThrow, + }) => { + React.useLayoutEffect(() => { + Scheduler.unstable_advanceTime(effectDuration); + if (shouldThrow) { + throw Error('expected'); + } + return () => { + Scheduler.unstable_advanceTime(cleanupDuration); + }; + }); + Scheduler.unstable_advanceTime(duration); + return null; + }; + + Scheduler.unstable_advanceTime(1); + + // Test an error that happens during an effect + + ReactTestRenderer.act(() => { + ReactTestRenderer.create( + + + }> + + + + , + ); + }); + + expect(callback).toHaveBeenCalledTimes(2); + + let call = callback.mock.calls[0]; + + // Initial render (with error) + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('root'); + expect(call[1]).toBe('mount'); + expect(call[2]).toBe(100100); // durations + expect(call[3]).toBe(10011); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + + call = callback.mock.calls[1]; + + // Cleanup render from error boundary + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('root'); + expect(call[1]).toBe('update'); + expect(call[2]).toBe(100000000); // durations + expect(call[3]).toBe(10110111); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + }); + + it('should properly report time in layout effect cleanup functions even when there are errors', () => { + const callback = jest.fn(); + + class ErrorBoundary extends React.Component { + state = {error: null}; + static getDerivedStateFromError(error) { + return {error}; + } + render() { + return this.state.error === null + ? this.props.children + : this.props.fallback; + } + } + + const ComponetWithEffects = ({ + cleanupDuration, + duration, + effectDuration, + shouldThrow = false, + }) => { + React.useLayoutEffect(() => { + Scheduler.unstable_advanceTime(effectDuration); + return () => { + Scheduler.unstable_advanceTime(cleanupDuration); + if (shouldThrow) { + throw Error('expected'); + } + }; + }); + Scheduler.unstable_advanceTime(duration); + return null; + }; + + Scheduler.unstable_advanceTime(1); + + let renderer = null; + + ReactTestRenderer.act(() => { + renderer = ReactTestRenderer.create( + + + }> + + + + , + ); + }); + + expect(callback).toHaveBeenCalledTimes(1); + + let call = callback.mock.calls[0]; + + // Initial render + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('root'); + expect(call[1]).toBe('mount'); + expect(call[2]).toBe(100100); // durations + expect(call[3]).toBe(10011); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + + callback.mockClear(); + + // Test an error that happens during an cleanup function + + ReactTestRenderer.act(() => { + renderer.update( + + + }> + + + + , + ); + }); + + expect(callback).toHaveBeenCalledTimes(2); + + call = callback.mock.calls[0]; + + // Update (that throws) + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('root'); + expect(call[1]).toBe('update'); + expect(call[2]).toBe(1101100); // durations + expect(call[3]).toBe(120121); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + + call = callback.mock.calls[1]; + + // Cleanup render from error boundary + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('root'); + expect(call[1]).toBe('update'); + expect(call[2]).toBe(100001000); // durations + expect(call[3]).toBe(11221221); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + }); + + if (enableSchedulerTracing) { + it('should report interactions that were active', () => { + const callback = jest.fn(); + + const ComponetWithEffects = () => { + const [didMount, setDidMount] = React.useState(false); + React.useLayoutEffect(() => { + Scheduler.unstable_advanceTime(didMount ? 1000 : 100); + if (!didMount) { + setDidMount(true); + } + return () => { + Scheduler.unstable_advanceTime(10000); + }; + }, [didMount]); + Scheduler.unstable_advanceTime(10); + return null; + }; + + const interaction = { + id: 0, + name: 'mount', + timestamp: Scheduler.unstable_now(), + }; + + Scheduler.unstable_advanceTime(1); + + SchedulerTracing.unstable_trace( + interaction.name, + interaction.timestamp, + () => { + ReactTestRenderer.create( + + + , + ); + }, + ); + + expect(callback).toHaveBeenCalledTimes(2); + + let call = callback.mock.calls[0]; + + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('root'); + expect(call[1]).toBe('mount'); + expect(call[4]).toMatchInteractions([interaction]); + + call = callback.mock.calls[1]; + + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('root'); + expect(call[1]).toBe('update'); + expect(call[4]).toMatchInteractions([interaction]); + }); + } + }); + + describe(`onPostCommit enableSchedulerTracing:${ + enableSchedulerTracing ? 'enabled' : 'disabled' + } deferPassiveEffectCleanupDuringUnmount:${ + deferPassiveEffectCleanupDuringUnmount ? 'enabled' : 'disabled' + }`, () => { + beforeEach(() => { + jest.resetModules(); + + loadModules({ + deferPassiveEffectCleanupDuringUnmount, + enableSchedulerTracing, + }); + }); + + it('should report time spent in passive effects', () => { + const callback = jest.fn(); + + const ComponetWithEffects = () => { + React.useLayoutEffect(() => { + // This layout effect is here to verify that its time isn't reported. + Scheduler.unstable_advanceTime(5); + return () => { + Scheduler.unstable_advanceTime(7); + }; + }); + React.useEffect(() => { + Scheduler.unstable_advanceTime(10); + return () => { + Scheduler.unstable_advanceTime(100); + }; + }, []); + React.useEffect(() => { + Scheduler.unstable_advanceTime(1000); + return () => { + Scheduler.unstable_advanceTime(10000); + }; + }); + return null; + }; + + Scheduler.unstable_advanceTime(1); + + let renderer; + ReactTestRenderer.act(() => { + renderer = ReactTestRenderer.create( + + + , + ); + }); + Scheduler.unstable_flushAll(); + + expect(callback).toHaveBeenCalledTimes(1); + + let call = callback.mock.calls[0]; + + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('mount-test'); + expect(call[1]).toBe('mount'); + expect(call[2]).toBe(1010); // durations + expect(call[3]).toBe(1); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + + Scheduler.unstable_advanceTime(1); + + ReactTestRenderer.act(() => { + renderer.update( + + + , + ); + }); + Scheduler.unstable_flushAll(); - // Flush the remaining work, - // Which should take an additional 10ms of simulated time. - expect(Scheduler).toFlushAndYield(['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(innerCall[4]).toBe(70); // start time - expect(innerCall[5]).toBe(87); // commit time - expect(outerCall[0]).toBe('outer'); - expect(outerCall[2]).toBe(32); // actual time - expect(outerCall[3]).toBe(32); // base time - expect(outerCall[4]).toBe(5); // start time - expect(outerCall[5]).toBe(87); // commit time + call = callback.mock.calls[1]; + + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('update-test'); + expect(call[1]).toBe('update'); + expect(call[2]).toBe(11000); // durations + expect(call[3]).toBe(1017); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + + Scheduler.unstable_advanceTime(1); + + ReactTestRenderer.act(() => { + renderer.update( + , + ); + }); + Scheduler.unstable_flushAll(); + + expect(callback).toHaveBeenCalledTimes(3); + + call = callback.mock.calls[2]; + + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('unmount-test'); + expect(call[1]).toBe('update'); + // TODO (bvaughn) The duration reported below should be 10100, but is 0 + // by the time the passive effect is flushed its parent Fiber pointer is gone. + // If we refactor to preserve the unmounted Fiber tree we could fix this. + // The current implementation would require too much extra overhead to track this. + expect(call[2]).toBe(0); // durations + expect(call[3]).toBe(12030); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events }); - it('should report the expected times when a high-pri update replaces a mount in-progress', () => { + it('should report time spent in passive effects with cascading renders', () => { const callback = jest.fn(); - const Yield = ({renderTime}) => { - Scheduler.unstable_advanceTime(renderTime); - Scheduler.unstable_yieldValue('Yield:' + renderTime); + const ComponetWithEffects = () => { + const [didMount, setDidMount] = React.useState(false); + React.useEffect(() => { + if (!didMount) { + setDidMount(true); + } + Scheduler.unstable_advanceTime(didMount ? 30 : 10); + return () => { + Scheduler.unstable_advanceTime(100); + }; + }, [didMount]); return null; }; - Scheduler.unstable_advanceTime(5); // 0 -> 5 - - // Render a partially update, but don't finish. - // This partial render should take 10ms of simulated time. - const renderer = ReactTestRenderer.create( - - - - , - {unstable_isConcurrent: true}, - ); - expect(Scheduler).toFlushAndYieldThrough(['Yield:10']); - expect(callback).toHaveBeenCalledTimes(0); - - // Simulate time moving forward while frame is paused. - Scheduler.unstable_advanceTime(100); // 15 -> 115 + Scheduler.unstable_advanceTime(1); - // Interrupt with higher priority work. - // The interrupted work simulates an additional 5ms of time. - renderer.unstable_flushSync(() => { - renderer.update( - - + ReactTestRenderer.act(() => { + ReactTestRenderer.create( + + , ); }); - expect(Scheduler).toHaveYielded(['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 - expect(call[4]).toBe(115); // start time - expect(call[5]).toBe(120); // commit time + expect(callback).toHaveBeenCalledTimes(2); - callback.mockReset(); + let call = callback.mock.calls[0]; - // Verify no more unexpected callbacks from low priority work - expect(Scheduler).toFlushWithoutYielding(); - expect(callback).toHaveBeenCalledTimes(0); + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('mount-test'); + expect(call[1]).toBe('mount'); + expect(call[2]).toBe(10); // durations + expect(call[3]).toBe(1); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + + call = callback.mock.calls[1]; + + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('mount-test'); + expect(call[1]).toBe('update'); + expect(call[2]).toBe(130); // durations + expect(call[3]).toBe(11); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events }); - it('should report the expected times when a high-priority update replaces a low-priority update', () => { + it('should bubble time spent in effects to higher profilers', () => { const callback = jest.fn(); - const Yield = ({renderTime}) => { - Scheduler.unstable_advanceTime(renderTime); - Scheduler.unstable_yieldValue('Yield:' + renderTime); + const ComponetWithEffects = ({ + cleanupDuration, + duration, + setCountRef, + }) => { + const setCount = React.useState(0)[1]; + if (setCountRef != null) { + setCountRef.current = setCount; + } + React.useEffect(() => { + Scheduler.unstable_advanceTime(duration); + return () => { + Scheduler.unstable_advanceTime(cleanupDuration); + }; + }); + Scheduler.unstable_advanceTime(1); return null; }; - Scheduler.unstable_advanceTime(5); // 0 -> 5 + const setCountRef = React.createRef(null); - const renderer = ReactTestRenderer.create( - - - - , - {unstable_isConcurrent: true}, - ); + let renderer = null; + ReactTestRenderer.act(() => { + renderer = ReactTestRenderer.create( + + + + + + + + , + ); + }); - // Render everything initially. - // This should take 21 seconds of actual and base time. - expect(Scheduler).toFlushAndYield(['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 - expect(call[4]).toBe(5); // start time - expect(call[5]).toBe(26); // commit time - callback.mockReset(); + let call = callback.mock.calls[0]; - Scheduler.unstable_advanceTime(30); // 26 -> 56 + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('root-mount'); + expect(call[1]).toBe('mount'); + expect(call[2]).toBe(1010); // durations + expect(call[3]).toBe(2); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events - // Render a partially update, but don't finish. - // This partial render should take 3ms of simulated time. - renderer.update( - - - - - , - ); - expect(Scheduler).toFlushAndYieldThrough(['Yield:3']); - expect(callback).toHaveBeenCalledTimes(0); + ReactTestRenderer.act(() => setCountRef.current(count => count + 1)); - // Simulate time moving forward while frame is paused. - Scheduler.unstable_advanceTime(100); // 59 -> 159 + expect(callback).toHaveBeenCalledTimes(2); - // Render another 5ms of simulated time. - expect(Scheduler).toFlushAndYieldThrough(['Yield:5']); - expect(callback).toHaveBeenCalledTimes(0); + call = callback.mock.calls[1]; - // Simulate time moving forward while frame is paused. - Scheduler.unstable_advanceTime(100); // 164 -> 264 + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('root-mount'); + expect(call[1]).toBe('update'); + expect(call[2]).toBe(110); // durations + expect(call[3]).toBe(1013); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events - // Interrupt with higher priority work. - // The interrupted work simulates an additional 11ms of time. - renderer.unstable_flushSync(() => { + ReactTestRenderer.act(() => { renderer.update( - - + + + + , ); }); - expect(Scheduler).toHaveYielded(['Yield:11']); - // The actual time should include only the most recent render, - // Because this lets us avoid a lot of commit phase reset complexity. - // The base time includes only the final rendered tree times. - expect(callback).toHaveBeenCalledTimes(1); - call = callback.mock.calls[0]; - expect(call[2]).toBe(11); // actual time - expect(call[3]).toBe(11); // base time - expect(call[4]).toBe(264); // start time - expect(call[5]).toBe(275); // commit time + expect(callback).toHaveBeenCalledTimes(3); - // Verify no more unexpected callbacks from low priority work - expect(Scheduler).toFlushAndYield([]); - expect(callback).toHaveBeenCalledTimes(1); + call = callback.mock.calls[2]; + + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('root-update'); + expect(call[1]).toBe('update'); + expect(call[2]).toBe(1100); // durations + expect(call[3]).toBe(1124); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events }); - it('should report the expected times when a high-priority update interrupts a low-priority update', () => { + it('should properly report time in passive effects even when there are errors', () => { const callback = jest.fn(); - const Yield = ({renderTime}) => { - Scheduler.unstable_advanceTime(renderTime); - Scheduler.unstable_yieldValue('Yield:' + renderTime); - return null; - }; - - let first; - class FirstComponent extends React.Component { - state = {renderTime: 1}; - render() { - first = this; - Scheduler.unstable_advanceTime(this.state.renderTime); - Scheduler.unstable_yieldValue( - 'FirstComponent:' + this.state.renderTime, - ); - return ; + class ErrorBoundary extends React.Component { + state = {error: null}; + static getDerivedStateFromError(error) { + return {error}; } - } - let second; - class SecondComponent extends React.Component { - state = {renderTime: 2}; render() { - second = this; - Scheduler.unstable_advanceTime(this.state.renderTime); - Scheduler.unstable_yieldValue( - 'SecondComponent:' + this.state.renderTime, - ); - return ; + return this.state.error === null + ? this.props.children + : this.props.fallback; } } - Scheduler.unstable_advanceTime(5); // 0 -> 5 - - const renderer = ReactTestRenderer.create( - - - - , - {unstable_isConcurrent: 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(Scheduler).toFlushAndYield([ - '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 - expect(call[4]).toBe(5); // start time - expect(call[5]).toBe(19); // commit time - - callback.mockClear(); - - Scheduler.unstable_advanceTime(100); // 19 -> 119 - - // Render a partially update, but don't finish. - // This partial render will take 10ms of actual render time. - first.setState({renderTime: 10}); - expect(Scheduler).toFlushAndYieldThrough(['FirstComponent:10']); - expect(callback).toHaveBeenCalledTimes(0); + const ComponetWithEffects = ({ + cleanupDuration, + duration, + effectDuration, + shouldThrow, + }) => { + React.useEffect(() => { + Scheduler.unstable_advanceTime(effectDuration); + if (shouldThrow) { + throw Error('expected'); + } + return () => { + Scheduler.unstable_advanceTime(cleanupDuration); + }; + }); + Scheduler.unstable_advanceTime(duration); + return null; + }; - // Simulate time moving forward while frame is paused. - Scheduler.unstable_advanceTime(100); // 129 -> 229 + Scheduler.unstable_advanceTime(1); - // Interrupt with higher priority work. - // This simulates a total of 37ms of actual render time. - renderer.unstable_flushSync(() => second.setState({renderTime: 30})); - expect(Scheduler).toHaveYielded(['SecondComponent:30', 'Yield:7']); + // Test an error that happens during an effect - // The actual time should include only the most recent render (37ms), - // Because this greatly simplifies the commit phase logic. - // 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(37); // actual time - expect(call[3]).toBe(42); // base time - expect(call[4]).toBe(229); // start time - expect(call[5]).toBe(266); // commit time + ReactTestRenderer.act(() => { + ReactTestRenderer.create( + + + }> + + + + , + ); + }); - callback.mockClear(); + expect(callback).toHaveBeenCalledTimes(2); - // Simulate time moving forward while frame is paused. - Scheduler.unstable_advanceTime(100); // 266 -> 366 + let call = callback.mock.calls[0]; - // 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(Scheduler).toFlushAndYield(['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 - expect(call[4]).toBe(366); // start time - expect(call[5]).toBe(380); // commit time + // Initial render (with error) + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('root'); + expect(call[1]).toBe('mount'); + expect(call[2]).toBe(100100); // durations + expect(call[3]).toBe(10011); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + + call = callback.mock.calls[1]; + + // Cleanup render from error boundary + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('root'); + expect(call[1]).toBe('update'); + expect(call[2]).toBe(100000000); // durations + expect(call[3]).toBe(10110111); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events }); - [true, false].forEach( - replayFailedUnitOfWorkWithInvokeGuardedCallback => { - describe(`replayFailedUnitOfWorkWithInvokeGuardedCallback ${ - replayFailedUnitOfWorkWithInvokeGuardedCallback - ? 'enabled' - : 'disabled' - }`, () => { - beforeEach(() => { - jest.resetModules(); - - loadModules({ - replayFailedUnitOfWorkWithInvokeGuardedCallback, - }); - }); - - it('should accumulate actual time after an error handled by componentDidCatch()', () => { - const callback = jest.fn(); + it('should properly report time in passive effect cleanup functions even when there are errors', () => { + const callback = jest.fn(); - const ThrowsError = () => { - Scheduler.unstable_advanceTime(3); - throw Error('expected error'); - }; + class ErrorBoundary extends React.Component { + state = {error: null}; + static getDerivedStateFromError(error) { + return {error}; + } + render() { + return this.state.error === null + ? this.props.children + : this.props.fallback; + } + } - class ErrorBoundary extends React.Component { - state = {error: null}; - componentDidCatch(error) { - this.setState({error}); - } - render() { - Scheduler.unstable_advanceTime(2); - return this.state.error === null ? ( - this.props.children - ) : ( - - ); - } + const ComponetWithEffects = ({ + cleanupDuration, + duration, + effectDuration, + shouldThrow = false, + id, + }) => { + React.useEffect(() => { + Scheduler.unstable_advanceTime(effectDuration); + return () => { + Scheduler.unstable_advanceTime(cleanupDuration); + if (shouldThrow) { + throw Error('expected'); } + }; + }); + Scheduler.unstable_advanceTime(duration); + return null; + }; - Scheduler.unstable_advanceTime(5); // 0 -> 5 - - ReactTestRenderer.create( - - - - - - , - ); + Scheduler.unstable_advanceTime(1); - expect(callback).toHaveBeenCalledTimes(2); - - // Callbacks bubble (reverse order). - let [mountCall, updateCall] = callback.mock.calls; - - // The initial mount only includes the ErrorBoundary (which takes 2) - // But it spends time rendering all of the failed subtree also. - expect(mountCall[1]).toBe('mount'); - // actual time includes: 2 (ErrorBoundary) + 9 (AdvanceTime) + 3 (ThrowsError) - // We don't count the time spent in replaying the failed unit of work (ThrowsError) - expect(mountCall[2]).toBe(14); - // base time includes: 2 (ErrorBoundary) - // Since the tree is empty for the initial commit - expect(mountCall[3]).toBe(2); - // start time - expect(mountCall[4]).toBe(5); - // commit time: 5 initially + 14 of work - // Add an additional 3 (ThrowsError) if we replayed the failed work - expect(mountCall[5]).toBe( - __DEV__ && replayFailedUnitOfWorkWithInvokeGuardedCallback - ? 22 - : 19, - ); + let renderer = null; - // 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); - // start time - expect(updateCall[4]).toBe( - __DEV__ && replayFailedUnitOfWorkWithInvokeGuardedCallback - ? 22 - : 19, - ); - // commit time: 19 (startTime) + 2 (ErrorBoundary) + 20 (AdvanceTime) - // Add an additional 3 (ThrowsError) if we replayed the failed work - expect(updateCall[5]).toBe( - __DEV__ && replayFailedUnitOfWorkWithInvokeGuardedCallback - ? 44 - : 41, - ); - }); + ReactTestRenderer.act(() => { + renderer = ReactTestRenderer.create( + + + }> + + + + , + ); + }); - it('should accumulate actual time after an error handled by getDerivedStateFromError()', () => { - const callback = jest.fn(); + expect(callback).toHaveBeenCalledTimes(1); - const ThrowsError = () => { - Scheduler.unstable_advanceTime(10); - throw Error('expected error'); - }; + let call = callback.mock.calls[0]; - class ErrorBoundary extends React.Component { - state = {error: null}; - static getDerivedStateFromError(error) { - return {error}; - } - render() { - Scheduler.unstable_advanceTime(2); - return this.state.error === null ? ( - this.props.children - ) : ( - - ); - } - } + // Initial render + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('root'); + expect(call[1]).toBe('mount'); + expect(call[2]).toBe(100100); // durations + expect(call[3]).toBe(10011); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events - Scheduler.unstable_advanceTime(5); // 0 -> 5 + callback.mockClear(); - ReactTestRenderer.create( - - - - - - , - ); + // Test an error that happens during an cleanup function - expect(callback).toHaveBeenCalledTimes(1); - - // Callbacks bubble (reverse order). - let [mountCall] = callback.mock.calls; - - // The initial mount includes the ErrorBoundary's error state, - // But it 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) - // We don't count the time spent in replaying the failed unit of work (ThrowsError) - expect(mountCall[2]).toBe(39); - // base time includes: 2 (ErrorBoundary) + 20 (AdvanceTime) - expect(mountCall[3]).toBe(22); - // start time - expect(mountCall[4]).toBe(5); - // commit time - expect(mountCall[5]).toBe( - __DEV__ && replayFailedUnitOfWorkWithInvokeGuardedCallback - ? 54 - : 44, - ); - }); + ReactTestRenderer.act(() => { + renderer.update( + + + }> + + + + , + ); + }); - it('should reset the fiber stack correct after a "complete" phase error', () => { - jest.resetModules(); + expect(callback).toHaveBeenCalledTimes(2); - loadModules({ - useNoopRenderer: true, - replayFailedUnitOfWorkWithInvokeGuardedCallback, - }); + call = callback.mock.calls[0]; - // Simulate a renderer error during the "complete" phase. - // This mimics behavior like React Native's View/Text nesting validation. - ReactNoop.render( - - hi - , - ); - expect(Scheduler).toFlushAndThrow('Error in host config.'); + // Update (that throws) + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('root'); + expect(call[1]).toBe('update'); + // The duration varies because the flushing behavior varies when this flag is on. + // We continue flushing pending effects even if one throws. + expect(call[2]).toBe( + deferPassiveEffectCleanupDuringUnmount ? 1101100 : 1101000, + ); // durations + expect(call[3]).toBe(120121); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + + call = callback.mock.calls[1]; + + // Cleanup render from error boundary + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('root'); + expect(call[1]).toBe('update'); + expect(call[2]).toBe(100000000); // durations + // The commit time varies because the above duration time varies + expect(call[3]).toBe( + deferPassiveEffectCleanupDuringUnmount ? 11221221 : 11221121, + ); // commit start time (before mutations or effects) + expect(call[4]).toEqual( + enableSchedulerTracing ? new Set() : undefined, + ); // interaction events + }); - // A similar case we've seen caused by an invariant in ReactDOM. - // It didn't reproduce without a host component inside. - ReactNoop.render( - - - hi - - , - ); - expect(Scheduler).toFlushAndThrow('Error in host config.'); + if (enableSchedulerTracing) { + it('should report interactions that were active', () => { + const callback = jest.fn(); - // So long as the profiler timer's fiber stack is reset correctly, - // Subsequent renders should not error. - ReactNoop.render( - - hi - , - ); - expect(Scheduler).toFlushWithoutYielding(); - }); + const ComponetWithEffects = () => { + const [didMount, setDidMount] = React.useState(false); + React.useEffect(() => { + Scheduler.unstable_advanceTime(didMount ? 1000 : 100); + if (!didMount) { + setDidMount(true); + } + return () => { + Scheduler.unstable_advanceTime(10000); + }; + }, [didMount]); + Scheduler.unstable_advanceTime(10); + return null; + }; + + const interaction = { + id: 0, + name: 'mount', + timestamp: Scheduler.unstable_now(), + }; + + Scheduler.unstable_advanceTime(1); + + ReactTestRenderer.act(() => { + SchedulerTracing.unstable_trace( + interaction.name, + interaction.timestamp, + () => { + ReactTestRenderer.create( + + + , + ); + }, + ); }); - }, - ); - }); - - it('reflects the most recently rendered id value', () => { - const callback = jest.fn(); - - Scheduler.unstable_advanceTime(5); // 0 -> 5 - - const renderer = ReactTestRenderer.create( - - - , - ); - - expect(callback).toHaveBeenCalledTimes(1); - Scheduler.unstable_advanceTime(20); // 7 -> 27 + expect(callback).toHaveBeenCalledTimes(2); - renderer.update( - - - , - ); - - expect(callback).toHaveBeenCalledTimes(2); - - const [mountCall, updateCall] = callback.mock.calls; + let call = callback.mock.calls[0]; - 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(mountCall[4]).toBe(5); // start time + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('root'); + expect(call[1]).toBe('mount'); + expect(call[4]).toMatchInteractions([interaction]); - expect(updateCall[0]).toBe('two'); - expect(updateCall[1]).toBe('update'); - expect(updateCall[2]).toBe(1); // actual time - expect(updateCall[3]).toBe(1); // base time - expect(updateCall[4]).toBe(27); // start time - }); - - it('should not be called until after mutations', () => { - let classComponentMounted = false; - const callback = jest.fn( - (id, phase, actualDuration, baseDuration, startTime, commitTime) => { - // Don't call this hook until after mutations - expect(classComponentMounted).toBe(true); - // But the commit time should reflect pre-mutation - expect(commitTime).toBe(2); - }, - ); + call = callback.mock.calls[1]; - class ClassComponent extends React.Component { - componentDidMount() { - Scheduler.unstable_advanceTime(5); - classComponentMounted = true; - } - render() { - Scheduler.unstable_advanceTime(2); - return null; - } + expect(call).toHaveLength(enableSchedulerTracing ? 5 : 4); + expect(call[0]).toBe('root'); + expect(call[1]).toBe('update'); + expect(call[4]).toMatchInteractions([interaction]); + }); } - - ReactTestRenderer.create( - - - , - ); - - expect(callback).toHaveBeenCalledTimes(1); }); }); }); @@ -1540,14 +2739,16 @@ describe('Profiler', () => { timestamp: Scheduler.unstable_now(), }; - const onRender = jest.fn(); + const onPostCommit = jest.fn(() => { + Scheduler.unstable_yieldValue('onPostCommit'); + }); let renderer; SchedulerTracing.unstable_trace( interactionCreation.name, Scheduler.unstable_now(), () => { renderer = ReactTestRenderer.create( - + , { @@ -1578,13 +2779,13 @@ describe('Profiler', () => { expect(onWorkScheduled.mock.calls[0][1] > 0).toBe(true); // Mount - expect(Scheduler).toFlushAndYield(['first', 'last']); - expect(onRender).toHaveBeenCalledTimes(1); - let call = onRender.mock.calls[0]; + expect(Scheduler).toFlushAndYield(['first', 'last', 'onPostCommit']); + expect(onPostCommit).toHaveBeenCalledTimes(1); + let call = onPostCommit.mock.calls[0]; expect(call[0]).toEqual('test-profiler'); - expect(call[5]).toEqual(Scheduler.unstable_now()); + expect(call[3]).toEqual(Scheduler.unstable_now()); if (ReactFeatureFlags.enableSchedulerTracing) { - expect(call[6]).toMatchInteractions([interactionCreation]); + expect(call[4]).toMatchInteractions([interactionCreation]); } expect(onInteractionTraced).toHaveBeenCalledTimes(1); @@ -1601,7 +2802,7 @@ describe('Profiler', () => { interactionCreation, ]); - onRender.mockClear(); + onPostCommit.mockClear(); onWorkScheduled.mockClear(); onWorkStarted.mockClear(); onWorkStopped.mockClear(); @@ -1639,7 +2840,7 @@ describe('Profiler', () => { expect(onWorkScheduled.mock.calls[0][1] > 0).toBe(true); expect(Scheduler).toFlushAndYieldThrough(['first']); - expect(onRender).not.toHaveBeenCalled(); + expect(onPostCommit).not.toHaveBeenCalled(); expect(onInteractionTraced).toHaveBeenCalledTimes(2); expect(onInteractionTraced).toHaveBeenLastNotifiedOfInteraction( @@ -1652,14 +2853,14 @@ describe('Profiler', () => { ).toMatchInteractions([interactionOne]); expect(getWorkForReactThreads(onWorkStopped)).toHaveLength(0); - expect(Scheduler).toFlushAndYield(['last']); - expect(onRender).toHaveBeenCalledTimes(1); + expect(Scheduler).toFlushAndYield(['last', 'onPostCommit']); + expect(onPostCommit).toHaveBeenCalledTimes(1); - call = onRender.mock.calls[0]; + call = onPostCommit.mock.calls[0]; expect(call[0]).toEqual('test-profiler'); - expect(call[5]).toEqual(Scheduler.unstable_now()); + expect(call[3]).toEqual(Scheduler.unstable_now()); if (ReactFeatureFlags.enableSchedulerTracing) { - expect(call[6]).toMatchInteractions([interactionOne]); + expect(call[4]).toMatchInteractions([interactionOne]); } didRunCallback = true; @@ -1677,7 +2878,7 @@ describe('Profiler', () => { expect(didRunCallback).toBe(true); - onRender.mockClear(); + onPostCommit.mockClear(); onWorkScheduled.mockClear(); onWorkStarted.mockClear(); onWorkStopped.mockClear(); @@ -1686,14 +2887,14 @@ describe('Profiler', () => { // Verify that updating state again does not re-log our interaction. instance.setState({count: 3}); - expect(Scheduler).toFlushAndYield(['first', 'last']); + expect(Scheduler).toFlushAndYield(['first', 'last', 'onPostCommit']); - expect(onRender).toHaveBeenCalledTimes(1); - call = onRender.mock.calls[0]; + expect(onPostCommit).toHaveBeenCalledTimes(1); + call = onPostCommit.mock.calls[0]; expect(call[0]).toEqual('test-profiler'); - expect(call[5]).toEqual(Scheduler.unstable_now()); + expect(call[3]).toEqual(Scheduler.unstable_now()); if (ReactFeatureFlags.enableSchedulerTracing) { - expect(call[6]).toMatchInteractions([]); + expect(call[4]).toMatchInteractions([]); } expect(onInteractionTraced).toHaveBeenCalledTimes(2); @@ -1704,7 +2905,7 @@ describe('Profiler', () => { expect(getWorkForReactThreads(onWorkStarted)).toHaveLength(0); expect(getWorkForReactThreads(onWorkStopped)).toHaveLength(0); - onRender.mockClear(); + onPostCommit.mockClear(); Scheduler.unstable_advanceTime(3); @@ -1719,7 +2920,7 @@ describe('Profiler', () => { Scheduler.unstable_now(), () => { renderer.update( - + , ); @@ -1746,14 +2947,14 @@ describe('Profiler', () => { ]); expect(onWorkScheduled.mock.calls[0][1] > 0).toBe(true); - expect(Scheduler).toFlushAndYield(['first', 'last']); + expect(Scheduler).toFlushAndYield(['first', 'last', 'onPostCommit']); - expect(onRender).toHaveBeenCalledTimes(1); - call = onRender.mock.calls[0]; + expect(onPostCommit).toHaveBeenCalledTimes(1); + call = onPostCommit.mock.calls[0]; expect(call[0]).toEqual('test-profiler'); - expect(call[5]).toEqual(Scheduler.unstable_now()); + expect(call[3]).toEqual(Scheduler.unstable_now()); if (ReactFeatureFlags.enableSchedulerTracing) { - expect(call[6]).toMatchInteractions([interactionTwo]); + expect(call[4]).toMatchInteractions([interactionTwo]); } expect(onInteractionTraced).toHaveBeenCalledTimes(3); @@ -1771,8 +2972,51 @@ describe('Profiler', () => { ]); }); + it('should not mark an interaction complete while passive effects are outstanding', () => { + const onCommit = jest.fn(); + const onPostCommit = jest.fn(() => { + Scheduler.unstable_yieldValue('onPostCommit'); + }); + + const ComponetWithEffects = () => { + React.useEffect(() => { + Scheduler.unstable_yieldValue('passive effect'); + }); + React.useLayoutEffect(() => { + Scheduler.unstable_yieldValue('layout effect'); + }); + Scheduler.unstable_yieldValue('render'); + return null; + }; + + SchedulerTracing.unstable_trace('mount', Scheduler.unstable_now(), () => { + ReactTestRenderer.create( + + + , + ); + }); + + expect(Scheduler).toHaveYielded(['render', 'layout effect']); + + expect(onCommit).toHaveBeenCalled(); + expect(onPostCommit).not.toHaveBeenCalled(); + expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); + + expect(Scheduler).toFlushAndYield(['passive effect', 'onPostCommit']); + + expect(onCommit).toHaveBeenCalled(); + expect(onPostCommit).toHaveBeenCalled(); + expect(onInteractionScheduledWorkCompleted).toHaveBeenCalledTimes(1); + }); + it('should report the expected times when a high-priority update interrupts a low-priority update', () => { - const onRender = jest.fn(); + const onPostCommit = jest.fn(() => { + Scheduler.unstable_yieldValue('onPostCommit'); + }); let first; class FirstComponent extends React.Component { @@ -1796,7 +3040,7 @@ describe('Profiler', () => { Scheduler.unstable_advanceTime(5); const renderer = ReactTestRenderer.create( - + , @@ -1804,12 +3048,16 @@ describe('Profiler', () => { ); // Initial mount. - expect(Scheduler).toFlushAndYield(['FirstComponent', 'SecondComponent']); + expect(Scheduler).toFlushAndYield([ + 'FirstComponent', + 'SecondComponent', + 'onPostCommit', + ]); expect(onInteractionTraced).not.toHaveBeenCalled(); expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); - onRender.mockClear(); + onPostCommit.mockClear(); Scheduler.unstable_advanceTime(100); @@ -1832,7 +3080,7 @@ describe('Profiler', () => { ]); expect(Scheduler).toFlushAndYieldThrough(['FirstComponent']); - expect(onRender).not.toHaveBeenCalled(); + expect(onPostCommit).not.toHaveBeenCalled(); expect(onInteractionTraced).toHaveBeenCalledTimes(1); expect(onInteractionTraced).toHaveBeenLastNotifiedOfInteraction( @@ -1875,7 +3123,13 @@ describe('Profiler', () => { }, ); }); + + // Profiler tag causes passive effects to be scheduled, + // so the interactions are still not completed. expect(Scheduler).toHaveYielded(['SecondComponent']); + expect(onInteractionTraced).toHaveBeenCalledTimes(2); + expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); + expect(Scheduler).toFlushAndYieldThrough(['onPostCommit']); expect(onInteractionTraced).toHaveBeenCalledTimes(2); expect(onInteractionScheduledWorkCompleted).toHaveBeenCalledTimes(1); @@ -1884,28 +3138,28 @@ describe('Profiler', () => { ).toHaveBeenLastNotifiedOfInteraction(interactionHighPri); // Verify the high priority update was associated with the high priority event. - expect(onRender).toHaveBeenCalledTimes(1); - let call = onRender.mock.calls[0]; + expect(onPostCommit).toHaveBeenCalledTimes(1); + let call = onPostCommit.mock.calls[0]; expect(call[0]).toEqual('test'); - expect(call[5]).toEqual(Scheduler.unstable_now()); - expect(call[6]).toMatchInteractions( + expect(call[3]).toEqual(Scheduler.unstable_now()); + expect(call[4]).toMatchInteractions( ReactFeatureFlags.enableSchedulerTracing ? [interactionLowPri, interactionHighPri] : [], ); - onRender.mockClear(); + onPostCommit.mockClear(); Scheduler.unstable_advanceTime(100); // Resume the original low priority update, with rebased state. // Verify the low priority update was retained. - expect(Scheduler).toFlushAndYield(['FirstComponent']); - expect(onRender).toHaveBeenCalledTimes(1); - call = onRender.mock.calls[0]; + expect(Scheduler).toFlushAndYield(['FirstComponent', 'onPostCommit']); + expect(onPostCommit).toHaveBeenCalledTimes(1); + call = onPostCommit.mock.calls[0]; expect(call[0]).toEqual('test'); - expect(call[5]).toEqual(Scheduler.unstable_now()); - expect(call[6]).toMatchInteractions( + expect(call[3]).toEqual(Scheduler.unstable_now()); + expect(call[4]).toMatchInteractions( ReactFeatureFlags.enableSchedulerTracing ? [interactionLowPri] : [], ); @@ -1970,14 +3224,16 @@ describe('Profiler', () => { }; // Initial mount. - const onRender = jest.fn(); + const onPostCommit = jest.fn(() => { + Scheduler.unstable_yieldValue('onPostCommit'); + }); let firstCommitTime = Scheduler.unstable_now(); SchedulerTracing.unstable_trace( interactionOne.name, Scheduler.unstable_now(), () => { ReactTestRenderer.create( - + , {unstable_isConcurrent: true}, @@ -1993,7 +3249,12 @@ describe('Profiler', () => { expect(getWorkForReactThreads(onWorkStarted)).toHaveLength(0); expect(getWorkForReactThreads(onWorkStopped)).toHaveLength(0); - expect(Scheduler).toFlushAndYield(['Example:0', 'Example:1']); + expect(Scheduler).toFlushAndYield([ + 'Example:0', + 'onPostCommit', + 'Example:1', + 'onPostCommit', + ]); expect(onInteractionTraced).toHaveBeenCalledTimes(1); expect(onInteractionScheduledWorkCompleted).toHaveBeenCalledTimes(1); @@ -2015,21 +3276,21 @@ describe('Profiler', () => { interactionOne, ]); - expect(onRender).toHaveBeenCalledTimes(2); - let call = onRender.mock.calls[0]; + expect(onPostCommit).toHaveBeenCalledTimes(2); + let call = onPostCommit.mock.calls[0]; expect(call[0]).toEqual('test'); - expect(call[5]).toEqual(firstCommitTime); - expect(call[6]).toMatchInteractions( + expect(call[3]).toEqual(firstCommitTime); + expect(call[4]).toMatchInteractions( ReactFeatureFlags.enableSchedulerTracing ? [interactionOne] : [], ); - call = onRender.mock.calls[1]; + call = onPostCommit.mock.calls[1]; expect(call[0]).toEqual('test'); - expect(call[5]).toEqual(Scheduler.unstable_now()); - expect(call[6]).toMatchInteractions( + expect(call[3]).toEqual(Scheduler.unstable_now()); + expect(call[4]).toMatchInteractions( ReactFeatureFlags.enableSchedulerTracing ? [interactionOne] : [], ); - onRender.mockClear(); + onPostCommit.mockClear(); const interactionTwo = { id: 1, @@ -2045,7 +3306,7 @@ describe('Profiler', () => { instance.setState({count: 2}); }, ); - expect(onRender).not.toHaveBeenCalled(); + expect(onPostCommit).not.toHaveBeenCalled(); expect(onInteractionTraced).toHaveBeenCalledTimes(2); expect(onInteractionTraced).toHaveBeenLastNotifiedOfInteraction( interactionTwo, @@ -2059,7 +3320,12 @@ describe('Profiler', () => { // Flush async work (outside of traced scope) // This will cause an intentional cascading update from did-update firstCommitTime = Scheduler.unstable_now(); - expect(Scheduler).toFlushAndYield(['Example:2', 'Example:3']); + expect(Scheduler).toFlushAndYield([ + 'Example:2', + 'onPostCommit', + 'Example:3', + 'onPostCommit', + ]); expect(onInteractionTraced).toHaveBeenCalledTimes(2); expect(onInteractionScheduledWorkCompleted).toHaveBeenCalledTimes(2); @@ -2082,21 +3348,21 @@ describe('Profiler', () => { ]); // Verify the cascading commit is associated with the origin event - expect(onRender).toHaveBeenCalledTimes(2); - call = onRender.mock.calls[0]; + expect(onPostCommit).toHaveBeenCalledTimes(2); + call = onPostCommit.mock.calls[0]; expect(call[0]).toEqual('test'); - expect(call[5]).toEqual(firstCommitTime); - expect(call[6]).toMatchInteractions( + expect(call[3]).toEqual(firstCommitTime); + expect(call[4]).toMatchInteractions( ReactFeatureFlags.enableSchedulerTracing ? [interactionTwo] : [], ); - call = onRender.mock.calls[1]; + call = onPostCommit.mock.calls[1]; expect(call[0]).toEqual('test'); - expect(call[5]).toEqual(Scheduler.unstable_now()); - expect(call[6]).toMatchInteractions( + expect(call[3]).toEqual(Scheduler.unstable_now()); + expect(call[4]).toMatchInteractions( ReactFeatureFlags.enableSchedulerTracing ? [interactionTwo] : [], ); - onRender.mockClear(); + onPostCommit.mockClear(); const interactionThree = { id: 2, @@ -2115,7 +3381,7 @@ describe('Profiler', () => { instance.setState({count: 5}, callback); }, ); - expect(onRender).not.toHaveBeenCalled(); + expect(onPostCommit).not.toHaveBeenCalled(); expect(onInteractionTraced).toHaveBeenCalledTimes(3); expect(onInteractionTraced).toHaveBeenLastNotifiedOfInteraction( @@ -2128,7 +3394,12 @@ describe('Profiler', () => { // Flush async work (outside of traced scope) // This will cause an intentional cascading update from the setState callback firstCommitTime = Scheduler.unstable_now(); - expect(Scheduler).toFlushAndYield(['Example:5', 'Example:6']); + expect(Scheduler).toFlushAndYield([ + 'Example:5', + 'onPostCommit', + 'Example:6', + 'onPostCommit', + ]); expect(onInteractionTraced).toHaveBeenCalledTimes(3); expect(onInteractionScheduledWorkCompleted).toHaveBeenCalledTimes(3); @@ -2151,23 +3422,25 @@ describe('Profiler', () => { ]); // Verify the cascading commit is associated with the origin event - expect(onRender).toHaveBeenCalledTimes(2); - call = onRender.mock.calls[0]; + expect(onPostCommit).toHaveBeenCalledTimes(2); + call = onPostCommit.mock.calls[0]; expect(call[0]).toEqual('test'); - expect(call[5]).toEqual(firstCommitTime); - expect(call[6]).toMatchInteractions( + expect(call[3]).toEqual(firstCommitTime); + expect(call[4]).toMatchInteractions( ReactFeatureFlags.enableSchedulerTracing ? [interactionThree] : [], ); - call = onRender.mock.calls[1]; + call = onPostCommit.mock.calls[1]; expect(call[0]).toEqual('test'); - expect(call[5]).toEqual(Scheduler.unstable_now()); - expect(call[6]).toMatchInteractions( + expect(call[3]).toEqual(Scheduler.unstable_now()); + expect(call[4]).toMatchInteractions( ReactFeatureFlags.enableSchedulerTracing ? [interactionThree] : [], ); }); it('should trace interactions associated with a parent component state update', () => { - const onRender = jest.fn(); + const onPostCommit = jest.fn(() => { + Scheduler.unstable_yieldValue('onPostCommit'); + }); let parentInstance = null; class Child extends React.Component { @@ -2184,7 +3457,7 @@ describe('Profiler', () => { render() { parentInstance = this; return ( - + ); @@ -2196,8 +3469,8 @@ describe('Profiler', () => { ReactTestRenderer.create(, { unstable_isConcurrent: true, }); - expect(Scheduler).toFlushAndYield(['Child:0']); - onRender.mockClear(); + expect(Scheduler).toFlushAndYield(['Child:0', 'onPostCommit']); + onPostCommit.mockClear(); const interaction = { id: 0, @@ -2221,12 +3494,12 @@ describe('Profiler', () => { expect(getWorkForReactThreads(onWorkStarted)).toHaveLength(0); expect(getWorkForReactThreads(onWorkStopped)).toHaveLength(0); - expect(onRender).not.toHaveBeenCalled(); - expect(Scheduler).toFlushAndYield(['Child:1']); - expect(onRender).toHaveBeenCalledTimes(1); - let call = onRender.mock.calls[0]; + expect(onPostCommit).not.toHaveBeenCalled(); + expect(Scheduler).toFlushAndYield(['Child:1', 'onPostCommit']); + expect(onPostCommit).toHaveBeenCalledTimes(1); + let call = onPostCommit.mock.calls[0]; expect(call[0]).toEqual('test-profiler'); - expect(call[6]).toMatchInteractions( + expect(call[4]).toMatchInteractions( ReactFeatureFlags.enableSchedulerTracing ? [interaction] : [], ); @@ -2270,13 +3543,15 @@ describe('Profiler', () => { } } - const onRender = jest.fn(); + const onPostCommit = jest.fn(() => { + Scheduler.unstable_yieldValue('onPostCommit'); + }); SchedulerTracing.unstable_trace( interaction.name, Scheduler.unstable_now(), () => { ReactNoop.render( - + }> @@ -2300,14 +3575,15 @@ describe('Profiler', () => { 'Text [Loading...]', 'Text [Sync]', 'Monkey', + 'onPostCommit', ]); // Should have committed the placeholder. expect(ReactNoop.getChildrenAsJSX()).toEqual('Loading...Sync'); - expect(onRender).toHaveBeenCalledTimes(1); + expect(onPostCommit).toHaveBeenCalledTimes(1); - let call = onRender.mock.calls[0]; + let call = onPostCommit.mock.calls[0]; expect(call[0]).toEqual('test-profiler'); - expect(call[6]).toMatchInteractions( + expect(call[4]).toMatchInteractions( ReactFeatureFlags.enableSchedulerTracing ? [interaction] : [], ); @@ -2316,19 +3592,22 @@ describe('Profiler', () => { // An unrelated update in the middle shouldn't affect things... monkey.current.forceUpdate(); - expect(Scheduler).toFlushAndYield(['Monkey']); - expect(onRender).toHaveBeenCalledTimes(2); + expect(Scheduler).toFlushAndYield(['Monkey', 'onPostCommit']); + expect(onPostCommit).toHaveBeenCalledTimes(2); // Once the promise resolves, we render the suspended view await awaitableAdvanceTimers(20000); expect(Scheduler).toHaveYielded(['Promise resolved [Async]']); - expect(Scheduler).toFlushAndYield(['AsyncText [Async]']); + expect(Scheduler).toFlushAndYield([ + 'AsyncText [Async]', + 'onPostCommit', + ]); expect(ReactNoop.getChildrenAsJSX()).toEqual('AsyncSync'); - expect(onRender).toHaveBeenCalledTimes(3); + expect(onPostCommit).toHaveBeenCalledTimes(3); - call = onRender.mock.calls[2]; + call = onPostCommit.mock.calls[2]; expect(call[0]).toEqual('test-profiler'); - expect(call[6]).toMatchInteractions( + expect(call[4]).toMatchInteractions( ReactFeatureFlags.enableSchedulerTracing ? [interaction] : [], ); @@ -2346,13 +3625,15 @@ describe('Profiler', () => { timestamp: Scheduler.unstable_now(), }; - const onRender = jest.fn(); + const onPostCommit = jest.fn(() => + Scheduler.unstable_yieldValue('onPostCommit'), + ); SchedulerTracing.unstable_trace( interaction.name, interaction.timestamp, () => { ReactTestRenderer.create( - + }> @@ -2369,7 +3650,11 @@ describe('Profiler', () => { await resourcePromise; expect(Scheduler).toHaveYielded(['Promise resolved [loaded]']); - expect(Scheduler).toFlushExpired(['AsyncText [loaded]']); + expect(Scheduler).toFlushExpired([ + 'onPostCommit', + 'AsyncText [loaded]', + ]); + expect(Scheduler).toFlushAndYield(['onPostCommit']); expect(onInteractionScheduledWorkCompleted).toHaveBeenCalledTimes(1); expect( onInteractionScheduledWorkCompleted, @@ -2390,6 +3675,7 @@ describe('Profiler', () => { } render() { + Scheduler.unstable_yieldValue('render'); const {ms, text} = this.props; TextResource.read([text, ms]); return {this.state.hasMounted}; @@ -2402,13 +3688,15 @@ describe('Profiler', () => { timestamp: Scheduler.unstable_now(), }; - const onRender = jest.fn(); + const onPostCommit = jest.fn(() => + Scheduler.unstable_yieldValue('onPostCommit'), + ); SchedulerTracing.unstable_trace( interaction.name, interaction.timestamp, () => { ReactTestRenderer.create( - + }> @@ -2419,17 +3707,19 @@ describe('Profiler', () => { expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); - expect(Scheduler).toHaveYielded(['Text [loading]']); + expect(Scheduler).toHaveYielded(['render', 'Text [loading]']); jest.runAllTimers(); await resourcePromise; expect(Scheduler).toHaveYielded(['Promise resolved [loaded]']); - expect(Scheduler).toFlushExpired([]); + expect(Scheduler).toFlushExpired(['onPostCommit', 'render']); expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); wrappedCascadingFn(); + expect(Scheduler).toHaveYielded(['onPostCommit', 'render']); + expect(Scheduler).toFlushAndYield(['onPostCommit']); expect(onInteractionScheduledWorkCompleted).toHaveBeenCalledTimes(1); expect( @@ -2444,13 +3734,15 @@ describe('Profiler', () => { timestamp: Scheduler.unstable_now(), }; - const onRender = jest.fn(); + const onPostCommit = jest.fn(() => { + Scheduler.unstable_yieldValue('onPostCommit'); + }); SchedulerTracing.unstable_trace( interaction.name, interaction.timestamp, () => { ReactTestRenderer.create( - + }> @@ -2468,6 +3760,7 @@ describe('Profiler', () => { expect(Scheduler).toFlushAndYield([ 'Suspend [loaded]', 'Text [loading]', + 'onPostCommit', ]); expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); @@ -2475,7 +3768,10 @@ describe('Profiler', () => { await awaitableAdvanceTimers(500); expect(Scheduler).toHaveYielded(['Promise resolved [loaded]']); - expect(Scheduler).toFlushAndYield(['AsyncText [loaded]']); + expect(Scheduler).toFlushAndYield([ + 'AsyncText [loaded]', + 'onPostCommit', + ]); expect(onInteractionScheduledWorkCompleted).toHaveBeenCalledTimes(1); expect( onInteractionScheduledWorkCompleted, @@ -2489,13 +3785,15 @@ describe('Profiler', () => { timestamp: Scheduler.unstable_now(), }; - const onRender = jest.fn(); + const onPostCommit = jest.fn(() => { + Scheduler.unstable_yieldValue('onPostCommit'); + }); SchedulerTracing.unstable_trace( interaction.name, interaction.timestamp, () => { ReactTestRenderer.create( - + }> @@ -2507,6 +3805,7 @@ describe('Profiler', () => { expect(Scheduler).toFlushAndYield([ 'Suspend [loaded]', 'Text [loading]', + 'onPostCommit', ]); expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); @@ -2514,7 +3813,10 @@ describe('Profiler', () => { jest.advanceTimersByTime(100); await resourcePromise; expect(Scheduler).toHaveYielded(['Promise resolved [loaded]']); - expect(Scheduler).toFlushAndYield(['AsyncText [loaded]']); + expect(Scheduler).toFlushAndYield([ + 'AsyncText [loaded]', + 'onPostCommit', + ]); expect(onInteractionScheduledWorkCompleted).toHaveBeenCalledTimes(1); expect( @@ -2529,14 +3831,16 @@ describe('Profiler', () => { timestamp: Scheduler.unstable_now(), }; - const onRender = jest.fn(); + const onPostCommit = jest.fn(() => + Scheduler.unstable_yieldValue('onPostCommit'), + ); let renderer; SchedulerTracing.unstable_trace( initialRenderInteraction.name, initialRenderInteraction.timestamp, () => { renderer = ReactTestRenderer.create( - + }> @@ -2546,13 +3850,19 @@ describe('Profiler', () => { }, ); expect(renderer.toJSON()).toEqual(['loading', 'initial']); + expect(Scheduler).toHaveYielded([ + 'Suspend [loaded]', + 'Text [loading]', + 'Text [initial]', + ]); + expect(Scheduler).toFlushAndYield(['onPostCommit']); expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); - expect(onRender).toHaveBeenCalledTimes(1); - expect(onRender.mock.calls[0][6]).toMatchInteractions([ + expect(onPostCommit).toHaveBeenCalledTimes(1); + expect(onPostCommit.mock.calls[0][4]).toMatchInteractions([ initialRenderInteraction, ]); - onRender.mockClear(); + onPostCommit.mockClear(); const highPriUpdateInteraction = { id: 1, @@ -2568,7 +3878,7 @@ describe('Profiler', () => { highPriUpdateInteraction.timestamp, () => { renderer.update( - + }> @@ -2578,21 +3888,19 @@ describe('Profiler', () => { }, ); }); + expect(renderer.toJSON()).toEqual(['loading', 'updated']); expect(Scheduler).toHaveYielded([ - 'Suspend [loaded]', - 'Text [loading]', - 'Text [initial]', 'Suspend [loaded]', 'Text [loading]', 'Text [updated]', ]); - expect(renderer.toJSON()).toEqual(['loading', 'updated']); + expect(Scheduler).toFlushAndYield(['onPostCommit']); - expect(onRender).toHaveBeenCalledTimes(1); - expect(onRender.mock.calls[0][6]).toMatchInteractions([ + expect(onPostCommit).toHaveBeenCalledTimes(1); + expect(onPostCommit.mock.calls[0][4]).toMatchInteractions([ highPriUpdateInteraction, ]); - onRender.mockClear(); + onPostCommit.mockClear(); expect(onInteractionScheduledWorkCompleted).toHaveBeenCalledTimes(1); expect( @@ -2607,9 +3915,10 @@ describe('Profiler', () => { expect(Scheduler).toHaveYielded(['Promise resolved [loaded]']); expect(Scheduler).toFlushExpired(['AsyncText [loaded]']); expect(renderer.toJSON()).toEqual(['loaded', 'updated']); + expect(Scheduler).toFlushAndYield(['onPostCommit']); - expect(onRender).toHaveBeenCalledTimes(1); - expect(onRender.mock.calls[0][6]).toMatchInteractions([ + expect(onPostCommit).toHaveBeenCalledTimes(1); + expect(onPostCommit.mock.calls[0][4]).toMatchInteractions([ initialRenderInteraction, ]); @@ -2636,13 +3945,15 @@ describe('Profiler', () => { timestamp: Scheduler.unstable_now(), }; - const onRender = jest.fn(); + const onPostCommit = jest.fn(() => { + Scheduler.unstable_yieldValue('onPostCommit'); + }); SchedulerTracing.unstable_trace( initialRenderInteraction.name, initialRenderInteraction.timestamp, () => { renderer.update( - + }> @@ -2658,7 +3969,7 @@ describe('Profiler', () => { ]); expect(onInteractionScheduledWorkCompleted).not.toHaveBeenCalled(); - expect(onRender).not.toHaveBeenCalled(); + expect(onPostCommit).not.toHaveBeenCalled(); Scheduler.unstable_advanceTime(50); jest.advanceTimersByTime(50); @@ -2677,7 +3988,7 @@ describe('Profiler', () => { highPriUpdateInteraction.timestamp, () => { renderer.update( - + }> @@ -2692,13 +4003,14 @@ describe('Profiler', () => { 'Text [loading]', 'Text [updated]', ]); + expect(Scheduler).toFlushAndYieldThrough(['onPostCommit']); expect(renderer.toJSON()).toEqual(['loading', 'updated']); - expect(onRender).toHaveBeenCalledTimes(1); - expect(onRender.mock.calls[0][6]).toMatchInteractions([ + expect(onPostCommit).toHaveBeenCalledTimes(1); + expect(onPostCommit.mock.calls[0][4]).toMatchInteractions([ highPriUpdateInteraction, ]); - onRender.mockClear(); + onPostCommit.mockClear(); expect(onInteractionScheduledWorkCompleted).toHaveBeenCalledTimes(0); @@ -2706,11 +4018,14 @@ describe('Profiler', () => { jest.advanceTimersByTime(50); await originalPromise; expect(Scheduler).toHaveYielded(['Promise resolved [loaded]']); - expect(Scheduler).toFlushAndYield(['AsyncText [loaded]']); + expect(Scheduler).toFlushAndYield([ + 'AsyncText [loaded]', + 'onPostCommit', + ]); expect(renderer.toJSON()).toEqual(['loaded', 'updated']); - expect(onRender).toHaveBeenCalledTimes(1); - expect(onRender.mock.calls[0][6]).toMatchInteractions([ + expect(onPostCommit).toHaveBeenCalledTimes(1); + expect(onPostCommit.mock.calls[0][4]).toMatchInteractions([ initialRenderInteraction, highPriUpdateInteraction, ]); @@ -2750,13 +4065,15 @@ describe('Profiler', () => { } }; - const onRender = jest.fn(); + const onPostCommit = jest.fn(() => { + Scheduler.unstable_yieldValue('onPostCommit'); + }); SchedulerTracing.unstable_trace( interaction.name, Scheduler.unstable_now(), () => { ReactNoop.render( - + }> @@ -2778,14 +4095,15 @@ describe('Profiler', () => { 'Suspend [Async]', 'Text [Loading...]', 'Text [Sync]', + 'onPostCommit', ]); // Should have committed the placeholder. expect(ReactNoop.getChildrenAsJSX()).toEqual('Loading...Sync'); - expect(onRender).toHaveBeenCalledTimes(1); + expect(onPostCommit).toHaveBeenCalledTimes(1); - let call = onRender.mock.calls[0]; + let call = onPostCommit.mock.calls[0]; expect(call[0]).toEqual('test-profiler'); - expect(call[6]).toMatchInteractions( + expect(call[4]).toMatchInteractions( ReactFeatureFlags.enableSchedulerTracing ? [interaction] : [], ); @@ -2799,14 +4117,17 @@ describe('Profiler', () => { // Once the promise resolves, we render the suspended view await awaitableAdvanceTimers(20000); expect(Scheduler).toHaveYielded(['Promise resolved [Async]']); - expect(Scheduler).toFlushAndYield(['AsyncText [Async]']); + expect(Scheduler).toFlushAndYield([ + 'AsyncText [Async]', + 'onPostCommit', + ]); expect(ReactNoop.getChildrenAsJSX()).toEqual('AsyncSync'); - expect(onRender).toHaveBeenCalledTimes(2); + expect(onPostCommit).toHaveBeenCalledTimes(2); // No interactions should be associated with this update. - call = onRender.mock.calls[1]; + call = onPostCommit.mock.calls[1]; expect(call[0]).toEqual('test-profiler'); - expect(call[6]).toMatchInteractions([]); + expect(call[4]).toMatchInteractions([]); }); }); }); From 810da53bc08dcf9c2b36474a4723973ac9fe7601 Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Mon, 24 Feb 2020 14:40:00 -0800 Subject: [PATCH 2/3] Added enableProfilerCommitHooks feature flag for commit hooks --- packages/shared/ReactFeatureFlags.js | 3 +++ packages/shared/forks/ReactFeatureFlags.native-fb.js | 1 + packages/shared/forks/ReactFeatureFlags.native-oss.js | 1 + packages/shared/forks/ReactFeatureFlags.persistent.js | 1 + packages/shared/forks/ReactFeatureFlags.test-renderer.js | 1 + packages/shared/forks/ReactFeatureFlags.test-renderer.www.js | 1 + packages/shared/forks/ReactFeatureFlags.testing.js | 1 + packages/shared/forks/ReactFeatureFlags.testing.www.js | 1 + packages/shared/forks/ReactFeatureFlags.www.js | 1 + 9 files changed, 11 insertions(+) diff --git a/packages/shared/ReactFeatureFlags.js b/packages/shared/ReactFeatureFlags.js index 784accd974c2..7516aebcbb1c 100644 --- a/packages/shared/ReactFeatureFlags.js +++ b/packages/shared/ReactFeatureFlags.js @@ -23,6 +23,9 @@ export const warnAboutDeprecatedLifecycles = true; // Gather advanced timing metrics for Profiler subtrees. export const enableProfilerTimer = __PROFILE__; +// Record durations for commit and passive effects phases. +export const enableProfilerCommitHooks = false; + // Trace which interactions trigger each commit. export const enableSchedulerTracing = __PROFILE__; diff --git a/packages/shared/forks/ReactFeatureFlags.native-fb.js b/packages/shared/forks/ReactFeatureFlags.native-fb.js index 2a6d0c93962b..9cb2b771c3d2 100644 --- a/packages/shared/forks/ReactFeatureFlags.native-fb.js +++ b/packages/shared/forks/ReactFeatureFlags.native-fb.js @@ -20,6 +20,7 @@ export const { // The rest of the flags are static for better dead code elimination. export const enableUserTimingAPI = __DEV__; export const enableProfilerTimer = __PROFILE__; +export const enableProfilerCommitHooks = false; export const enableSchedulerTracing = __PROFILE__; export const enableSuspenseServerRenderer = false; export const enableSelectiveHydration = false; diff --git a/packages/shared/forks/ReactFeatureFlags.native-oss.js b/packages/shared/forks/ReactFeatureFlags.native-oss.js index 1aa8be179cb3..e0541ace58a2 100644 --- a/packages/shared/forks/ReactFeatureFlags.native-oss.js +++ b/packages/shared/forks/ReactFeatureFlags.native-oss.js @@ -17,6 +17,7 @@ export const enableUserTimingAPI = __DEV__; export const replayFailedUnitOfWorkWithInvokeGuardedCallback = __DEV__; export const warnAboutDeprecatedLifecycles = true; export const enableProfilerTimer = __PROFILE__; +export const enableProfilerCommitHooks = false; export const enableSchedulerTracing = __PROFILE__; export const enableSuspenseServerRenderer = false; export const enableSelectiveHydration = false; diff --git a/packages/shared/forks/ReactFeatureFlags.persistent.js b/packages/shared/forks/ReactFeatureFlags.persistent.js index 4ec1c8ed30f8..c3b7bb944ea1 100644 --- a/packages/shared/forks/ReactFeatureFlags.persistent.js +++ b/packages/shared/forks/ReactFeatureFlags.persistent.js @@ -17,6 +17,7 @@ export const enableUserTimingAPI = __DEV__; export const warnAboutDeprecatedLifecycles = true; export const replayFailedUnitOfWorkWithInvokeGuardedCallback = __DEV__; export const enableProfilerTimer = __PROFILE__; +export const enableProfilerCommitHooks = false; export const enableSchedulerTracing = __PROFILE__; export const enableSuspenseServerRenderer = false; export const enableSelectiveHydration = false; diff --git a/packages/shared/forks/ReactFeatureFlags.test-renderer.js b/packages/shared/forks/ReactFeatureFlags.test-renderer.js index c1fae8355a97..a55c5804ce5a 100644 --- a/packages/shared/forks/ReactFeatureFlags.test-renderer.js +++ b/packages/shared/forks/ReactFeatureFlags.test-renderer.js @@ -17,6 +17,7 @@ export const enableUserTimingAPI = __DEV__; export const warnAboutDeprecatedLifecycles = true; export const replayFailedUnitOfWorkWithInvokeGuardedCallback = false; export const enableProfilerTimer = __PROFILE__; +export const enableProfilerCommitHooks = false; export const enableSchedulerTracing = __PROFILE__; export const enableSuspenseServerRenderer = false; export const enableSelectiveHydration = false; diff --git a/packages/shared/forks/ReactFeatureFlags.test-renderer.www.js b/packages/shared/forks/ReactFeatureFlags.test-renderer.www.js index 45bb75b5b9d0..3b4aaeb0e97a 100644 --- a/packages/shared/forks/ReactFeatureFlags.test-renderer.www.js +++ b/packages/shared/forks/ReactFeatureFlags.test-renderer.www.js @@ -17,6 +17,7 @@ export const enableUserTimingAPI = __DEV__; export const warnAboutDeprecatedLifecycles = true; export const replayFailedUnitOfWorkWithInvokeGuardedCallback = false; export const enableProfilerTimer = __PROFILE__; +export const enableProfilerCommitHooks = false; export const enableSchedulerTracing = __PROFILE__; export const enableSuspenseServerRenderer = false; export const enableSelectiveHydration = false; diff --git a/packages/shared/forks/ReactFeatureFlags.testing.js b/packages/shared/forks/ReactFeatureFlags.testing.js index 30ba2e1f35f2..52231d515002 100644 --- a/packages/shared/forks/ReactFeatureFlags.testing.js +++ b/packages/shared/forks/ReactFeatureFlags.testing.js @@ -17,6 +17,7 @@ export const enableUserTimingAPI = __DEV__; export const warnAboutDeprecatedLifecycles = true; export const replayFailedUnitOfWorkWithInvokeGuardedCallback = false; export const enableProfilerTimer = __PROFILE__; +export const enableProfilerCommitHooks = false; export const enableSchedulerTracing = __PROFILE__; export const enableSuspenseServerRenderer = false; export const enableSelectiveHydration = false; diff --git a/packages/shared/forks/ReactFeatureFlags.testing.www.js b/packages/shared/forks/ReactFeatureFlags.testing.www.js index 37d53806ff11..2fa27e4065a1 100644 --- a/packages/shared/forks/ReactFeatureFlags.testing.www.js +++ b/packages/shared/forks/ReactFeatureFlags.testing.www.js @@ -17,6 +17,7 @@ export const enableUserTimingAPI = false; export const warnAboutDeprecatedLifecycles = true; export const replayFailedUnitOfWorkWithInvokeGuardedCallback = false; export const enableProfilerTimer = false; +export const enableProfilerCommitHooks = false; export const enableSchedulerTracing = false; export const enableSuspenseServerRenderer = true; export const enableSelectiveHydration = true; diff --git a/packages/shared/forks/ReactFeatureFlags.www.js b/packages/shared/forks/ReactFeatureFlags.www.js index 5ff790efe461..45286c0fbc59 100644 --- a/packages/shared/forks/ReactFeatureFlags.www.js +++ b/packages/shared/forks/ReactFeatureFlags.www.js @@ -34,6 +34,7 @@ export const { export let enableUserTimingAPI = __DEV__ && !__EXPERIMENTAL__; export const enableProfilerTimer = __PROFILE__; +export const enableProfilerCommitHooks = false; export const enableSchedulerTracing = __PROFILE__; export const enableSchedulerDebugging = true; From 858c87073fccc4b0e2240058685c8a6ab857cc87 Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Mon, 24 Feb 2020 14:46:28 -0800 Subject: [PATCH 3/3] Moved onCommit and onPassiveCommit behind separate feature flag --- .../src/ReactFiberCommitWork.js | 121 ++++++++++++------ .../src/ReactFiberWorkLoop.js | 29 ++++- .../src/ReactProfilerTimer.js | 13 +- .../__tests__/ReactProfiler-test.internal.js | 3 + 4 files changed, 114 insertions(+), 52 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiberCommitWork.js b/packages/react-reconciler/src/ReactFiberCommitWork.js index bfb13df239e2..07835f65f818 100644 --- a/packages/react-reconciler/src/ReactFiberCommitWork.js +++ b/packages/react-reconciler/src/ReactFiberCommitWork.js @@ -29,6 +29,7 @@ import { deferPassiveEffectCleanupDuringUnmount, enableSchedulerTracing, enableProfilerTimer, + enableProfilerCommitHooks, enableSuspenseServerRenderer, enableDeprecatedFlareAPI, enableFundamentalAPI, @@ -183,7 +184,11 @@ const callComponentWillUnmountWithTimer = function(current, instance) { startPhaseTimer(current, 'componentWillUnmount'); instance.props = current.memoizedProps; instance.state = current.memoizedState; - if (enableProfilerTimer && current.mode & ProfileMode) { + if ( + enableProfilerTimer && + enableProfilerCommitHooks && + current.mode & ProfileMode + ) { try { startLayoutEffectTimer(); instance.componentWillUnmount(); @@ -447,7 +452,11 @@ export function commitPassiveHookEffects(finishedWork: Fiber): void { // TODO (#17945) We should call all passive destroy functions (for all fibers) // before calling any create functions. The current approach only serializes // these for a single fiber. - if (enableProfilerTimer && finishedWork.mode & ProfileMode) { + if ( + enableProfilerTimer && + enableProfilerCommitHooks && + finishedWork.mode & ProfileMode + ) { try { startPassiveEffectTimer(); commitHookEffectListUnmount( @@ -480,7 +489,7 @@ export function commitPassiveEffectDurations( finishedRoot: FiberRoot, finishedWork: Fiber, ): void { - if (enableProfilerTimer) { + if (enableProfilerTimer && enableProfilerCommitHooks) { // Only Profilers with work in their subtree will have an Update effect scheduled. if ((finishedWork.effectTag & Update) !== NoEffect) { switch (finishedWork.tag) { @@ -546,7 +555,11 @@ function commitLifeCycles( // This is done to prevent sibling component effects from interfering with each other, // e.g. a destroy function in one component should never override a ref set // by a create function in another component during the same commit. - if (enableProfilerTimer && finishedWork.mode & ProfileMode) { + if ( + enableProfilerTimer && + enableProfilerCommitHooks && + finishedWork.mode & ProfileMode + ) { try { startLayoutEffectTimer(); commitHookEffectListMount(HookLayout | HookHasEffect, finishedWork); @@ -597,7 +610,11 @@ function commitLifeCycles( } } } - if (enableProfilerTimer && finishedWork.mode & ProfileMode) { + if ( + enableProfilerTimer && + enableProfilerCommitHooks && + finishedWork.mode & ProfileMode + ) { try { startLayoutEffectTimer(); instance.componentDidMount(); @@ -645,7 +662,11 @@ function commitLifeCycles( } } } - if (enableProfilerTimer && finishedWork.mode & ProfileMode) { + if ( + enableProfilerTimer && + enableProfilerCommitHooks && + finishedWork.mode & ProfileMode + ) { try { startLayoutEffectTimer(); instance.componentDidUpdate( @@ -773,40 +794,42 @@ function commitLifeCycles( } } - if (typeof onCommit === 'function') { - if (enableSchedulerTracing) { - onCommit( - finishedWork.memoizedProps.id, - current === null ? 'mount' : 'update', - effectDuration, - commitTime, - finishedRoot.memoizedInteractions, - ); - } else { - onCommit( - finishedWork.memoizedProps.id, - current === null ? 'mount' : 'update', - effectDuration, - commitTime, - ); + if (enableProfilerCommitHooks) { + if (typeof onCommit === 'function') { + if (enableSchedulerTracing) { + onCommit( + finishedWork.memoizedProps.id, + current === null ? 'mount' : 'update', + effectDuration, + commitTime, + finishedRoot.memoizedInteractions, + ); + } else { + onCommit( + finishedWork.memoizedProps.id, + current === null ? 'mount' : 'update', + effectDuration, + commitTime, + ); + } } - } - // Schedule a passive effect for this Profiler to call onPostCommit hooks. - // This effect should be scheduled even if there is no onPostCommit callback for this Profiler, - // because the effect is also where times bubble to parent Profilers. - enqueuePendingPassiveProfilerEffect(finishedWork); - - // Propagate layout effect durations to the next nearest Profiler ancestor. - // Do not reset these values until the next render so DevTools has a chance to read them first. - let parentFiber = finishedWork.return; - while (parentFiber !== null) { - if (parentFiber.tag === Profiler) { - const parentStateNode = parentFiber.stateNode; - parentStateNode.effectDuration += effectDuration; - break; + // Schedule a passive effect for this Profiler to call onPostCommit hooks. + // This effect should be scheduled even if there is no onPostCommit callback for this Profiler, + // because the effect is also where times bubble to parent Profilers. + enqueuePendingPassiveProfilerEffect(finishedWork); + + // Propagate layout effect durations to the next nearest Profiler ancestor. + // Do not reset these values until the next render so DevTools has a chance to read them first. + let parentFiber = finishedWork.return; + while (parentFiber !== null) { + if (parentFiber.tag === Profiler) { + const parentStateNode = parentFiber.stateNode; + parentStateNode.effectDuration += effectDuration; + break; + } + parentFiber = parentFiber.return; } - parentFiber = parentFiber.return; } } return; @@ -958,7 +981,11 @@ function commitUnmount( if ((tag & HookPassive) !== NoHookEffect) { enqueuePendingPassiveHookEffectUnmount(current, effect); } else { - if (enableProfilerTimer && current.mode & ProfileMode) { + if ( + enableProfilerTimer && + enableProfilerCommitHooks && + current.mode & ProfileMode + ) { startLayoutEffectTimer(); safelyCallDestroy(current, destroy); recordLayoutEffectDuration(current); @@ -991,7 +1018,11 @@ function commitUnmount( do { const {destroy, tag} = effect; if (destroy !== undefined) { - if (enableProfilerTimer && current.mode & ProfileMode) { + if ( + enableProfilerTimer && + enableProfilerCommitHooks && + current.mode & ProfileMode + ) { if ((tag & HookPassive) !== NoHookEffect) { safelyCallDestroy(current, destroy); } else { @@ -1543,7 +1574,11 @@ function commitWork(current: Fiber | null, finishedWork: Fiber): void { // This prevents sibling component effects from interfering with each other, // e.g. a destroy function in one component should never override a ref set // by a create function in another component during the same commit. - if (enableProfilerTimer && finishedWork.mode & ProfileMode) { + if ( + enableProfilerTimer && + enableProfilerCommitHooks && + finishedWork.mode & ProfileMode + ) { try { startLayoutEffectTimer(); commitHookEffectListUnmount( @@ -1598,7 +1633,11 @@ function commitWork(current: Fiber | null, finishedWork: Fiber): void { // This prevents sibling component effects from interfering with each other, // e.g. a destroy function in one component should never override a ref set // by a create function in another component during the same commit. - if (enableProfilerTimer && finishedWork.mode & ProfileMode) { + if ( + enableProfilerTimer && + enableProfilerCommitHooks && + finishedWork.mode & ProfileMode + ) { try { startLayoutEffectTimer(); commitHookEffectListUnmount(HookLayout | HookHasEffect, finishedWork); diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.js b/packages/react-reconciler/src/ReactFiberWorkLoop.js index be380d2c3c28..9bb4a9a33c02 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.js +++ b/packages/react-reconciler/src/ReactFiberWorkLoop.js @@ -24,6 +24,7 @@ import { enableSuspenseServerRenderer, replayFailedUnitOfWorkWithInvokeGuardedCallback, enableProfilerTimer, + enableProfilerCommitHooks, enableSchedulerTracing, warnAboutUnmockedScheduler, flushSuspenseFallbacksInTests, @@ -2184,7 +2185,7 @@ export function flushPassiveEffects() { } export function enqueuePendingPassiveProfilerEffect(fiber: Fiber): void { - if (enableProfilerTimer) { + if (enableProfilerTimer && enableProfilerCommitHooks) { pendingPassiveProfilerEffects.push(fiber); if (!rootDoesHavePassiveEffects) { rootDoesHavePassiveEffects = true; @@ -2270,7 +2271,11 @@ function flushPassiveEffectsImpl() { if (typeof destroy === 'function') { if (__DEV__) { setCurrentDebugFiberInDEV(fiber); - if (enableProfilerTimer && fiber.mode & ProfileMode) { + if ( + enableProfilerTimer && + enableProfilerCommitHooks && + fiber.mode & ProfileMode + ) { startPassiveEffectTimer(); invokeGuardedCallback(null, destroy, null); recordPassiveEffectDuration(fiber); @@ -2285,7 +2290,11 @@ function flushPassiveEffectsImpl() { resetCurrentDebugFiberInDEV(); } else { try { - if (enableProfilerTimer && fiber.mode & ProfileMode) { + if ( + enableProfilerTimer && + enableProfilerCommitHooks && + fiber.mode & ProfileMode + ) { try { startPassiveEffectTimer(); destroy(); @@ -2310,7 +2319,11 @@ function flushPassiveEffectsImpl() { const fiber = ((mountEffects[i + 1]: any): Fiber); if (__DEV__) { setCurrentDebugFiberInDEV(fiber); - if (enableProfilerTimer && fiber.mode & ProfileMode) { + if ( + enableProfilerTimer && + enableProfilerCommitHooks && + fiber.mode & ProfileMode + ) { startPassiveEffectTimer(); invokeGuardedCallback(null, invokePassiveEffectCreate, null, effect); recordPassiveEffectDuration(fiber); @@ -2326,7 +2339,11 @@ function flushPassiveEffectsImpl() { } else { try { const create = effect.create; - if (enableProfilerTimer && fiber.mode & ProfileMode) { + if ( + enableProfilerTimer && + enableProfilerCommitHooks && + fiber.mode & ProfileMode + ) { try { startPassiveEffectTimer(); effect.destroy = create(); @@ -2373,7 +2390,7 @@ function flushPassiveEffectsImpl() { } } - if (enableProfilerTimer) { + if (enableProfilerTimer && enableProfilerCommitHooks) { let profilerEffects = pendingPassiveProfilerEffects; pendingPassiveProfilerEffects = []; for (let i = 0; i < profilerEffects.length; i++) { diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js index 7e51418bbcdf..d876b4f07e41 100644 --- a/packages/react-reconciler/src/ReactProfilerTimer.js +++ b/packages/react-reconciler/src/ReactProfilerTimer.js @@ -9,7 +9,10 @@ import type {Fiber} from './ReactFiber'; -import {enableProfilerTimer} from 'shared/ReactFeatureFlags'; +import { + enableProfilerTimer, + enableProfilerCommitHooks, +} from 'shared/ReactFeatureFlags'; import {Profiler} from 'shared/ReactWorkTags'; // Intentionally not named imports because Rollup would use dynamic dispatch for @@ -81,7 +84,7 @@ function stopProfilerTimerIfRunningAndRecordDelta( } function recordLayoutEffectDuration(fiber: Fiber): void { - if (!enableProfilerTimer) { + if (!enableProfilerTimer || !enableProfilerCommitHooks) { return; } @@ -104,7 +107,7 @@ function recordLayoutEffectDuration(fiber: Fiber): void { } function recordPassiveEffectDuration(fiber: Fiber): void { - if (!enableProfilerTimer) { + if (!enableProfilerTimer || !enableProfilerCommitHooks) { return; } @@ -132,14 +135,14 @@ function recordPassiveEffectDuration(fiber: Fiber): void { } function startLayoutEffectTimer(): void { - if (!enableProfilerTimer) { + if (!enableProfilerTimer || !enableProfilerCommitHooks) { return; } layoutEffectStartTime = now(); } function startPassiveEffectTimer(): void { - if (!enableProfilerTimer) { + if (!enableProfilerTimer || !enableProfilerCommitHooks) { return; } passiveEffectStartTime = now(); diff --git a/packages/react/src/__tests__/ReactProfiler-test.internal.js b/packages/react/src/__tests__/ReactProfiler-test.internal.js index 1f693beebccc..91332eee02c1 100644 --- a/packages/react/src/__tests__/ReactProfiler-test.internal.js +++ b/packages/react/src/__tests__/ReactProfiler-test.internal.js @@ -26,6 +26,7 @@ let resourcePromise; function loadModules({ deferPassiveEffectCleanupDuringUnmount = false, enableProfilerTimer = true, + enableProfilerCommitHooks = true, enableSchedulerTracing = true, replayFailedUnitOfWorkWithInvokeGuardedCallback = false, useNoopRenderer = false, @@ -33,7 +34,9 @@ function loadModules({ ReactFeatureFlags = require('shared/ReactFeatureFlags'); ReactFeatureFlags.debugRenderPhaseSideEffectsForStrictMode = false; ReactFeatureFlags.deferPassiveEffectCleanupDuringUnmount = deferPassiveEffectCleanupDuringUnmount; + ReactFeatureFlags.runAllPassiveEffectDestroysBeforeCreates = deferPassiveEffectCleanupDuringUnmount; ReactFeatureFlags.enableProfilerTimer = enableProfilerTimer; + ReactFeatureFlags.enableProfilerCommitHooks = enableProfilerCommitHooks; ReactFeatureFlags.enableSchedulerTracing = enableSchedulerTracing; ReactFeatureFlags.replayFailedUnitOfWorkWithInvokeGuardedCallback = replayFailedUnitOfWorkWithInvokeGuardedCallback;