diff --git a/src/renderers/shared/ReactDebugTool.js b/src/renderers/shared/ReactDebugTool.js index b6e6f98e31..cd6ac3bb80 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 083b5f64f3..a5d75364a6 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');