Don't count the time inside flushes towards lifecycle hooks

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,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);
   },

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(<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');