From 8e598ea5c65b48e712ab78b0508b1fb58061fa2d Mon Sep 17 00:00:00 2001 From: Dan Abramov Date: Wed, 25 May 2016 17:39:05 +0100 Subject: [PATCH] Don't count the time inside flushes towards lifecycle hooks (#6860) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * Don't count the time inside flushes towards lifecycle hooks Fixes #6842. We keep the existing behavior of testing for matching `onBeginLifeCycleTimer`/`onEndLifeCycleTimer` calls, but we push the current timer onto the stack if we enter a flush. This solves an issue with portals which cause updates while a lifecycle timer is already running. I chose to subtract the time spent in the flush from the time counted towards the lifecycle method because it would artificially inflate the “total” time of the component due to all the components inside the portal, so it would skew the exclusive table. * Fix up the comment (cherry picked from commit 8d7161e0047e5ae85701f5684d196e3898c65263) --- src/renderers/shared/ReactDebugTool.js | 105 ++++++++++++------ .../shared/__tests__/ReactPerf-test.js | 56 ++++++++++ 2 files changed, 128 insertions(+), 33 deletions(-) diff --git a/src/renderers/shared/ReactDebugTool.js b/src/renderers/shared/ReactDebugTool.js index b6e6f98e316fb..cd6ac3bb80ed1 100644 --- a/src/renderers/shared/ReactDebugTool.js +++ b/src/renderers/shared/ReactDebugTool.js @@ -41,11 +41,13 @@ function emitEvent(handlerFunctionName, arg1, arg2, arg3, arg4, arg5) { var isProfiling = false; var flushHistory = []; +var lifeCycleTimerStack = []; var currentFlushNesting = 0; var currentFlushMeasurements = null; var currentFlushStartTime = null; var currentTimerDebugID = null; var currentTimerStartTime = null; +var currentTimerNestedFlushDuration = null; var currentTimerType = null; function clearHistory() { @@ -103,6 +105,72 @@ function checkDebugID(debugID) { warning(debugID, 'ReactDebugTool: debugID may not be empty.'); } +function beginLifeCycleTimer(debugID, timerType) { + if (!isProfiling || currentFlushNesting === 0) { + return; + } + warning( + !currentTimerType, + 'There is an internal error in the React performance measurement code. ' + + 'Did not expect %s timer to start while %s timer is still in ' + + 'progress for %s instance.', + timerType, + currentTimerType || 'no', + (debugID === currentTimerDebugID) ? 'the same' : 'another' + ); + currentTimerStartTime = performanceNow(); + currentTimerNestedFlushDuration = 0; + currentTimerDebugID = debugID; + currentTimerType = timerType; +} + +function endLifeCycleTimer(debugID, timerType) { + if (!isProfiling || currentFlushNesting === 0) { + return; + } + warning( + currentTimerType === timerType, + 'There is an internal error in the React performance measurement code. ' + + 'We did not expect %s timer to stop while %s timer is still in ' + + 'progress for %s instance. Please report this as a bug in React.', + timerType, + currentTimerType || 'no', + (debugID === currentTimerDebugID) ? 'the same' : 'another' + ); + currentFlushMeasurements.push({ + timerType, + instanceID: debugID, + duration: performanceNow() - currentTimerStartTime - currentTimerNestedFlushDuration, + }); + currentTimerStartTime = null; + currentTimerNestedFlushDuration = null; + currentTimerDebugID = null; + currentTimerType = null; +} + +function pauseCurrentLifeCycleTimer() { + var currentTimer = { + startTime: currentTimerStartTime, + nestedFlushStartTime: performanceNow(), + debugID: currentTimerDebugID, + timerType: currentTimerType, + }; + lifeCycleTimerStack.push(currentTimer); + currentTimerStartTime = null; + currentTimerNestedFlushDuration = null; + currentTimerDebugID = null; + currentTimerType = null; +} + +function resumeCurrentLifeCycleTimer() { + var {startTime, nestedFlushStartTime, debugID, timerType} = lifeCycleTimerStack.pop(); + var nestedFlushDuration = performanceNow() - nestedFlushStartTime; + currentTimerStartTime = startTime; + currentTimerNestedFlushDuration += nestedFlushDuration; + currentTimerDebugID = debugID; + currentTimerType = timerType; +} + var ReactDebugTool = { addDevtool(devtool) { eventHandlers.push(devtool); @@ -148,6 +216,7 @@ var ReactDebugTool = { if (__DEV__) { currentFlushNesting++; resetMeasurements(); + pauseCurrentLifeCycleTimer(); } emitEvent('onBeginFlush'); }, @@ -155,6 +224,7 @@ var ReactDebugTool = { if (__DEV__) { resetMeasurements(); currentFlushNesting--; + resumeCurrentLifeCycleTimer(); } emitEvent('onEndFlush'); }, @@ -162,44 +232,13 @@ var ReactDebugTool = { checkDebugID(debugID); emitEvent('onBeginLifeCycleTimer', debugID, timerType); if (__DEV__) { - if (isProfiling && currentFlushNesting > 0) { - warning( - !currentTimerType, - 'There is an internal error in the React performance measurement code. ' + - 'Did not expect %s timer to start while %s timer is still in ' + - 'progress for %s instance.', - timerType, - currentTimerType || 'no', - (debugID === currentTimerDebugID) ? 'the same' : 'another' - ); - currentTimerStartTime = performanceNow(); - currentTimerDebugID = debugID; - currentTimerType = timerType; - } + beginLifeCycleTimer(debugID, timerType); } }, onEndLifeCycleTimer(debugID, timerType) { checkDebugID(debugID); if (__DEV__) { - if (isProfiling && currentFlushNesting > 0) { - warning( - currentTimerType === timerType, - 'There is an internal error in the React performance measurement code. ' + - 'We did not expect %s timer to stop while %s timer is still in ' + - 'progress for %s instance. Please report this as a bug in React.', - timerType, - currentTimerType || 'no', - (debugID === currentTimerDebugID) ? 'the same' : 'another' - ); - currentFlushMeasurements.push({ - timerType, - instanceID: debugID, - duration: performanceNow() - currentTimerStartTime, - }); - currentTimerStartTime = null; - currentTimerDebugID = null; - currentTimerType = null; - } + endLifeCycleTimer(debugID, timerType); } emitEvent('onEndLifeCycleTimer', debugID, timerType); }, diff --git a/src/renderers/shared/__tests__/ReactPerf-test.js b/src/renderers/shared/__tests__/ReactPerf-test.js index 083b5f64f344c..a5d75364a6249 100644 --- a/src/renderers/shared/__tests__/ReactPerf-test.js +++ b/src/renderers/shared/__tests__/ReactPerf-test.js @@ -329,6 +329,62 @@ describe('ReactPerf', function() { }]); }); + it('should not count time in a portal towards lifecycle method', function() { + function Foo() { + return null; + } + + var portalContainer = document.createElement('div'); + class Portal extends React.Component { + componentDidMount() { + ReactDOM.render(, portalContainer); + } + render() { + return null; + } + } + + var container = document.createElement('div'); + var measurements = measure(() => { + ReactDOM.render(, container); + }); + + expect(ReactPerf.getExclusive(measurements)).toEqual([{ + key: 'Portal', + instanceCount: 1, + totalDuration: 6, + counts: { + ctor: 1, + componentDidMount: 1, + render: 1, + }, + durations: { + ctor: 1, + // We want to exclude nested imperative ReactDOM.render() from lifecycle hook's own time. + // Otherwise it would artificially float to the top even though its exclusive time is small. + // This is how we get 4 as a number with the performanceNow() mock: + // - we capture the time we enter componentDidMount (n = 0) + // - we capture the time when we enter a nested flush (n = 1) + // - in the nested flush, we call it twice: before and after rendering. (n = 3) + // - we capture the time when we exit a nested flush (n = 4) + // - we capture the time we exit componentDidMount (n = 5) + // Time spent in componentDidMount = (5 - 0 - (4 - 3)) = 4. + componentDidMount: 4, + render: 1, + }, + }, { + key: 'Foo', + instanceCount: 1, + totalDuration: 1, + counts: { + render: 1, + }, + durations: { + render: 1, + }, + }]); + }); + it('warns once when using getMeasurementsSummaryMap', function() { var measurements = measure(() => {}); spyOn(console, 'error');