Don't count the time inside flushes towards lifecycle hooks (#6860)
* 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
Dan Abramov committed
May 25, 2016 at 17:39 UTC
8d7161e0047e5ae85701f5684d196e3898c65263
2 files changed
+128
-33
src/renderers/shared/ReactDebugTool.js
+72
-33
@@ -41,11 +41,13 @@ function emitEvent(handlerFunctionName, arg1, arg2, arg3, arg4, arg5) {
41
42
var isProfiling = false;
43
var flushHistory = [];
44
+var lifeCycleTimerStack = [];
45
var currentFlushNesting = 0;
46
var currentFlushMeasurements = null;
47
var currentFlushStartTime = null;
48
var currentTimerDebugID = null;
49
var currentTimerStartTime = null;
50
+var currentTimerNestedFlushDuration = null;
51
var currentTimerType = null;
52
53
function clearHistory() {
@@ -103,6 +105,72 @@ function checkDebugID(debugID) {
105
warning(debugID, 'ReactDebugTool: debugID may not be empty.');
106
}
107
108
+function beginLifeCycleTimer(debugID, timerType) {
109
+ if (!isProfiling || currentFlushNesting === 0) {
110
+ return;
111
+ }
112
+ warning(
113
+ !currentTimerType,
114
+ 'There is an internal error in the React performance measurement code. ' +
115
+ 'Did not expect %s timer to start while %s timer is still in ' +
116
+ 'progress for %s instance.',
117
+ timerType,
118
+ currentTimerType || 'no',
119
+ (debugID === currentTimerDebugID) ? 'the same' : 'another'
120
+ );
121
+ currentTimerStartTime = performanceNow();
122
+ currentTimerNestedFlushDuration = 0;
123
+ currentTimerDebugID = debugID;
124
+ currentTimerType = timerType;
125
+}
126
+
127
+function endLifeCycleTimer(debugID, timerType) {
128
+ if (!isProfiling || currentFlushNesting === 0) {
129
+ return;
130
+ }
131
+ warning(
132
+ currentTimerType === timerType,
133
+ 'There is an internal error in the React performance measurement code. ' +
134
+ 'We did not expect %s timer to stop while %s timer is still in ' +
135
+ 'progress for %s instance. Please report this as a bug in React.',
136
+ timerType,
137
+ currentTimerType || 'no',
138
+ (debugID === currentTimerDebugID) ? 'the same' : 'another'
139
+ );
140
+ currentFlushMeasurements.push({
141
+ timerType,
142
+ instanceID: debugID,
143
+ duration: performanceNow() - currentTimerStartTime - currentTimerNestedFlushDuration,
144
+ });
145
+ currentTimerStartTime = null;
146
+ currentTimerNestedFlushDuration = null;
147
+ currentTimerDebugID = null;
148
+ currentTimerType = null;
149
+}
150
+
151
+function pauseCurrentLifeCycleTimer() {
152
+ var currentTimer = {
153
+ startTime: currentTimerStartTime,
154
+ nestedFlushStartTime: performanceNow(),
155
+ debugID: currentTimerDebugID,
156
+ timerType: currentTimerType,
157
+ };
158
+ lifeCycleTimerStack.push(currentTimer);
159
+ currentTimerStartTime = null;
160
+ currentTimerNestedFlushDuration = null;
161
+ currentTimerDebugID = null;
162
+ currentTimerType = null;
163
+}
164
+
165
+function resumeCurrentLifeCycleTimer() {
166
+ var {startTime, nestedFlushStartTime, debugID, timerType} = lifeCycleTimerStack.pop();
167
+ var nestedFlushDuration = performanceNow() - nestedFlushStartTime;
168
+ currentTimerStartTime = startTime;
169
+ currentTimerNestedFlushDuration += nestedFlushDuration;
170
+ currentTimerDebugID = debugID;
171
+ currentTimerType = timerType;
172
+}
173
+
174
var ReactDebugTool = {
175
addDevtool(devtool) {
176
eventHandlers.push(devtool);
@@ -148,6 +216,7 @@ var ReactDebugTool = {
216
if (__DEV__) {
217
currentFlushNesting++;
218
resetMeasurements();
219
+ pauseCurrentLifeCycleTimer();
220
}
221
emitEvent('onBeginFlush');
222
},
@@ -155,6 +224,7 @@ var ReactDebugTool = {
224
if (__DEV__) {
225
resetMeasurements();
226
currentFlushNesting--;
227
+ resumeCurrentLifeCycleTimer();
228
}
229
emitEvent('onEndFlush');
230
},
@@ -162,44 +232,13 @@ var ReactDebugTool = {
232
checkDebugID(debugID);
233
emitEvent('onBeginLifeCycleTimer', debugID, timerType);
234
if (__DEV__) {
165
- if (isProfiling && currentFlushNesting > 0) {
166
- warning(
167
- !currentTimerType,
168
- 'There is an internal error in the React performance measurement code. ' +
169
- 'Did not expect %s timer to start while %s timer is still in ' +
170
- 'progress for %s instance.',
171
- timerType,
172
- currentTimerType || 'no',
173
- (debugID === currentTimerDebugID) ? 'the same' : 'another'
174
- );
175
- currentTimerStartTime = performanceNow();
176
- currentTimerDebugID = debugID;
177
- currentTimerType = timerType;
178
- }
235
+ beginLifeCycleTimer(debugID, timerType);
236
}
237
},
238
onEndLifeCycleTimer(debugID, timerType) {
239
checkDebugID(debugID);
240
if (__DEV__) {
184
- if (isProfiling && currentFlushNesting > 0) {
185
- warning(
186
- currentTimerType === timerType,
187
- 'There is an internal error in the React performance measurement code. ' +
188
- 'We did not expect %s timer to stop while %s timer is still in ' +
189
- 'progress for %s instance. Please report this as a bug in React.',
190
- timerType,
191
- currentTimerType || 'no',
192
- (debugID === currentTimerDebugID) ? 'the same' : 'another'
193
- );
194
- currentFlushMeasurements.push({
195
- timerType,
196
- instanceID: debugID,
197
- duration: performanceNow() - currentTimerStartTime,
198
- });
199
- currentTimerStartTime = null;
200
- currentTimerDebugID = null;
201
- currentTimerType = null;
202
- }
241
+ endLifeCycleTimer(debugID, timerType);
242
}
243
emitEvent('onEndLifeCycleTimer', debugID, timerType);
244
},
src/renderers/shared/__tests__/ReactPerf-test.js
+56
@@ -329,6 +329,62 @@ describe('ReactPerf', function() {
329
}]);
330
});
331
332
+ it('should not count time in a portal towards lifecycle method', function() {
333
+ function Foo() {
334
+ return null;
335
+ }
336
+
337
+ var portalContainer = document.createElement('div');
338
+ class Portal extends React.Component {
339
+ componentDidMount() {
340
+ ReactDOM.render(<Foo />, portalContainer);
341
+ }
342
+ render() {
343
+ return null;
344
+ }
345
+ }
346
+
347
+ var container = document.createElement('div');
348
+ var measurements = measure(() => {
349
+ ReactDOM.render(<Portal />, container);
350
+ });
351
+
352
+ expect(ReactPerf.getExclusive(measurements)).toEqual([{
353
+ key: 'Portal',
354
+ instanceCount: 1,
355
+ totalDuration: 6,
356
+ counts: {
357
+ ctor: 1,
358
+ componentDidMount: 1,
359
+ render: 1,
360
+ },
361
+ durations: {
362
+ ctor: 1,
363
+ // We want to exclude nested imperative ReactDOM.render() from lifecycle hook's own time.
364
+ // Otherwise it would artificially float to the top even though its exclusive time is small.
365
+ // This is how we get 4 as a number with the performanceNow() mock:
366
+ // - we capture the time we enter componentDidMount (n = 0)
367
+ // - we capture the time when we enter a nested flush (n = 1)
368
+ // - in the nested flush, we call it twice: before and after <Foo /> rendering. (n = 3)
369
+ // - we capture the time when we exit a nested flush (n = 4)
370
+ // - we capture the time we exit componentDidMount (n = 5)
371
+ // Time spent in componentDidMount = (5 - 0 - (4 - 3)) = 4.
372
+ componentDidMount: 4,
373
+ render: 1,
374
+ },
375
+ }, {
376
+ key: 'Foo',
377
+ instanceCount: 1,
378
+ totalDuration: 1,
379
+ counts: {
380
+ render: 1,
381
+ },
382
+ durations: {
383
+ render: 1,
384
+ },
385
+ }]);
386
+ });
387
+
388
it('warns once when using getMeasurementsSummaryMap', function() {
389
var measurements = measure(() => {});
390
spyOn(console, 'error');