From 3814ed22b675cdded024d2fac21d7a00e93ef532 Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Thu, 17 May 2018 14:39:10 -0700 Subject: [PATCH 1/5] Removed stupid unnecessary quotation marks --- .../__tests__/ReactProfiler-test.internal.js | 138 +++++++++--------- 1 file changed, 69 insertions(+), 69 deletions(-) diff --git a/packages/react/src/__tests__/ReactProfiler-test.internal.js b/packages/react/src/__tests__/ReactProfiler-test.internal.js index f3b12109b6adc..d86385ba3d4a5 100644 --- a/packages/react/src/__tests__/ReactProfiler-test.internal.js +++ b/packages/react/src/__tests__/ReactProfiler-test.internal.js @@ -198,8 +198,8 @@ describe('Profiler', () => { expect(call).toHaveLength(4); expect(call[0]).toBe('test'); expect(call[1]).toBe('mount'); - expect(call[2]).toBe(10); // "actual" time - expect(call[3]).toBe(10); // "base" time + expect(call[2]).toBe(10); // actual time + expect(call[3]).toBe(10); // base time callback.mockReset(); @@ -216,8 +216,8 @@ describe('Profiler', () => { expect(call).toHaveLength(4); expect(call[0]).toBe('test'); expect(call[1]).toBe('update'); - expect(call[2]).toBe(10); // "actual" time - expect(call[3]).toBe(10); // "base" time + expect(call[2]).toBe(10); // actual time + expect(call[3]).toBe(10); // base time }); it('includes render times of nested Profilers in their parent times', () => { @@ -243,10 +243,10 @@ 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(parentCall[2]).toBe(30); // actual time + expect(parentCall[3]).toBe(30); // base time }); it('tracks sibling Profilers separately', () => { @@ -270,10 +270,10 @@ 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(secondCall[2]).toBe(5); // actual time + expect(secondCall[3]).toBe(5); // base time }); it('does not include time spent outside of profile root', () => { @@ -293,8 +293,8 @@ 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 }); it('is not called when blocked by sCU false', () => { @@ -347,7 +347,7 @@ 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(); const renderer = ReactTestRenderer.create( @@ -373,12 +373,12 @@ 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(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 }); it('includes time spent in render phase lifecycles', () => { @@ -417,16 +417,16 @@ 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(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 }); 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}) => { @@ -453,8 +453,8 @@ 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 + expect(callback.mock.calls[0][2]).toBe(5); // actual time + expect(callback.mock.calls[0][3]).toBe(5); // base time }); it('should not include time between frames', () => { @@ -493,14 +493,14 @@ 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(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 }); it('should report the expected times when a high-priority update replaces an in-progress initial render', () => { @@ -540,11 +540,11 @@ 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 callback.mockReset(); @@ -571,12 +571,12 @@ 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 callback.mockReset(); @@ -618,12 +618,12 @@ 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 // Verify no more unexpected callbacks from low priority work expect(renderer.unstable_flushAll()).toEqual([]); @@ -669,8 +669,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 +679,13 @@ 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 callback.mockClear(); // 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', @@ -696,35 +696,35 @@ describe('Profiler', () => { advanceTimeBy(100); // 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 callback.mockClear(); // 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 }); [true, false].forEach(flagEnabled => { @@ -740,7 +740,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 = () => { @@ -780,21 +780,21 @@ 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); // 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); }); - 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 = () => { @@ -832,13 +832,13 @@ 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); }); }); @@ -868,13 +868,13 @@ 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(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 }); }); }); From 9d66ab32022283a50c9793019d7e639e83da40b4 Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Thu, 17 May 2018 15:54:43 -0700 Subject: [PATCH 2/5] Added start time parameter to Profiler onRender callback --- packages/react-reconciler/src/ReactFiber.js | 1 + .../src/ReactFiberCommitWork.js | 1 + .../src/ReactProfilerTimer.js | 11 ++- .../__tests__/ReactProfiler-test.internal.js | 91 ++++++++++++++++--- 4 files changed, 90 insertions(+), 14 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiber.js b/packages/react-reconciler/src/ReactFiber.js index 93371c60d1719..4f841bdd4c148 100644 --- a/packages/react-reconciler/src/ReactFiber.js +++ b/packages/react-reconciler/src/ReactFiber.js @@ -461,6 +461,7 @@ export function createFiberFromProfiler( fiber.type = REACT_PROFILER_TYPE; fiber.expirationTime = expirationTime; fiber.stateNode = { + elapsedPauseTimeAtStart: 0, duration: 0, startTime: 0, }; diff --git a/packages/react-reconciler/src/ReactFiberCommitWork.js b/packages/react-reconciler/src/ReactFiberCommitWork.js index e5e2f26402b09..24b49e14a10e6 100644 --- a/packages/react-reconciler/src/ReactFiberCommitWork.js +++ b/packages/react-reconciler/src/ReactFiberCommitWork.js @@ -828,6 +828,7 @@ export default function( current === null ? 'mount' : 'update', finishedWork.stateNode.duration, finishedWork.treeBaseTime, + finishedWork.stateNode.startTime, ); // Reset actualTime after successful commit. diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js index d192bc1e91d58..4e0d0d40c1eea 100644 --- a/packages/react-reconciler/src/ReactProfilerTimer.js +++ b/packages/react-reconciler/src/ReactProfilerTimer.js @@ -55,7 +55,9 @@ export function createProfilerTimer(now: () => number): ProfilerTimer { if (__DEV__) { fiberStack.push(fiber); } - fiber.stateNode.startTime = now() - totalElapsedPauseTime; + const stateNode = fiber.stateNode; + stateNode.elapsedPauseTimeAtStart = totalElapsedPauseTime; + stateNode.startTime = now(); } function pauseActualRenderTimerIfRunning(): void { @@ -68,8 +70,11 @@ export function createProfilerTimer(now: () => number): ProfilerTimer { 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 { diff --git a/packages/react/src/__tests__/ReactProfiler-test.internal.js b/packages/react/src/__tests__/ReactProfiler-test.internal.js index d86385ba3d4a5..589c870f4fed9 100644 --- a/packages/react/src/__tests__/ReactProfiler-test.internal.js +++ b/packages/react/src/__tests__/ReactProfiler-test.internal.js @@ -185,6 +185,8 @@ describe('Profiler', () => { it('logs render times for both mount and update', () => { const callback = jest.fn(); + advanceTimeBy(5); // 0 -> 5 + const renderer = ReactTestRenderer.create( @@ -195,14 +197,17 @@ describe('Profiler', () => { let [call] = callback.mock.calls; - expect(call).toHaveLength(4); + expect(call).toHaveLength(5); 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 callback.mockReset(); + advanceTimeBy(20); // 15 -> 35 + renderer.update( @@ -213,16 +218,19 @@ describe('Profiler', () => { [call] = callback.mock.calls; - expect(call).toHaveLength(4); + expect(call).toHaveLength(5); 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 }); it('includes render times of nested Profilers in their parent times', () => { const callback = jest.fn(); + advanceTimeBy(5); // 0 -> 5 + ReactTestRenderer.create( @@ -245,13 +253,17 @@ describe('Profiler', () => { // 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(parentCall[2]).toBe(30); // actual time expect(parentCall[3]).toBe(30); // base time + expect(parentCall[4]).toBe(5); // start time }); it('tracks sibling Profilers separately', () => { const callback = jest.fn(); + advanceTimeBy(5); // 0 -> 5 + ReactTestRenderer.create( @@ -272,8 +284,10 @@ describe('Profiler', () => { // 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(secondCall[2]).toBe(5); // actual time expect(secondCall[3]).toBe(5); // base time + expect(secondCall[4]).toBe(25); // start time }); it('does not include time spent outside of profile root', () => { @@ -295,6 +309,7 @@ describe('Profiler', () => { expect(call[0]).toBe('test'); expect(call[2]).toBe(5); // actual time expect(call[3]).toBe(5); // base time + expect(call[4]).toBe(20); // start time }); it('is not called when blocked by sCU false', () => { @@ -350,20 +365,24 @@ describe('Profiler', () => { 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( - - + + , ); @@ -375,10 +394,12 @@ describe('Profiler', () => { expect(mountCall[1]).toBe('mount'); expect(mountCall[2]).toBe(20); // actual time expect(mountCall[3]).toBe(20); // base time + expect(mountCall[4]).toBe(5); // start time expect(updateCall[1]).toBe('update'); expect(updateCall[2]).toBe(10); // actual time expect(updateCall[3]).toBe(20); // base time + expect(updateCall[4]).toBe(55); // start time }); it('includes time spent in render phase lifecycles', () => { @@ -400,12 +421,16 @@ describe('Profiler', () => { const callback = jest.fn(); + advanceTimeBy(5); // 0 -> 5 + const renderer = ReactTestRenderer.create( , ); + advanceTimeBy(15); // 13 -> 28 + renderer.update( @@ -419,10 +444,12 @@ describe('Profiler', () => { 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(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 }); describe('with regard to interruptions', () => { @@ -435,6 +462,8 @@ describe('Profiler', () => { return null; }; + advanceTimeBy(5); // 0 -> 5 + // Render partially, but run out of time before completing. const renderer = ReactTestRenderer.create( @@ -455,6 +484,7 @@ describe('Profiler', () => { expect(callback).toHaveBeenCalledTimes(1); expect(callback.mock.calls[0][2]).toBe(5); // actual time expect(callback.mock.calls[0][3]).toBe(5); // base time + expect(callback.mock.calls[0][4]).toBe(5); // start time }); it('should not include time between frames', () => { @@ -466,6 +496,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 +516,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. @@ -498,9 +530,11 @@ describe('Profiler', () => { 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(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 }); it('should report the expected times when a high-priority update replaces an in-progress initial render', () => { @@ -512,6 +546,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 +561,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. @@ -545,6 +581,7 @@ describe('Profiler', () => { 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 callback.mockReset(); @@ -562,6 +599,8 @@ describe('Profiler', () => { return null; }; + advanceTimeBy(5); // 0 -> 5 + const renderer = ReactTestRenderer.create( @@ -577,9 +616,12 @@ describe('Profiler', () => { 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 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 +637,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 +646,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. @@ -624,6 +666,7 @@ describe('Profiler', () => { call = callback.mock.calls[0]; expect(call[2]).toBe(19); // actual time expect(call[3]).toBe(11); // base time + expect(call[4]).toBe(264); // start time // Verify no more unexpected callbacks from low priority work expect(renderer.unstable_flushAll()).toEqual([]); @@ -660,6 +703,8 @@ describe('Profiler', () => { } } + advanceTimeBy(5); // 0 -> 5 + const renderer = ReactTestRenderer.create( @@ -681,9 +726,12 @@ describe('Profiler', () => { 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 callback.mockClear(); + advanceTimeBy(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}); @@ -693,7 +741,7 @@ 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. @@ -708,9 +756,13 @@ describe('Profiler', () => { call = callback.mock.calls[0]; expect(call[2]).toBe(47); // actual time expect(call[3]).toBe(42); // base time + expect(call[4]).toBe(229); // start 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, // And does not include the original (interrupted) 10ms. @@ -725,6 +777,7 @@ describe('Profiler', () => { 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 }); [true, false].forEach(flagEnabled => { @@ -763,6 +816,8 @@ describe('Profiler', () => { } } + advanceTimeBy(5); // 0 -> 5 + ReactTestRenderer.create( @@ -785,6 +840,8 @@ describe('Profiler', () => { expect(mountCall[2]).toBe(flagEnabled && __DEV__ ? 27 : 17); // base time includes: 2 (ErrorBoundary) expect(mountCall[3]).toBe(2); + // start time + expect(mountCall[4]).toBe(5); // The update includes the ErrorBoundary and its fallback child expect(updateCall[1]).toBe('update'); @@ -792,6 +849,8 @@ describe('Profiler', () => { expect(updateCall[2]).toBe(22); // base time includes: 2 (ErrorBoundary) + 20 (AdvanceTime) expect(updateCall[3]).toBe(22); + // start time + expect(updateCall[4]).toBe(flagEnabled && __DEV__ ? 32 : 22); }); it('should accumulate actual time after an error handled by getDerivedStateFromCatch()', () => { @@ -817,6 +876,8 @@ describe('Profiler', () => { } } + advanceTimeBy(5); // 0 -> 5 + ReactTestRenderer.create( @@ -840,6 +901,8 @@ describe('Profiler', () => { expect(mountCall[2]).toBe(flagEnabled && __DEV__ ? 49 : 39); // base time includes: 2 (ErrorBoundary) + 20 (AdvanceTime) expect(mountCall[3]).toBe(22); + // start time + expect(mountCall[4]).toBe(5); }); }); }); @@ -848,6 +911,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 +921,8 @@ describe('Profiler', () => { expect(callback).toHaveBeenCalledTimes(1); + advanceTimeBy(20); // 7 -> 27 + renderer.update( @@ -870,11 +937,13 @@ describe('Profiler', () => { 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 }); }); }); From 16c6aaddb6a2d0f79bcb6b1c1f00db4f31a9b92f Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Thu, 17 May 2018 17:50:48 -0700 Subject: [PATCH 3/5] Profiler also captures commit time --- .../src/ReactFiberCommitWork.js | 4 ++ .../src/ReactFiberScheduler.js | 6 +++ .../src/ReactProfilerTimer.js | 18 +++++++ .../__tests__/ReactProfiler-test.internal.js | 47 +++++++++++++++---- 4 files changed, 67 insertions(+), 8 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiberCommitWork.js b/packages/react-reconciler/src/ReactFiberCommitWork.js index 24b49e14a10e6..8c471db22000e 100644 --- a/packages/react-reconciler/src/ReactFiberCommitWork.js +++ b/packages/react-reconciler/src/ReactFiberCommitWork.js @@ -12,6 +12,7 @@ import type {Fiber} from './ReactFiber'; import type {FiberRoot} from './ReactFiberRoot'; import type {ExpirationTime} from './ReactFiberExpirationTime'; import type {CapturedValue, CapturedError} from './ReactCapturedValue'; +import type {ProfilerTimer} from './ReactProfilerTimer'; import { enableMutatingReconciler, @@ -106,8 +107,10 @@ export default function( ) => ExpirationTime, markLegacyErrorBoundaryAsFailed: (instance: mixed) => void, recalculateCurrentTime: () => ExpirationTime, + profilerTimer: ProfilerTimer, ) { const {getPublicInstance, mutation, persistence} = config; + const {getCommitTime} = profilerTimer; const callComponentWillUnmountWithTimer = function(current, instance) { startPhaseTimer(current, 'componentWillUnmount'); @@ -829,6 +832,7 @@ export default function( 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 b2102a5e853ab..4540ed572c4f2 100644 --- a/packages/react-reconciler/src/ReactFiberScheduler.js +++ b/packages/react-reconciler/src/ReactFiberScheduler.js @@ -248,11 +248,13 @@ export default function( computeExpirationForFiber, markLegacyErrorBoundaryAsFailed, recalculateCurrentTime, + profilerTimer, ); const { checkActualRenderTimeStackEmpty, pauseActualRenderTimerIfRunning, + recordCommitTime, recordElapsedBaseRenderTimeIfRunning, resetActualRenderTimer, resumeActualRenderTimerIfPaused, @@ -420,6 +422,10 @@ export default function( } } + if (enableProfilerTimer) { + recordCommitTime(); + } + // The following switch statement is only concerned about placement, // updates, and deletions. To avoid needing to add a case for every // possible bitmap value, we remove the secondary effects from the diff --git a/packages/react-reconciler/src/ReactProfilerTimer.js b/packages/react-reconciler/src/ReactProfilerTimer.js index 4e0d0d40c1eea..1abefd12c5c6d 100644 --- a/packages/react-reconciler/src/ReactProfilerTimer.js +++ b/packages/react-reconciler/src/ReactProfilerTimer.js @@ -21,6 +21,8 @@ import warning from 'fbjs/lib/warning'; */ export type ProfilerTimer = { + getCommitTime(): number, + recordCommitTime(): void, checkActualRenderTimeStackEmpty(): void, markActualRenderTimeStarted(fiber: Fiber): void, pauseActualRenderTimerIfRunning(): void, @@ -39,6 +41,16 @@ export function createProfilerTimer(now: () => number): ProfilerTimer { fiberStack = []; } + let commitTime: number = 0; + + function getCommitTime(): number { + return commitTime; + } + + function recordCommitTime(): void { + commitTime = now(); + } + let timerPausedAt: number = 0; let totalElapsedPauseTime: number = 0; @@ -123,6 +135,8 @@ export function createProfilerTimer(now: () => number): ProfilerTimer { if (enableProfilerTimer) { return { + getCommitTime, + recordCommitTime, checkActualRenderTimeStackEmpty, markActualRenderTimeStarted, pauseActualRenderTimerIfRunning, @@ -135,6 +149,10 @@ export function createProfilerTimer(now: () => number): ProfilerTimer { }; } else { return { + getCommitTime(): number { + return 0; + }, + recordCommitTime(): void {}, checkActualRenderTimeStackEmpty(): void {}, markActualRenderTimeStarted(fiber: Fiber): void {}, pauseActualRenderTimerIfRunning(): void {}, diff --git a/packages/react/src/__tests__/ReactProfiler-test.internal.js b/packages/react/src/__tests__/ReactProfiler-test.internal.js index 589c870f4fed9..3e27588816fef 100644 --- a/packages/react/src/__tests__/ReactProfiler-test.internal.js +++ b/packages/react/src/__tests__/ReactProfiler-test.internal.js @@ -177,9 +177,11 @@ 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', () => { @@ -197,12 +199,13 @@ describe('Profiler', () => { let [call] = callback.mock.calls; - expect(call).toHaveLength(5); + 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[4]).toBe(5); // start time + expect(call[5]).toBe(15); // commit time callback.mockReset(); @@ -218,12 +221,13 @@ describe('Profiler', () => { [call] = callback.mock.calls; - expect(call).toHaveLength(5); + 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[4]).toBe(35); // start time + expect(call[5]).toBe(45); // commit time }); it('includes render times of nested Profilers in their parent times', () => { @@ -254,9 +258,11 @@ describe('Profiler', () => { 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', () => { @@ -285,14 +291,18 @@ describe('Profiler', () => { 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( @@ -309,7 +319,8 @@ describe('Profiler', () => { expect(call[0]).toBe('test'); expect(call[2]).toBe(5); // actual time expect(call[3]).toBe(5); // base time - expect(call[4]).toBe(20); // start time + expect(call[4]).toBe(25); // start time + expect(call[5]).toBe(50); // commit time }); it('is not called when blocked by sCU false', () => { @@ -395,11 +406,13 @@ describe('Profiler', () => { 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[4]).toBe(55); // start time + expect(updateCall[5]).toBe(65); // commit time }); it('includes time spent in render phase lifecycles', () => { @@ -445,11 +458,13 @@ describe('Profiler', () => { 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[4]).toBe(28); // start time + expect(updateCall[5]).toBe(43); // commit time }); describe('with regard to interruptions', () => { @@ -482,9 +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 - expect(callback.mock.calls[0][4]).toBe(5); // start 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', () => { @@ -531,10 +548,12 @@ describe('Profiler', () => { 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-priority update replaces an in-progress initial render', () => { @@ -582,6 +601,7 @@ describe('Profiler', () => { 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(); @@ -617,6 +637,7 @@ describe('Profiler', () => { 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(); @@ -667,6 +688,7 @@ describe('Profiler', () => { 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([]); @@ -727,6 +749,7 @@ describe('Profiler', () => { 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(); @@ -757,6 +780,7 @@ describe('Profiler', () => { 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(); @@ -778,6 +802,7 @@ describe('Profiler', () => { 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 => { @@ -842,6 +867,8 @@ describe('Profiler', () => { 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'); @@ -851,6 +878,8 @@ describe('Profiler', () => { 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()', () => { @@ -903,6 +932,8 @@ describe('Profiler', () => { expect(mountCall[3]).toBe(22); // start time expect(mountCall[4]).toBe(5); + // commit time + expect(mountCall[5]).toBe(flagEnabled && __DEV__ ? 54 : 44); }); }); }); From 22115eb02b17b6cd7d5d5c58a6755650e7e86002 Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Fri, 18 May 2018 07:14:58 -0700 Subject: [PATCH 4/5] Only init Profiler stateNode if enableProfilerTimer feature flag enabled --- packages/react-reconciler/src/ReactFiber.js | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiber.js b/packages/react-reconciler/src/ReactFiber.js index 4f841bdd4c148..d27a5b6a1313d 100644 --- a/packages/react-reconciler/src/ReactFiber.js +++ b/packages/react-reconciler/src/ReactFiber.js @@ -460,11 +460,13 @@ export function createFiberFromProfiler( const fiber = createFiber(Profiler, pendingProps, key, mode | ProfileMode); fiber.type = REACT_PROFILER_TYPE; fiber.expirationTime = expirationTime; - fiber.stateNode = { - elapsedPauseTimeAtStart: 0, - duration: 0, - startTime: 0, - }; + if (enableProfilerTimer) { + fiber.stateNode = { + elapsedPauseTimeAtStart: 0, + duration: 0, + startTime: 0, + }; + } return fiber; } From 974ee0021804f323b28be99cb5b484c3b6cb0477 Mon Sep 17 00:00:00 2001 From: Brian Vaughn Date: Fri, 18 May 2018 07:16:26 -0700 Subject: [PATCH 5/5] Moved commit time capture out of a hot loop --- packages/react-reconciler/src/ReactFiberScheduler.js | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/packages/react-reconciler/src/ReactFiberScheduler.js b/packages/react-reconciler/src/ReactFiberScheduler.js index 4540ed572c4f2..9af817fe93467 100644 --- a/packages/react-reconciler/src/ReactFiberScheduler.js +++ b/packages/react-reconciler/src/ReactFiberScheduler.js @@ -422,10 +422,6 @@ export default function( } } - if (enableProfilerTimer) { - recordCommitTime(); - } - // The following switch statement is only concerned about placement, // updates, and deletions. To avoid needing to add a case for every // possible bitmap value, we remove the secondary effects from the @@ -626,6 +622,10 @@ export default function( } 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.