diff --git a/packages/react-reconciler/src/ReactFiber.js b/packages/react-reconciler/src/ReactFiber.js index 93371c60d1719..d27a5b6a1313d 100644 --- a/packages/react-reconciler/src/ReactFiber.js +++ b/packages/react-reconciler/src/ReactFiber.js @@ -460,10 +460,13 @@ export function createFiberFromProfiler( const fiber = createFiber(Profiler, pendingProps, key, mode | ProfileMode); fiber.type = REACT_PROFILER_TYPE; fiber.expirationTime = expirationTime; - fiber.stateNode = { - duration: 0, - startTime: 0, - }; + if (enableProfilerTimer) { + fiber.stateNode = { + elapsedPauseTimeAtStart: 0, + duration: 0, + startTime: 0, + }; + } return fiber; } diff --git a/packages/react-reconciler/src/ReactFiberCommitWork.js b/packages/react-reconciler/src/ReactFiberCommitWork.js index 9c492b9b79cde..8f5fa74a5c5b5 100644 --- a/packages/react-reconciler/src/ReactFiberCommitWork.js +++ b/packages/react-reconciler/src/ReactFiberCommitWork.js @@ -20,6 +20,7 @@ import type {ExpirationTime} from './ReactFiberExpirationTime'; import type {CapturedValue, CapturedError} from './ReactCapturedValue'; import {enableProfilerTimer} from 'shared/ReactFeatureFlags'; +import {getCommitTime} from './ReactProfilerTimer'; import { ClassComponent, HostRoot, @@ -807,6 +808,8 @@ function commitWork(current: Fiber | null, finishedWork: Fiber): void { current === null ? 'mount' : 'update', finishedWork.stateNode.duration, finishedWork.treeBaseTime, + finishedWork.stateNode.startTime, + getCommitTime(), ); // Reset actualTime after successful commit. diff --git a/packages/react-reconciler/src/ReactFiberScheduler.js b/packages/react-reconciler/src/ReactFiberScheduler.js index 43f71c621394d..da32034b0842b 100644 --- a/packages/react-reconciler/src/ReactFiberScheduler.js +++ b/packages/react-reconciler/src/ReactFiberScheduler.js @@ -104,6 +104,7 @@ import {popHostContext, popHostContainer} from './ReactFiberHostContext'; import { checkActualRenderTimeStackEmpty, pauseActualRenderTimerIfRunning, + recordCommitTime, recordElapsedBaseRenderTimeIfRunning, resetActualRenderTimer, resumeActualRenderTimerIfPaused, @@ -566,6 +567,10 @@ function commitRoot(finishedWork: Fiber): ExpirationTime { } stopCommitSnapshotEffectsTimer(); + if (enableProfilerTimer) { + recordCommitTime(); + } + // Commit all the side-effects within a tree. We'll do this in two passes. // The first pass performs all the host insertions, updates, deletions and // ref unmounts. diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js index 9fd7544c527fc..bbe1c9bdeae19 100644 --- a/packages/react-reconciler/src/ReactProfilerTimer.js +++ b/packages/react-reconciler/src/ReactProfilerTimer.js @@ -14,25 +14,40 @@ import {enableProfilerTimer} from 'shared/ReactFeatureFlags'; import warning from 'fbjs/lib/warning'; import {now} from './ReactFiberHostConfig'; -/** - * The "actual" render time is total time required to render the descendants of a Profiler component. - * This time is stored as a stack, since Profilers can be nested. - * This time is started during the "begin" phase and stopped during the "complete" phase. - * It is paused (and accumulated) in the event of an interruption or an aborted render. - */ - export type ProfilerTimer = { checkActualRenderTimeStackEmpty(): void, + getCommitTime(): number, markActualRenderTimeStarted(fiber: Fiber): void, pauseActualRenderTimerIfRunning(): void, recordElapsedActualRenderTime(fiber: Fiber): void, resetActualRenderTimer(): void, resumeActualRenderTimerIfPaused(): void, + recordCommitTime(): void, recordElapsedBaseRenderTimeIfRunning(fiber: Fiber): void, startBaseRenderTimer(): void, stopBaseRenderTimerIfRunning(): void, }; +let commitTime: number = 0; + +function getCommitTime(): number { + return commitTime; +} + +function recordCommitTime(): void { + if (!enableProfilerTimer) { + return; + } + commitTime = now(); +} + +/** + * The "actual" render time is total time required to render the descendants of a Profiler component. + * This time is stored as a stack, since Profilers can be nested. + * This time is started during the "begin" phase and stopped during the "complete" phase. + * It is paused (and accumulated) in the event of an interruption or an aborted render. + */ + let fiberStack: Array; if (__DEV__) { @@ -61,7 +76,9 @@ function markActualRenderTimeStarted(fiber: Fiber): void { if (__DEV__) { fiberStack.push(fiber); } - fiber.stateNode.startTime = now() - totalElapsedPauseTime; + const stateNode = fiber.stateNode; + stateNode.elapsedPauseTimeAtStart = totalElapsedPauseTime; + stateNode.startTime = now(); } function pauseActualRenderTimerIfRunning(): void { @@ -80,8 +97,11 @@ function recordElapsedActualRenderTime(fiber: Fiber): void { if (__DEV__) { warning(fiber === fiberStack.pop(), 'Unexpected Fiber popped.'); } - fiber.stateNode.duration += - now() - totalElapsedPauseTime - fiber.stateNode.startTime; + const stateNode = fiber.stateNode; + stateNode.duration += + now() - + (totalElapsedPauseTime - stateNode.elapsedPauseTimeAtStart) - + stateNode.startTime; } function resetActualRenderTimer(): void { @@ -145,8 +165,10 @@ function stopBaseRenderTimerIfRunning(): void { export { checkActualRenderTimeStackEmpty, + getCommitTime, markActualRenderTimeStarted, pauseActualRenderTimerIfRunning, + recordCommitTime, recordElapsedActualRenderTime, resetActualRenderTimer, resumeActualRenderTimerIfPaused, diff --git a/packages/react/src/__tests__/ReactProfiler-test.internal.js b/packages/react/src/__tests__/ReactProfiler-test.internal.js index f3b12109b6adc..3e27588816fef 100644 --- a/packages/react/src/__tests__/ReactProfiler-test.internal.js +++ b/packages/react/src/__tests__/ReactProfiler-test.internal.js @@ -177,14 +177,18 @@ describe('Profiler', () => { , ); - // Should only be called twice, for normal expiration time purposes. + // Should only be called three times: + // Twice for normal expiration time purposes, + // And once to capture the commit time. // No additional calls from ProfilerTimer are expected. - expect(mockNow).toHaveBeenCalledTimes(2); + expect(mockNow).toHaveBeenCalledTimes(3); }); it('logs render times for both mount and update', () => { const callback = jest.fn(); + advanceTimeBy(5); // 0 -> 5 + const renderer = ReactTestRenderer.create( @@ -195,14 +199,18 @@ describe('Profiler', () => { let [call] = callback.mock.calls; - expect(call).toHaveLength(4); + expect(call).toHaveLength(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[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 callback.mockReset(); + advanceTimeBy(20); // 15 -> 35 + renderer.update( @@ -213,16 +221,20 @@ describe('Profiler', () => { [call] = callback.mock.calls; - expect(call).toHaveLength(4); + expect(call).toHaveLength(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[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 }); it('includes render times of nested Profilers in their parent times', () => { const callback = jest.fn(); + advanceTimeBy(5); // 0 -> 5 + ReactTestRenderer.create( @@ -243,15 +255,21 @@ describe('Profiler', () => { expect(parentCall[0]).toBe('parent'); // Parent times should include child times - expect(childCall[2]).toBe(20); // "actual" time - expect(childCall[3]).toBe(20); // "base" time - expect(parentCall[2]).toBe(30); // "actual" time - expect(parentCall[3]).toBe(30); // "base" time + 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('tracks sibling Profilers separately', () => { const callback = jest.fn(); + advanceTimeBy(5); // 0 -> 5 + ReactTestRenderer.create( @@ -270,15 +288,21 @@ describe('Profiler', () => { expect(secondCall[0]).toBe('second'); // Parent times should include child times - expect(firstCall[2]).toBe(20); // "actual" time - expect(firstCall[3]).toBe(20); // "base" time - expect(secondCall[2]).toBe(5); // "actual" time - expect(secondCall[3]).toBe(5); // "base" time + 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(); + advanceTimeBy(5); // 0 -> 5 + ReactTestRenderer.create( @@ -293,8 +317,10 @@ describe('Profiler', () => { 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[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', () => { @@ -347,23 +373,27 @@ describe('Profiler', () => { expect(callback.mock.calls[1][0]).toBe('outer'); }); - it('decreases "actual" time but not "base" time when sCU prevents an update', () => { + it('decreases actual time but not base time when sCU prevents an update', () => { const callback = jest.fn(); + advanceTimeBy(5); // 0 -> 5 + const renderer = ReactTestRenderer.create( - - + + , ); expect(callback).toHaveBeenCalledTimes(1); + advanceTimeBy(30); // 25 -> 55 + renderer.update( - - + + , ); @@ -373,12 +403,16 @@ describe('Profiler', () => { const [mountCall, updateCall] = callback.mock.calls; expect(mountCall[1]).toBe('mount'); - expect(mountCall[2]).toBe(20); // "actual" time - expect(mountCall[3]).toBe(20); // "base" time + expect(mountCall[2]).toBe(20); // actual time + expect(mountCall[3]).toBe(20); // base time + expect(mountCall[4]).toBe(5); // start time + expect(mountCall[5]).toBe(25); // commit time expect(updateCall[1]).toBe('update'); - expect(updateCall[2]).toBe(10); // "actual" time - expect(updateCall[3]).toBe(20); // "base" time + expect(updateCall[2]).toBe(10); // actual time + expect(updateCall[3]).toBe(20); // base time + expect(updateCall[4]).toBe(55); // start time + expect(updateCall[5]).toBe(65); // commit time }); it('includes time spent in render phase lifecycles', () => { @@ -400,12 +434,16 @@ describe('Profiler', () => { const callback = jest.fn(); + advanceTimeBy(5); // 0 -> 5 + const renderer = ReactTestRenderer.create( , ); + advanceTimeBy(15); // 13 -> 28 + renderer.update( @@ -417,16 +455,20 @@ describe('Profiler', () => { const [mountCall, updateCall] = callback.mock.calls; expect(mountCall[1]).toBe('mount'); - expect(mountCall[2]).toBe(8); // "actual" time - expect(mountCall[3]).toBe(8); // "base" time + expect(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(updateCall[1]).toBe('update'); - expect(updateCall[2]).toBe(15); // "actual" time - expect(updateCall[3]).toBe(15); // "base" time + 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 }); describe('with regard to interruptions', () => { - it('should accumulate "actual" time after a scheduling interruptions', () => { + it('should accumulate actual time after a scheduling interruptions', () => { const callback = jest.fn(); const Yield = ({renderTime}) => { @@ -435,6 +477,8 @@ describe('Profiler', () => { return null; }; + advanceTimeBy(5); // 0 -> 5 + // Render partially, but run out of time before completing. const renderer = ReactTestRenderer.create( @@ -453,8 +497,11 @@ describe('Profiler', () => { // Verify that logged times include both durations above. expect(callback).toHaveBeenCalledTimes(1); - expect(callback.mock.calls[0][2]).toBe(5); // "actual" time - expect(callback.mock.calls[0][3]).toBe(5); // "base" time + 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', () => { @@ -466,6 +513,8 @@ describe('Profiler', () => { return null; }; + advanceTimeBy(5); // 0 -> 5 + // Render partially, but don't finish. // This partial render should take 5ms of simulated time. const renderer = ReactTestRenderer.create( @@ -484,7 +533,7 @@ describe('Profiler', () => { expect(callback).toHaveBeenCalledTimes(0); // Simulate time moving forward while frame is paused. - advanceTimeBy(50); + advanceTimeBy(50); // 10 -> 60 // Flush the remaninig work, // Which should take an additional 10ms of simulated time. @@ -493,14 +542,18 @@ describe('Profiler', () => { const [innerCall, outerCall] = callback.mock.calls; - // Verify that the "actual" time includes all work times, + // 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[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[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-priority update replaces an in-progress initial render', () => { @@ -512,6 +565,8 @@ describe('Profiler', () => { return null; }; + advanceTimeBy(5); // 0 -> 5 + // Render a partially update, but don't finish. // This partial render should take 10ms of simulated time. const renderer = ReactTestRenderer.create( @@ -525,7 +580,7 @@ describe('Profiler', () => { expect(callback).toHaveBeenCalledTimes(0); // Simulate time moving forward while frame is paused. - advanceTimeBy(100); + advanceTimeBy(100); // 15 -> 115 // Interrupt with higher priority work. // The interrupted work simulates an additional 5ms of time. @@ -540,11 +595,13 @@ describe('Profiler', () => { ).toEqual(['Yield:5']); // The initial work was thrown away in this case, - // So the "actual" and "base" times should only include the final rendered tree times. + // 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[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(); @@ -562,6 +619,8 @@ describe('Profiler', () => { return null; }; + advanceTimeBy(5); // 0 -> 5 + const renderer = ReactTestRenderer.create( @@ -571,15 +630,19 @@ describe('Profiler', () => { ); // Render everything initially. - // This should take 21 seconds of "actual" and "base" time. + // This should take 21 seconds of actual and base time. expect(renderer.unstable_flushAll()).toEqual(['Yield:6', 'Yield:15']); expect(callback).toHaveBeenCalledTimes(1); let call = callback.mock.calls[0]; - expect(call[2]).toBe(21); // "actual" time - expect(call[3]).toBe(21); // "base" time + 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(); + advanceTimeBy(30); // 26 -> 56 + // Render a partially update, but don't finish. // This partial render should take 3ms of simulated time. renderer.update( @@ -595,7 +658,7 @@ describe('Profiler', () => { expect(callback).toHaveBeenCalledTimes(0); // Simulate time moving forward while frame is paused. - advanceTimeBy(100); + advanceTimeBy(100); // 59 -> 159 // Render another 5ms of simulated time. expect(renderer.unstable_flushThrough(['Yield:5'])).toEqual([ @@ -604,7 +667,7 @@ describe('Profiler', () => { expect(callback).toHaveBeenCalledTimes(0); // Simulate time moving forward while frame is paused. - advanceTimeBy(100); + advanceTimeBy(100); // 164 -> 264 // Interrupt with higher priority work. // The interrupted work simulates an additional 11ms of time. @@ -618,12 +681,14 @@ describe('Profiler', () => { }), ).toEqual(['Yield:11']); - // Verify that the "actual" time includes all three durations above. - // And the "base" time includes only the final rendered tree times. + // Verify that the actual time includes all three durations above. + // And the base time includes only the final rendered tree times. expect(callback).toHaveBeenCalledTimes(1); call = callback.mock.calls[0]; - expect(call[2]).toBe(19); // "actual" time - expect(call[3]).toBe(11); // "base" time + expect(call[2]).toBe(19); // 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(renderer.unstable_flushAll()).toEqual([]); @@ -660,6 +725,8 @@ describe('Profiler', () => { } } + advanceTimeBy(5); // 0 -> 5 + const renderer = ReactTestRenderer.create( @@ -669,8 +736,8 @@ describe('Profiler', () => { ); // Render everything initially. - // This simulates a total of 14ms of "actual" render time. - // The "base" render time is also 14ms for the initial render. + // This simulates a total of 14ms of actual render time. + // The base render time is also 14ms for the initial render. expect(renderer.unstable_flushAll()).toEqual([ 'FirstComponent:1', 'Yield:4', @@ -679,13 +746,17 @@ describe('Profiler', () => { ]); 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[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(); + advanceTimeBy(100); // 19 -> 119 + // Render a partially update, but don't finish. - // This partial render will take 10ms of "actual" render time. + // This partial render will take 10ms of actual render time. first.setState({renderTime: 10}); expect(renderer.unstable_flushThrough(['FirstComponent:10'])).toEqual([ 'FirstComponent:10', @@ -693,38 +764,45 @@ describe('Profiler', () => { expect(callback).toHaveBeenCalledTimes(0); // Simulate time moving forward while frame is paused. - advanceTimeBy(100); + advanceTimeBy(100); // 129 -> 229 // Interrupt with higher priority work. - // This simulates a total of 37ms of "actual" render time. + // This simulates a total of 37ms of actual render time. expect( renderer.unstable_flushSync(() => second.setState({renderTime: 30})), ).toEqual(['SecondComponent:30', 'Yield:7']); - // Verify that the "actual" time includes time spent in the both renders so far (10ms and 37ms). - // The "base" time should include the more recent times for the SecondComponent subtree, + // Verify that the actual time includes time spent in the both renders so far (10ms and 37ms). + // The base time should include the more recent times for the SecondComponent subtree, // As well as the original times for the FirstComponent subtree. expect(callback).toHaveBeenCalledTimes(1); call = callback.mock.calls[0]; - expect(call[2]).toBe(47); // "actual" time - expect(call[3]).toBe(42); // "base" time + expect(call[2]).toBe(47); // 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. + advanceTimeBy(100); // 266 -> 366 + // Resume the original low priority update, with rebased state. - // This simulates a total of 14ms of "actual" render time, + // 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, + // 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. + // TODO: This actual time should decrease by 10ms once the scheduler supports resuming. expect(renderer.unstable_flushAll()).toEqual([ 'FirstComponent:10', 'Yield:4', ]); expect(callback).toHaveBeenCalledTimes(1); call = callback.mock.calls[0]; - expect(call[2]).toBe(14); // "actual" time - expect(call[3]).toBe(51); // "base" time + 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(flagEnabled => { @@ -740,7 +818,7 @@ describe('Profiler', () => { mockNowForTests(); }); - it('should accumulate "actual" time after an error handled by componentDidCatch()', () => { + it('should accumulate actual time after an error handled by componentDidCatch()', () => { const callback = jest.fn(); const ThrowsError = () => { @@ -763,6 +841,8 @@ describe('Profiler', () => { } } + advanceTimeBy(5); // 0 -> 5 + ReactTestRenderer.create( @@ -780,21 +860,29 @@ describe('Profiler', () => { // The initial mount only includes the ErrorBoundary (which takes 2ms) // But it spends time rendering all of the failed subtree also. expect(mountCall[1]).toBe('mount'); - // "actual" time includes: 2 (ErrorBoundary) + 5 (AdvanceTime) + 10 (ThrowsError) + // actual time includes: 2 (ErrorBoundary) + 5 (AdvanceTime) + 10 (ThrowsError) // If replayFailedUnitOfWorkWithInvokeGuardedCallback is enbaled, ThrowsError is replayed. expect(mountCall[2]).toBe(flagEnabled && __DEV__ ? 27 : 17); - // "base" time includes: 2 (ErrorBoundary) + // base time includes: 2 (ErrorBoundary) expect(mountCall[3]).toBe(2); + // start time + expect(mountCall[4]).toBe(5); + // commit time + expect(mountCall[5]).toBe(flagEnabled && __DEV__ ? 32 : 22); // The update includes the ErrorBoundary and its fallback child expect(updateCall[1]).toBe('update'); - // "actual" time includes: 2 (ErrorBoundary) + 20 (AdvanceTime) + // actual time includes: 2 (ErrorBoundary) + 20 (AdvanceTime) expect(updateCall[2]).toBe(22); - // "base" time includes: 2 (ErrorBoundary) + 20 (AdvanceTime) + // base time includes: 2 (ErrorBoundary) + 20 (AdvanceTime) expect(updateCall[3]).toBe(22); + // start time + expect(updateCall[4]).toBe(flagEnabled && __DEV__ ? 32 : 22); + // commit time + expect(updateCall[5]).toBe(flagEnabled && __DEV__ ? 54 : 44); }); - it('should accumulate "actual" time after an error handled by getDerivedStateFromCatch()', () => { + it('should accumulate actual time after an error handled by getDerivedStateFromCatch()', () => { const callback = jest.fn(); const ThrowsError = () => { @@ -817,6 +905,8 @@ describe('Profiler', () => { } } + advanceTimeBy(5); // 0 -> 5 + ReactTestRenderer.create( @@ -832,14 +922,18 @@ describe('Profiler', () => { let [mountCall] = callback.mock.calls; // The initial mount includes the ErrorBoundary's error state, - // But i also spends "actual" time rendering UI that fails and isn't included. + // But i also spends actual time rendering UI that fails and isn't included. expect(mountCall[1]).toBe('mount'); - // "actual" time includes: 2 (ErrorBoundary) + 5 (AdvanceTime) + 10 (ThrowsError) + // actual time includes: 2 (ErrorBoundary) + 5 (AdvanceTime) + 10 (ThrowsError) // Then the re-render: 2 (ErrorBoundary) + 20 (AdvanceTime) // If replayFailedUnitOfWorkWithInvokeGuardedCallback is enbaled, ThrowsError is replayed. expect(mountCall[2]).toBe(flagEnabled && __DEV__ ? 49 : 39); - // "base" time includes: 2 (ErrorBoundary) + 20 (AdvanceTime) + // 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(flagEnabled && __DEV__ ? 54 : 44); }); }); }); @@ -848,6 +942,8 @@ describe('Profiler', () => { it('reflects the most recently rendered id value', () => { const callback = jest.fn(); + advanceTimeBy(5); // 0 -> 5 + const renderer = ReactTestRenderer.create( @@ -856,6 +952,8 @@ describe('Profiler', () => { expect(callback).toHaveBeenCalledTimes(1); + advanceTimeBy(20); // 7 -> 27 + renderer.update( @@ -868,13 +966,15 @@ describe('Profiler', () => { 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[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[2]).toBe(1); // actual time + expect(updateCall[3]).toBe(1); // base time + expect(updateCall[4]).toBe(27); // start time }); }); });