From 30358f61e248b04d3c9a00626e537fc52d64e52a Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Sat, 25 Jan 2020 09:21:46 -0800 Subject: [PATCH] Implemented Profiler onCommit() and onPostCommit() hooks --- packages/react-reconciler/src/ReactFiber.js | 16 +- .../src/ReactFiberBeginWork.js | 12 + .../src/ReactFiberCommitWork.js | 281 +++- .../src/ReactFiberWorkLoop.js | 7 + .../src/ReactProfilerTimer.js | 63 + .../__tests__/ReactProfiler-test.internal.js | 1127 ++++++++++++++++- 6 files changed, 1469 insertions(+), 37 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiber.js b/packages/react-reconciler/src/ReactFiber.js index 792cd1def4db5..370c559b57014 100644 --- a/packages/react-reconciler/src/ReactFiber.js +++ b/packages/react-reconciler/src/ReactFiber.js @@ -815,13 +815,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'); } } @@ -831,6 +826,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 9db5886a6c2b4..3738219bfc57c 100644 --- a/packages/react-reconciler/src/ReactFiberBeginWork.js +++ b/packages/react-reconciler/src/ReactFiberBeginWork.js @@ -577,6 +577,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; @@ -2974,6 +2980,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 77b074a175222..efe17b1a91901 100644 --- a/packages/react-reconciler/src/ReactFiberCommitWork.js +++ b/packages/react-reconciler/src/ReactFiberCommitWork.js @@ -74,7 +74,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, @@ -398,8 +405,18 @@ export function commitPassiveHookEffects(finishedWork: Fiber): void { case ForwardRef: case SimpleMemoComponent: case Chunk: { - commitHookEffectList(UnmountPassive, NoHookEffect, finishedWork); - commitHookEffectList(NoHookEffect, MountPassive, finishedWork); + if (enableProfilerTimer && finishedWork.mode & ProfileMode) { + try { + startPassiveEffectTimer(); + commitHookEffectList(UnmountPassive, NoHookEffect, finishedWork); + commitHookEffectList(NoHookEffect, MountPassive, finishedWork); + } finally { + recordPassiveEffectDuration(finishedWork); + } + } else { + commitHookEffectList(UnmountPassive, NoHookEffect, finishedWork); + commitHookEffectList(NoHookEffect, MountPassive, finishedWork); + } break; } default: @@ -408,6 +425,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, @@ -419,7 +491,16 @@ function commitLifeCycles( case ForwardRef: case SimpleMemoComponent: case Chunk: { - commitHookEffectList(UnmountLayout, MountLayout, finishedWork); + if (enableProfilerTimer && finishedWork.mode & ProfileMode) { + try { + startLayoutEffectTimer(); + commitHookEffectList(UnmountLayout, MountLayout, finishedWork); + } finally { + recordLayoutEffectDuration(finishedWork); + } + } else { + commitHookEffectList(UnmountLayout, MountLayout, finishedWork); + } return; } case ClassComponent: { @@ -457,7 +538,16 @@ function commitLifeCycles( } } } - instance.componentDidMount(); + if (enableProfilerTimer && finishedWork.mode & ProfileMode) { + try { + startLayoutEffectTimer(); + instance.componentDidMount(); + } finally { + recordLayoutEffectDuration(finishedWork); + } + } else { + instance.componentDidMount(); + } stopPhaseTimer(); } else { const prevProps = @@ -496,11 +586,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(); } } @@ -593,7 +696,10 @@ function commitLifeCycles( } case Profiler: { if (enableProfilerTimer) { - const onRender = finishedWork.memoizedProps.onRender; + const {onCommit, onPostCommit, onRender} = finishedWork.memoizedProps; + const {effectDuration, passiveEffectDuration} = finishedWork.stateNode; + + const commitTime = getCommitTime(); if (typeof onRender === 'function') { if (enableSchedulerTracing) { @@ -603,7 +709,7 @@ function commitLifeCycles( finishedWork.actualDuration, finishedWork.treeBaseDuration, finishedWork.actualStartTime, - getCommitTime(), + commitTime, finishedRoot.memoizedInteractions, ); } else { @@ -613,9 +719,74 @@ 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, + ); + } + } + + // In the common case, we don't call onPostCommit() here. + // Typically, passive effects haven't been measured yet, + // so any durations we have recorded will be for the previous commit's effects. + // However if we have recorded passive effect durations, + // it means cleanup functions were run as part of an unmount. + // In that event we should to call onPostCommit() and bubble durations. + // + // TODO (bvaughn, acdlite) We plan to refactor passive effect cleanup timing as part of the CM umbrella. + // Hopefully we can remove this codepath after that refactor? + if (passiveEffectDuration > 0) { + if (typeof onPostCommit === 'function') { + if (enableSchedulerTracing) { + onPostCommit( + finishedWork.memoizedProps.id, + current === null ? 'mount' : 'update', + passiveEffectDuration, + commitTime, + finishedRoot.memoizedInteractions, + ); + } else { + onPostCommit( + finishedWork.memoizedProps.id, + current === null ? 'mount' : 'update', + passiveEffectDuration, + commitTime, + ); + } + } + } + + // 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; + + // In most cases, this duration will be 0 (so accumulating it is a no-op). + // In the unmount case though, it's important that we bubble this value too. + parentStateNode.passiveEffectDuration += passiveEffectDuration; + break; } + parentFiber = parentFiber.return; } } return; @@ -772,16 +943,50 @@ function commitUnmount( renderPriorityLevel > NormalPriority ? NormalPriority : renderPriorityLevel; - runWithPriority(priorityLevel, () => { - let effect = firstEffect; - do { - const destroy = effect.destroy; - if (destroy !== undefined) { - safelyCallDestroy(current, destroy); - } - effect = effect.next; - } while (effect !== firstEffect); - }); + if (enableProfilerTimer && current.mode & ProfileMode) { + runWithPriority(priorityLevel, () => { + let effect = firstEffect; + do { + const destroy = effect.destroy; + if (destroy !== undefined) { + // In order to support the Profiler's onCommit and onPostCommit API, + // we need to attribute time spent in cleanup functions to the right effects group. + // Unfortunately for effects with no changed dependencies, this will be NoHookEffect. + // + // TODO (bvaughn, acdlite) Revisit this when we refactor passive effects and unmount. + if ((effect.tag & UnmountLayout) !== NoHookEffect) { + try { + startLayoutEffectTimer(); + safelyCallDestroy(current, destroy); + } finally { + recordLayoutEffectDuration(current); + } + } else if ((effect.tag & UnmountPassive) !== NoHookEffect) { + try { + startPassiveEffectTimer(); + safelyCallDestroy(current, destroy); + } finally { + recordPassiveEffectDuration(current); + } + } else { + safelyCallDestroy(current, destroy); + } + } + effect = effect.next; + } while (effect !== firstEffect); + }); + } else { + runWithPriority(priorityLevel, () => { + let effect = firstEffect; + do { + const destroy = effect.destroy; + if (destroy !== undefined) { + safelyCallDestroy(current, destroy); + } + effect = effect.next; + } while (effect !== firstEffect); + }); + } } } return; @@ -790,7 +995,13 @@ function commitUnmount( safelyDetachRef(current); const instance = current.stateNode; if (typeof instance.componentWillUnmount === 'function') { - safelyCallComponentWillUnmount(current, instance); + if (enableProfilerTimer && current.mode & ProfileMode) { + startLayoutEffectTimer(); + safelyCallComponentWillUnmount(current, instance); + recordLayoutEffectDuration(current); + } else { + safelyCallComponentWillUnmount(current, instance); + } } return; } @@ -1287,7 +1498,16 @@ function commitWork(current: Fiber | null, finishedWork: Fiber): void { case Chunk: { // Note: We currently never use MountMutation, but useLayout uses // UnmountMutation. - commitHookEffectList(UnmountMutation, MountMutation, finishedWork); + if (enableProfilerTimer && finishedWork.mode & ProfileMode) { + try { + startLayoutEffectTimer(); + commitHookEffectList(UnmountMutation, MountMutation, finishedWork); + } finally { + recordLayoutEffectDuration(finishedWork); + } + } else { + commitHookEffectList(UnmountMutation, MountMutation, finishedWork); + } return; } case Profiler: { @@ -1327,7 +1547,16 @@ function commitWork(current: Fiber | null, finishedWork: Fiber): void { case Chunk: { // Note: We currently never use MountMutation, but useLayout uses // UnmountMutation. - commitHookEffectList(UnmountMutation, MountMutation, finishedWork); + if (enableProfilerTimer && finishedWork.mode & ProfileMode) { + try { + startLayoutEffectTimer(); + commitHookEffectList(UnmountMutation, MountMutation, finishedWork); + } finally { + recordLayoutEffectDuration(finishedWork); + } + } else { + commitHookEffectList(UnmountMutation, MountMutation, finishedWork); + } return; } case ClassComponent: { diff --git a/packages/react-reconciler/src/ReactFiberWorkLoop.js b/packages/react-reconciler/src/ReactFiberWorkLoop.js index a4664613ac224..40b6c925a76b8 100644 --- a/packages/react-reconciler/src/ReactFiberWorkLoop.js +++ b/packages/react-reconciler/src/ReactFiberWorkLoop.js @@ -138,6 +138,7 @@ import { commitDetachRef, commitAttachRef, commitResetTextContent, + commitPassiveEffectDurations, } from './ReactFiberCommitWork'; import {enqueueUpdate} from './ReactUpdateQueue'; import {resetContextDependencies} from './ReactFiberNewContext'; @@ -2180,6 +2181,7 @@ function flushPassiveEffectsImpl() { if (rootWithPendingPassiveEffects === null) { return false; } + const root = rootWithPendingPassiveEffects; const expirationTime = pendingPassiveEffectsExpirationTime; rootWithPendingPassiveEffects = null; @@ -2215,6 +2217,11 @@ function flushPassiveEffectsImpl() { captureCommitPhaseError(effect, error); } } + + if (enableProfilerTimer) { + commitPassiveEffectDurations(root, effect); + } + const nextNextEffect = effect.nextEffect; // Remove nextEffect pointer to assist GC effect.nextEffect = null; diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js index c26f66d969244..70f991da8e0ff 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,69 @@ function stopProfilerTimerIfRunningAndRecordDelta( } } +function recordLayoutEffectDuration(fiber: Fiber): void { + if (!enableProfilerTimer) { + return; + } + + if (layoutEffectStartTime >= 0) { + const elapsedTime = now() - layoutEffectStartTime; + + // 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; + + // Store duration on the next nearest Profiler ancestor. + let parentFiber = fiber.return; + while (parentFiber !== null) { + if (parentFiber.tag === Profiler) { + const parentStateNode = parentFiber.stateNode; + 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 ad47793c8259a..a48fed28d7fa2 100644 --- a/packages/react/src/__tests__/ReactProfiler-test.internal.js +++ b/packages/react/src/__tests__/ReactProfiler-test.internal.js @@ -120,10 +120,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, + }); }); } @@ -1262,6 +1261,1087 @@ describe('Profiler', () => { expect(callback).toHaveBeenCalledTimes(1); }); }); + + describe('onCommit callback', () => { + beforeEach(() => { + jest.resetModules(); + + loadModules({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 null; + }; + + class ComponentWithCommitHooks extends React.Component { + componentDidMount() { + Scheduler.unstable_advanceTime(100000); + } + componentDidUpdate() { + Scheduler.unstable_advanceTime(1000000); + } + render() { + return null; + } + } + + Scheduler.unstable_advanceTime(1); + + const renderer = ReactTestRenderer.create( + + + + , + ); + + 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'); + // TODO (bvaughn, acdlite) The below assertion fails (expected 10100, received 0). + // See ReactFiberCommitWork -> commitUnmount() for an explanation as to why. + // expect(call[2]).toBe(10100); // durations + expect(call[3]).toBe(1112023); // 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'); + // TODO (bvaughn, acdlite) The below assertion fails (expected 100001000, received 100000000). + // See ReactFiberCommitWork -> commitUnmount() for an explanation as to why. + // 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 callback', () => { + beforeEach(() => { + jest.resetModules(); + + loadModules({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); + }); + 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( + + + , + ); + }); + + 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( + + + , + ); + }); + + 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(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( + , + ); + }); + + 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, acdlite) The below assertion fails (expected 10100, received 10000). + // See ReactFiberCommitWork -> commitUnmount() for an explanation as to why. + // expect(call[2]).toBe(10100); // durations + expect(call[3]).toBe(12023); // commit start time (before mutations or effects) + expect(call[4]).toEqual(enableSchedulerTracing ? new Set() : undefined); // interaction events + }); + + it('should report time spent in passive effects with cascading renders', () => { + const callback = jest.fn(); + + 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(1); + + ReactTestRenderer.act(() => { + 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(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 bubble time spent in 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.useEffect(() => { + 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( + + + + + , + ); + }); + + /* + // When a Profiler (and its subtree) get unmounted, + // the Profiler's unmount effect is processed before the subtree's cleanup effects are measured, + // so there's no good time for us to bubble the cleanup durations to the next Profiler. + // + // TODO (bvaughn, acdlite) We plan to refactor passive effect cleanup timing as part of the CM umbrella. + // Hopefully we can re-enable this test after that refactor? + 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 passive 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.useEffect(() => { + 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 passive 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.useEffect(() => { + 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(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 + expect(call[3]).toBe(11221121); // 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.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( + + + , + ); + }, + ); + }); + + 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('interaction tracing', () => { @@ -1771,6 +2851,45 @@ describe('Profiler', () => { ]); }); + it('should not mark an interaction complete while passive effects are outstanding', () => { + const onCommit = jest.fn(); + const onPostCommit = jest.fn(); + + 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).toFlushAndYieldThrough(['passive effect']); + + 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();