From b3364fe35a752fb170d3265c5b7aa622aaf9250c Mon Sep 17 00:00:00 2001 From: Dan Abramov Date: Tue, 24 May 2016 20:41:50 +0100 Subject: [PATCH 1/2] Don't count the time inside flushes towards lifecycle hooks MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- 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..043130b86a475 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'); From b21f64c5181d914e35300d1ba4685842a41985ef Mon Sep 17 00:00:00 2001 From: Dan Abramov Date: Wed, 25 May 2016 17:36:53 +0100 Subject: [PATCH 2/2] Fix up the comment --- src/renderers/shared/__tests__/ReactPerf-test.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/renderers/shared/__tests__/ReactPerf-test.js b/src/renderers/shared/__tests__/ReactPerf-test.js index 043130b86a475..a5d75364a6249 100644 --- a/src/renderers/shared/__tests__/ReactPerf-test.js +++ b/src/renderers/shared/__tests__/ReactPerf-test.js @@ -365,7 +365,7 @@ describe('ReactPerf', function() { // 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) + // - 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.