Don't count the time inside flushes towards lifecycle hooks (facebook…

…#6860)

* Don't count the time inside flushes towards lifecycle hooks

Fixes facebook#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

(cherry picked from commit 8d7161e)

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