Record "actual" times for all Fibers within a Profiler tree (alt) (fa…

…cebook#12910)

* Moved actual time fields from Profiler stateNode to Fiber

* Record actual time for all Fibers within a ProfileMode tree

* Changed how profiler accumulates time

This change gives up on accumulating time across renders of different priority, but in exchange- simplifies how the commit phase (reset) code works, and perhaps also makes the profiling code more compatible with future resuming behavior

packages/react-reconciler/src/ReactFiber.js

@@ -152,8 +152,24 @@ export type Fiber = {|
   // memory if we need to.
   alternate: Fiber | null,
 
-  // Profiling metrics
+  // Time spent rendering this Fiber and its descendants for the current update.
+  // This tells us how well the tree makes use of sCU for memoization.
+  // This field is only set when the enableProfilerTimer flag is enabled.
+  actualDuration?: number,
+
+  // If the Fiber is currently active in the "render" phase,
+  // This marks the time at which the work began.
+  // This field is only set when the enableProfilerTimer flag is enabled.
+  actualStartTime?: number,
+
+  // Duration of the most recent render time for this Fiber.
+  // This value is not updated when we bailout for memoization purposes.
+  // This field is only set when the enableProfilerTimer flag is enabled.
   selfBaseTime?: number,
+
+  // Sum of base times for all descedents of this Fiber.
+  // This value bubbles up during the "complete" phase.
+  // This field is only set when the enableProfilerTimer flag is enabled.
   treeBaseTime?: number,
 
   // Conceptual aliases
@@ -211,6 +227,8 @@ function FiberNode(
   this.alternate = null;
 
   if (enableProfilerTimer) {
+    this.actualDuration = 0;
+    this.actualStartTime = 0;
     this.selfBaseTime = 0;
     this.treeBaseTime = 0;
   }
@@ -295,6 +313,15 @@ export function createWorkInProgress(
     workInProgress.nextEffect = null;
     workInProgress.firstEffect = null;
     workInProgress.lastEffect = null;
+
+    if (enableProfilerTimer) {
+      // We intentionally reset, rather than copy, actualDuration & actualStartTime.
+      // This prevents time from endlessly accumulating in new commits.
+      // This has the downside of resetting values for different priority renders,
+      // But works for yielding (the common case) and should support resuming.
+      workInProgress.actualDuration = 0;
+      workInProgress.actualStartTime = 0;
+    }
   }
 
   workInProgress.expirationTime = expirationTime;
@@ -460,13 +487,6 @@ export function createFiberFromProfiler(
   const fiber = createFiber(Profiler, pendingProps, key, mode | ProfileMode);
   fiber.type = REACT_PROFILER_TYPE;
   fiber.expirationTime = expirationTime;
-  if (enableProfilerTimer) {
-    fiber.stateNode = {
-      elapsedPauseTimeAtStart: 0,
-      duration: 0,
-      startTime: 0,
-    };
-  }
 
   return fiber;
 }
@@ -541,6 +561,8 @@ export function assignFiberPropertiesInDEV(
   target.expirationTime = source.expirationTime;
   target.alternate = source.alternate;
   if (enableProfilerTimer) {
+    target.actualDuration = source.actualDuration;
+    target.actualStartTime = source.actualStartTime;
     target.selfBaseTime = source.selfBaseTime;
     target.treeBaseTime = source.treeBaseTime;
   }

packages/react-reconciler/src/ReactFiberBeginWork.js

@@ -61,7 +61,7 @@ import {
 } from './ReactChildFiber';
 import {processUpdateQueue} from './ReactUpdateQueue';
 import {NoWork, Never} from './ReactFiberExpirationTime';
-import {AsyncMode, StrictMode} from './ReactTypeOfMode';
+import {AsyncMode, ProfileMode, StrictMode} from './ReactTypeOfMode';
 import {
   shouldSetTextContent,
   shouldDeprioritizeSubtree,
@@ -214,11 +214,6 @@ function updateMode(current, workInProgress) {
 function updateProfiler(current, workInProgress) {
   const nextProps = workInProgress.pendingProps;
   if (enableProfilerTimer) {
-    // Start render timer here and push start time onto queue
-    markActualRenderTimeStarted(workInProgress);
-
-    // Let the "complete" phase know to stop the timer,
-    // And the scheduler to record the measured time.
     workInProgress.effectTag |= Update;
   }
   if (workInProgress.memoizedProps === nextProps) {
@@ -1111,11 +1106,6 @@ function bailoutOnLowPriority(current, workInProgress) {
     case ContextProvider:
       pushProvider(workInProgress);
       break;
-    case Profiler:
-      if (enableProfilerTimer) {
-        markActualRenderTimeStarted(workInProgress);
-      }
-      break;
   }
   // TODO: What if this is currently in progress?
   // How can that happen? How is this not being cloned?
@@ -1138,6 +1128,12 @@ function beginWork(
   workInProgress: Fiber,
   renderExpirationTime: ExpirationTime,
 ): Fiber | null {
+  if (enableProfilerTimer) {
+    if (workInProgress.mode & ProfileMode) {
+      markActualRenderTimeStarted(workInProgress);
+    }
+  }
+
   if (
     workInProgress.expirationTime === NoWork ||
     workInProgress.expirationTime > renderExpirationTime

packages/react-reconciler/src/ReactFiberCommitWork.js

@@ -806,15 +806,11 @@ function commitWork(current: Fiber | null, finishedWork: Fiber): void {
         onRender(
           finishedWork.memoizedProps.id,
           current === null ? 'mount' : 'update',
-          finishedWork.stateNode.duration,
+          finishedWork.actualDuration,
           finishedWork.treeBaseTime,
-          finishedWork.stateNode.startTime,
+          finishedWork.actualStartTime,
           getCommitTime(),
         );
-
-        // Reset actualTime after successful commit.
-        // By default, we append to this time to account for errors and pauses.
-        finishedWork.stateNode.duration = 0;
       }
       return;
     }

packages/react-reconciler/src/ReactFiberCompleteWork.js

@@ -38,6 +38,7 @@ import {
   TimeoutComponent,
 } from 'shared/ReactTypeOfWork';
 import {Placement, Ref, Update} from 'shared/ReactTypeOfSideEffect';
+import {ProfileMode} from './ReactTypeOfMode';
 import invariant from 'fbjs/lib/invariant';
 
 import {
@@ -312,6 +313,13 @@ function completeWork(
   renderExpirationTime: ExpirationTime,
 ): Fiber | null {
   const newProps = workInProgress.pendingProps;
+
+  if (enableProfilerTimer) {
+    if (workInProgress.mode & ProfileMode) {
+      recordElapsedActualRenderTime(workInProgress);
+    }
+  }
+
   switch (workInProgress.tag) {
     case FunctionalComponent:
       return null;
@@ -489,9 +497,6 @@ function completeWork(
     case Mode:
       return null;
     case Profiler:
-      if (enableProfilerTimer) {
-        recordElapsedActualRenderTime(workInProgress);
-      }
       return null;
     case HostPortal:
       popHostContainer(workInProgress);

packages/react-reconciler/src/ReactFiberScheduler.js

@@ -106,6 +106,7 @@ import {
   checkActualRenderTimeStackEmpty,
   pauseActualRenderTimerIfRunning,
   recordCommitTime,
+  recordElapsedActualRenderTime,
   recordElapsedBaseRenderTimeIfRunning,
   resetActualRenderTimer,
   resumeActualRenderTimerIfPaused,
@@ -311,6 +312,10 @@ if (__DEV__ && replayFailedUnitOfWorkWithInvokeGuardedCallback) {
       clearCaughtError();
 
       if (enableProfilerTimer) {
+        if (failedUnitOfWork.mode & ProfileMode) {
+          recordElapsedActualRenderTime(failedUnitOfWork);
+        }
+
         // Stop "base" render timer again (after the re-thrown error).
         stopBaseRenderTimerIfRunning();
       }
@@ -573,6 +578,8 @@ function commitRoot(finishedWork: Fiber): ExpirationTime {
   stopCommitSnapshotEffectsTimer();
 
   if (enableProfilerTimer) {
+    // Mark the current commit time to be shared by all Profilers in this batch.
+    // This enables them to be grouped later.
     recordCommitTime();
   }
 

packages/react-reconciler/src/ReactFiberUnwindWork.js

@@ -20,7 +20,6 @@ import {
   HostComponent,
   HostPortal,
   ContextProvider,
-  Profiler,
   TimeoutComponent,
 } from 'shared/ReactTypeOfWork';
 import {
@@ -34,6 +33,7 @@ import {
   enableProfilerTimer,
   enableSuspense,
 } from 'shared/ReactFeatureFlags';
+import {ProfileMode} from './ReactTypeOfMode';
 
 import {createCapturedValue} from './ReactCapturedValue';
 import {
@@ -301,6 +301,12 @@ function unwindWork(
   renderIsExpired: boolean,
   renderExpirationTime: ExpirationTime,
 ) {
+  if (enableProfilerTimer) {
+    if (workInProgress.mode & ProfileMode) {
+      recordElapsedActualRenderTime(workInProgress);
+    }
+  }
+
   switch (workInProgress.tag) {
     case ClassComponent: {
       popLegacyContextProvider(workInProgress);
@@ -345,6 +351,14 @@ function unwindWork(
 }
 
 function unwindInterruptedWork(interruptedWork: Fiber) {
+  if (enableProfilerTimer) {
+    if (interruptedWork.mode & ProfileMode) {
+      // Resume in case we're picking up on work that was paused.
+      resumeActualRenderTimerIfPaused();
+      recordElapsedActualRenderTime(interruptedWork);
+    }
+  }
+
   switch (interruptedWork.tag) {
     case ClassComponent: {
       popLegacyContextProvider(interruptedWork);
@@ -365,13 +379,6 @@ function unwindInterruptedWork(interruptedWork: Fiber) {
     case ContextProvider:
       popProvider(interruptedWork);
       break;
-    case Profiler:
-      if (enableProfilerTimer) {
-        // Resume in case we're picking up on work that was paused.
-        resumeActualRenderTimerIfPaused();
-        recordElapsedActualRenderTime(interruptedWork);
-      }
-      break;
     default:
       break;
   }

packages/react-reconciler/src/ReactProfilerTimer.js

@@ -9,6 +9,7 @@
 
 import type {Fiber} from './ReactFiber';
 
+import getComponentName from 'shared/getComponentName';
 import {enableProfilerTimer} from 'shared/ReactFeatureFlags';
 
 import warning from 'fbjs/lib/warning';
@@ -76,9 +77,10 @@ function markActualRenderTimeStarted(fiber: Fiber): void {
   if (__DEV__) {
     fiberStack.push(fiber);
   }
-  const stateNode = fiber.stateNode;
-  stateNode.elapsedPauseTimeAtStart = totalElapsedPauseTime;
-  stateNode.startTime = now();
+
+  fiber.actualDuration =
+    now() - ((fiber.actualDuration: any): number) - totalElapsedPauseTime;
+  fiber.actualStartTime = now();
 }
 
 function pauseActualRenderTimerIfRunning(): void {
@@ -95,13 +97,15 @@ function recordElapsedActualRenderTime(fiber: Fiber): void {
     return;
   }
   if (__DEV__) {
-    warning(fiber === fiberStack.pop(), 'Unexpected Fiber popped.');
+    warning(
+      fiber === fiberStack.pop(),
+      'Unexpected Fiber (%s) popped.',
+      getComponentName(fiber),
+    );
   }
-  const stateNode = fiber.stateNode;
-  stateNode.duration +=
-    now() -
-    (totalElapsedPauseTime - stateNode.elapsedPauseTimeAtStart) -
-    stateNode.startTime;
+
+  fiber.actualDuration =
+    now() - totalElapsedPauseTime - ((fiber.actualDuration: any): number);
 }
 
 function resetActualRenderTimer(): void {

packages/react/src/__tests__/ReactProfiler-test.internal.js

@@ -228,6 +228,28 @@ describe('Profiler', () => {
       expect(call[3]).toBe(10); // base time
       expect(call[4]).toBe(35); // start time
       expect(call[5]).toBe(45); // commit time
+
+      callback.mockReset();
+
+      advanceTimeBy(20); // 45 -> 65
+
+      renderer.update(
+        <React.unstable_Profiler id="test" onRender={callback}>
+          <AdvanceTime byAmount={4} />
+        </React.unstable_Profiler>,
+      );
+
+      expect(callback).toHaveBeenCalledTimes(1);
+
+      [call] = callback.mock.calls;
+
+      expect(call).toHaveLength(6);
+      expect(call[0]).toBe('test');
+      expect(call[1]).toBe('update');
+      expect(call[2]).toBe(4); // actual time
+      expect(call[3]).toBe(4); // base time
+      expect(call[4]).toBe(65); // start time
+      expect(call[5]).toBe(69); // commit time
     });
 
     it('includes render times of nested Profilers in their parent times', () => {
@@ -576,7 +598,9 @@ describe('Profiler', () => {
           </React.unstable_Profiler>,
           {unstable_isAsync: true},
         );
-        expect(renderer.unstable_flushThrough(['first'])).toEqual(['Yield:10']);
+        expect(renderer.unstable_flushThrough(['Yield:10'])).toEqual([
+          'Yield:10',
+        ]);
         expect(callback).toHaveBeenCalledTimes(0);
 
         // Simulate time moving forward while frame is paused.
@@ -681,11 +705,12 @@ describe('Profiler', () => {
           }),
         ).toEqual(['Yield:11']);
 
-        // Verify that the actual time includes all three durations above.
-        // And the base time includes only the final rendered tree times.
+        // The actual time should include only the most recent render,
+        // Because this lets us avoid a lot of commit phase reset complexity.
+        // The base time includes only the final rendered tree times.
         expect(callback).toHaveBeenCalledTimes(1);
         call = callback.mock.calls[0];
-        expect(call[2]).toBe(19); // actual time
+        expect(call[2]).toBe(11); // actual time
         expect(call[3]).toBe(11); // base time
         expect(call[4]).toBe(264); // start time
         expect(call[5]).toBe(275); // commit time
@@ -772,12 +797,13 @@ describe('Profiler', () => {
           renderer.unstable_flushSync(() => second.setState({renderTime: 30})),
         ).toEqual(['SecondComponent:30', 'Yield:7']);
 
-        // Verify that the actual time includes time spent in the both renders so far (10ms and 37ms).
+        // The actual time should include only the most recent render (37ms),
+        // Because this lets us avoid a lot of commit phase reset complexity.
         // The base time should include the more recent times for the SecondComponent subtree,
         // As well as the original times for the FirstComponent subtree.
         expect(callback).toHaveBeenCalledTimes(1);
         call = callback.mock.calls[0];
-        expect(call[2]).toBe(47); // actual time
+        expect(call[2]).toBe(37); // actual time
         expect(call[3]).toBe(42); // base time
         expect(call[4]).toBe(229); // start time
         expect(call[5]).toBe(266); // commit time