Measure time between scheduling an async callback and flushing it

acdlite · acdlite · commit 3888bbc15a73 · 2017-11-09T17:35:03.000Z
Helps detect starvation issues.
diff --git a/packages/react-reconciler/src/ReactDebugFiberPerf.js b/packages/react-reconciler/src/ReactDebugFiberPerf.js
@@ -58,6 +58,7 @@ let hasScheduledUpdateInCurrentCommit: boolean = false;
 let hasScheduledUpdateInCurrentPhase: boolean = false;
 let commitCountInCurrentWorkLoop: number = 0;
 let effectCountInCurrentCommit: number = 0;
+let isWaitingForCallback: boolean = false;
 // During commits, we only show a measurement once per method name
 // to avoid stretch the commit phase with measurement overhead.
 const labelsInCurrentCommit: Set<string> = new Set();
@@ -231,6 +232,25 @@ export function recordScheduleUpdate(): void {
   }
 }
 
+export function startRequestCallbackTimer(): void {
+  if (enableUserTimingAPI && !isWaitingForCallback) {
+    isWaitingForCallback = true;
+    beginMark('(Waiting for async callback...)');
+  }
+}
+
+export function stopRequestCallbackTimer(didExpire: boolean): void {
+  if (enableUserTimingAPI) {
+    isWaitingForCallback = false;
+    const warning = didExpire ? 'Async work expired' : null;
+    endMark(
+      '(Waiting for async callback...)',
+      '(Waiting for async callback...)',
+      warning,
+    );
+  }
+}
+
 export function startWorkTimer(fiber: Fiber): void {
   if (enableUserTimingAPI) {
     if (!supportsUserTiming || shouldIgnoreFiber(fiber)) {
@@ -344,9 +364,7 @@ export function stopWorkLoopTimer(interruptedBy: Fiber | null): void {
         warning = 'A top-level update interrupted the previous render';
       } else {
         const componentName = getComponentName(interruptedBy) || 'Unknown';
-        warning = `An update to ${
-          componentName
-        } interrupted the previous render`;
+        warning = `An update to ${componentName} interrupted the previous render`;
       }
     } else if (commitCountInCurrentWorkLoop > 1) {
       warning = 'There were cascading updates';
diff --git a/packages/react-reconciler/src/ReactFiberScheduler.js b/packages/react-reconciler/src/ReactFiberScheduler.js
@@ -13,7 +13,9 @@ import type {FiberRoot} from './ReactFiberRoot';
 import type {HydrationContext} from './ReactFiberHydrationContext';
 import type {ExpirationTime} from './ReactFiberExpirationTime';
 
-import {getStackAddendumByWorkInProgressFiber} from 'shared/ReactFiberComponentTreeHook';
+import {
+  getStackAddendumByWorkInProgressFiber,
+} from 'shared/ReactFiberComponentTreeHook';
 import ReactErrorUtils from 'shared/ReactErrorUtils';
 import {ReactCurrentOwner} from 'shared/ReactGlobalSharedState';
 import {
@@ -33,6 +35,7 @@ import {
   HostPortal,
   ClassComponent,
 } from 'shared/ReactTypeOfWork';
+import {enableUserTimingAPI} from 'shared/ReactFeatureFlags';
 import getComponentName from 'shared/getComponentName';
 import invariant from 'fbjs/lib/invariant';
 import warning from 'fbjs/lib/warning';
@@ -47,6 +50,8 @@ import ReactDebugCurrentFiber from './ReactDebugCurrentFiber';
 import {
   recordEffect,
   recordScheduleUpdate,
+  startRequestCallbackTimer,
+  stopRequestCallbackTimer,
   startWorkTimer,
   stopWorkTimer,
   stopFailedWorkTimer,
@@ -1337,6 +1342,7 @@ export default function<T, P, I, TI, PI, C, CC, CX, PL>(
       performWork(Sync, null);
     } else if (!isCallbackScheduled) {
       isCallbackScheduled = true;
+      startRequestCallbackTimer();
       scheduleDeferredCallback(performAsyncWork);
     }
   }
@@ -1427,6 +1433,12 @@ export default function<T, P, I, TI, PI, C, CC, CX, PL>(
     // Keep working on roots until there's no more work, or until the we reach
     // the deadlne.
     findHighestPriorityRoot();
+
+    if (enableUserTimingAPI && deadline !== null) {
+      const didExpire = nextFlushedExpirationTime < recalculateCurrentTime();
+      stopRequestCallbackTimer(didExpire);
+    }
+
     while (
       nextFlushedRoot !== null &&
       nextFlushedExpirationTime !== NoWork &&
@@ -1449,6 +1461,7 @@ export default function<T, P, I, TI, PI, C, CC, CX, PL>(
     // If there's work left over, schedule a new callback.
     if (nextFlushedRoot !== null && !isCallbackScheduled) {
       isCallbackScheduled = true;
+      startRequestCallbackTimer();
       scheduleDeferredCallback(performAsyncWork);
     }
 
diff --git a/packages/react-reconciler/src/__tests__/ReactIncrementalPerf-test.js b/packages/react-reconciler/src/__tests__/ReactIncrementalPerf-test.js
@@ -546,4 +546,15 @@ describe('ReactDebugFiberPerf', () => {
     ReactNoop.flush();
     expect(getFlameChart()).toMatchSnapshot();
   });
+
+  it('warns if async work expires (starvation)', () => {
+    function Foo() {
+      return <span />;
+    }
+
+    ReactNoop.render(<Foo />);
+    ReactNoop.expire(5000);
+    ReactNoop.flush();
+    expect(getFlameChart()).toMatchSnapshot();
+  });
 });
diff --git a/packages/react-reconciler/src/__tests__/__snapshots__/ReactIncrementalPerf-test.js.snap b/packages/react-reconciler/src/__tests__/__snapshots__/ReactIncrementalPerf-test.js.snap
@@ -1,7 +1,9 @@
 // Jest Snapshot v1, https://goo.gl/fbAQLP
 
 exports[`ReactDebugFiberPerf captures all lifecycles 1`] = `
-"// Mount
+"⚛ (Waiting for async callback...)
+  // Mount
+
 ⚛ (React Tree Reconciliation)
   ⚛ AllLifecycles [mount]
     ⚛ AllLifecycles.componentWillMount
@@ -12,7 +14,9 @@ exports[`ReactDebugFiberPerf captures all lifecycles 1`] = `
   ⚛ (Calling Lifecycle Methods: 1 Total)
     ⚛ AllLifecycles.componentDidMount
 
-// Update
+⚛ (Waiting for async callback...)
+  // Update
+
 ⚛ (React Tree Reconciliation)
   ⚛ AllLifecycles [update]
     ⚛ AllLifecycles.componentWillReceiveProps
@@ -25,7 +29,9 @@ exports[`ReactDebugFiberPerf captures all lifecycles 1`] = `
   ⚛ (Calling Lifecycle Methods: 2 Total)
     ⚛ AllLifecycles.componentDidUpdate
 
-// Unmount
+⚛ (Waiting for async callback...)
+  // Unmount
+
 ⚛ (React Tree Reconciliation)
 
 ⚛ (Committing Changes)
@@ -36,7 +42,9 @@ exports[`ReactDebugFiberPerf captures all lifecycles 1`] = `
 `;
 
 exports[`ReactDebugFiberPerf deduplicates lifecycle names during commit to reduce overhead 1`] = `
-"// The commit phase should mention A and B just once
+"⚛ (Waiting for async callback...)
+  // The commit phase should mention A and B just once
+
 ⚛ (React Tree Reconciliation)
   ⚛ Parent [update]
     ⚛ A [update]
@@ -50,8 +58,10 @@ exports[`ReactDebugFiberPerf deduplicates lifecycle names during commit to reduc
     ⚛ A.componentDidUpdate
     ⚛ B.componentDidUpdate
 
-// Because of deduplication, we don't know B was cascading,
-// but we should still see the warning for the commit phase.
+⚛ (Waiting for async callback...)
+  // Because of deduplication, we don't know B was cascading,
+  // but we should still see the warning for the commit phase.
+
 ⚛ (React Tree Reconciliation)
   ⚛ Parent [update]
     ⚛ A [update]
@@ -94,7 +104,9 @@ exports[`ReactDebugFiberPerf does not schedule an extra callback if setState is
 `;
 
 exports[`ReactDebugFiberPerf does not treat setState from cWM or cWRP as cascading 1`] = `
-"// Should not print a warning
+"⚛ (Waiting for async callback...)
+  // Should not print a warning
+
 ⚛ (React Tree Reconciliation)
   ⚛ Parent [mount]
     ⚛ NotCascading [mount]
@@ -104,7 +116,9 @@ exports[`ReactDebugFiberPerf does not treat setState from cWM or cWRP as cascadi
   ⚛ (Committing Host Effects: 1 Total)
   ⚛ (Calling Lifecycle Methods: 0 Total)
 
-// Should not print a warning
+⚛ (Waiting for async callback...)
+  // Should not print a warning
+
 ⚛ (React Tree Reconciliation)
   ⚛ Parent [update]
     ⚛ NotCascading [update]
@@ -117,7 +131,9 @@ exports[`ReactDebugFiberPerf does not treat setState from cWM or cWRP as cascadi
 `;
 
 exports[`ReactDebugFiberPerf measures a simple reconciliation 1`] = `
-"// Mount
+"⚛ (Waiting for async callback...)
+  // Mount
+
 ⚛ (React Tree Reconciliation)
   ⚛ Parent [mount]
     ⚛ Child [mount]
@@ -126,7 +142,9 @@ exports[`ReactDebugFiberPerf measures a simple reconciliation 1`] = `
   ⚛ (Committing Host Effects: 1 Total)
   ⚛ (Calling Lifecycle Methods: 0 Total)
 
-// Update
+⚛ (Waiting for async callback...)
+  // Update
+
 ⚛ (React Tree Reconciliation)
   ⚛ Parent [update]
     ⚛ Child [update]
@@ -135,7 +153,9 @@ exports[`ReactDebugFiberPerf measures a simple reconciliation 1`] = `
   ⚛ (Committing Host Effects: 2 Total)
   ⚛ (Calling Lifecycle Methods: 2 Total)
 
-// Unmount
+⚛ (Waiting for async callback...)
+  // Unmount
+
 ⚛ (React Tree Reconciliation)
 
 ⚛ (Committing Changes)
@@ -145,18 +165,24 @@ exports[`ReactDebugFiberPerf measures a simple reconciliation 1`] = `
 `;
 
 exports[`ReactDebugFiberPerf measures deferred work in chunks 1`] = `
-"// Start mounting Parent and A
+"⚛ (Waiting for async callback...)
+  // Start mounting Parent and A
+
 ⚛ (React Tree Reconciliation)
   ⚛ Parent [mount]
     ⚛ A [mount]
       ⚛ Child [mount]
 
-// Mount B just a little (but not enough to memoize)
+⚛ (Waiting for async callback...)
+  // Mount B just a little (but not enough to memoize)
+
 ⚛ (React Tree Reconciliation)
   ⚛ Parent [mount]
     ⚛ B [mount]
 
-// Complete B and Parent
+⚛ (Waiting for async callback...)
+  // Complete B and Parent
+
 ⚛ (React Tree Reconciliation)
   ⚛ Parent [mount]
     ⚛ B [mount]
@@ -177,7 +203,9 @@ exports[`ReactDebugFiberPerf measures deprioritized work 1`] = `
   ⚛ (Committing Host Effects: 1 Total)
   ⚛ (Calling Lifecycle Methods: 0 Total)
 
-// Flush the child
+⚛ (Waiting for async callback...)
+  // Flush the child
+
 ⚛ (React Tree Reconciliation)
   ⚛ Child [mount]
 
@@ -188,7 +216,9 @@ exports[`ReactDebugFiberPerf measures deprioritized work 1`] = `
 `;
 
 exports[`ReactDebugFiberPerf recovers from caught errors 1`] = `
-"// Stop on Baddie and restart from Boundary
+"⚛ (Waiting for async callback...)
+  // Stop on Baddie and restart from Boundary
+
 ⚛ (React Tree Reconciliation)
   ⚛ Parent [mount]
     ⛔ Boundary [mount] Warning: An error was thrown inside this error boundary
@@ -211,7 +241,9 @@ exports[`ReactDebugFiberPerf recovers from caught errors 1`] = `
 `;
 
 exports[`ReactDebugFiberPerf recovers from fatal errors 1`] = `
-"// Will fatal
+"⚛ (Waiting for async callback...)
+  // Will fatal
+
 ⚛ (React Tree Reconciliation)
   ⚛ Parent [mount]
     ⚛ Baddie [mount]
@@ -220,7 +252,9 @@ exports[`ReactDebugFiberPerf recovers from fatal errors 1`] = `
   ⚛ (Committing Host Effects: 1 Total)
   ⚛ (Calling Lifecycle Methods: 1 Total)
 
-// Will reconcile from a clean state
+⚛ (Waiting for async callback...)
+  // Will reconcile from a clean state
+
 ⚛ (React Tree Reconciliation)
   ⚛ Parent [mount]
     ⚛ Child [mount]
@@ -232,7 +266,9 @@ exports[`ReactDebugFiberPerf recovers from fatal errors 1`] = `
 `;
 
 exports[`ReactDebugFiberPerf skips parents during setState 1`] = `
-"// Should include just A and B, no Parents
+"⚛ (Waiting for async callback...)
+  // Should include just A and B, no Parents
+
 ⚛ (React Tree Reconciliation)
   ⚛ A [update]
   ⚛ B [update]
@@ -244,7 +280,9 @@ exports[`ReactDebugFiberPerf skips parents during setState 1`] = `
 `;
 
 exports[`ReactDebugFiberPerf supports portals 1`] = `
-"⚛ (React Tree Reconciliation)
+"⚛ (Waiting for async callback...)
+
+⚛ (React Tree Reconciliation)
   ⚛ Parent [mount]
     ⚛ Child [mount]
 
@@ -255,7 +293,9 @@ exports[`ReactDebugFiberPerf supports portals 1`] = `
 `;
 
 exports[`ReactDebugFiberPerf supports returns 1`] = `
-"⚛ (React Tree Reconciliation)
+"⚛ (Waiting for async callback...)
+
+⚛ (React Tree Reconciliation)
   ⚛ App [mount]
     ⚛ CoParent [mount]
       ⚛ HandleReturns [mount]
@@ -272,26 +312,42 @@ exports[`ReactDebugFiberPerf supports returns 1`] = `
 `;
 
 exports[`ReactDebugFiberPerf warns if an in-progress update is interrupted 1`] = `
-"⚛ (React Tree Reconciliation)
-  ⚛ Foo [mount]
+"⚛ (Waiting for async callback...)
 
-⛔ (React Tree Reconciliation) Warning: A top-level update interrupted the previous render
+⚛ (React Tree Reconciliation)
   ⚛ Foo [mount]
 
+⚛ (Waiting for async callback...)
+  ⛔ (React Tree Reconciliation) Warning: A top-level update interrupted the previous render
+    ⚛ Foo [mount]
+  ⚛ (Committing Changes)
+    ⚛ (Committing Host Effects: 1 Total)
+    ⚛ (Calling Lifecycle Methods: 0 Total)
+
+⚛ (React Tree Reconciliation)
+
 ⚛ (Committing Changes)
   ⚛ (Committing Host Effects: 1 Total)
-  ⚛ (Calling Lifecycle Methods: 0 Total)
+  ⚛ (Calling Lifecycle Methods: 1 Total)
+"
+`;
+
+exports[`ReactDebugFiberPerf warns if async work expires (starvation) 1`] = `
+"⛔ (Waiting for async callback...) Warning: Async work expired
 
 ⚛ (React Tree Reconciliation)
+  ⚛ Foo [mount]
 
 ⚛ (Committing Changes)
   ⚛ (Committing Host Effects: 1 Total)
-  ⚛ (Calling Lifecycle Methods: 1 Total)
+  ⚛ (Calling Lifecycle Methods: 0 Total)
 "
 `;
 
 exports[`ReactDebugFiberPerf warns on cascading renders from setState 1`] = `
-"// Should print a warning
+"⚛ (Waiting for async callback...)
+  // Should print a warning
+
 ⚛ (React Tree Reconciliation)
   ⚛ Parent [mount]
     ⚛ Cascading [mount]
@@ -311,7 +367,9 @@ exports[`ReactDebugFiberPerf warns on cascading renders from setState 1`] = `
 `;
 
 exports[`ReactDebugFiberPerf warns on cascading renders from top-level render 1`] = `
-"// Rendering the first root
+"⚛ (Waiting for async callback...)
+  // Rendering the first root
+
 ⚛ (React Tree Reconciliation)
   ⚛ Cascading [mount]
 
