Skip to content

Commit

Permalink
Don't count the time inside flushes towards lifecycle hooks (#6860)
Browse files Browse the repository at this point in the history
* 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
  • Loading branch information
gaearon committed May 25, 2016
1 parent de1de9e commit 8d7161e
Show file tree
Hide file tree
Showing 2 changed files with 128 additions and 33 deletions.
105 changes: 72 additions & 33 deletions src/renderers/shared/ReactDebugTool.js
Original file line number Diff line number Diff line change
Expand Up @@ -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() {
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -148,58 +216,29 @@ var ReactDebugTool = {
if (__DEV__) {
currentFlushNesting++;
resetMeasurements();
pauseCurrentLifeCycleTimer();
}
emitEvent('onBeginFlush');
},
onEndFlush() {
if (__DEV__) {
resetMeasurements();
currentFlushNesting--;
resumeCurrentLifeCycleTimer();
}
emitEvent('onEndFlush');
},
onBeginLifeCycleTimer(debugID, timerType) {
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);
},
Expand Down
56 changes: 56 additions & 0 deletions src/renderers/shared/__tests__/ReactPerf-test.js
Original file line number Diff line number Diff line change
Expand Up @@ -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(<Foo />, portalContainer);
}
render() {
return null;
}
}

var container = document.createElement('div');
var measurements = measure(() => {
ReactDOM.render(<Portal />, 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 <Foo /> 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');
Expand Down

0 comments on commit 8d7161e

Please sign in to comment.