Measure time between scheduling an async callback and flushing it (#11506)

* Measure time between scheduling an async callback and flushing it

Helps detect starvation issues.

* Debug comments should print directly above the next measure

* Better warning message

Most users won't know what "expires" means

Author: acdlite

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,29 @@ export function recordScheduleUpdate(): void {
   }
 }
 
+export function startRequestCallbackTimer(): void {
+  if (enableUserTimingAPI) {
+    if (supportsUserTiming && !isWaitingForCallback) {
+      isWaitingForCallback = true;
+      beginMark('(Waiting for async callback...)');
+    }
+  }
+}
+
+export function stopRequestCallbackTimer(didExpire: boolean): void {
+  if (enableUserTimingAPI) {
+    if (supportsUserTiming) {
+      isWaitingForCallback = false;
+      const warning = didExpire ? 'React was blocked by main thread' : null;
+      endMark(
+        '(Waiting for async callback...)',
+        '(Waiting for async callback...)',
+        warning,
+      );
+    }
+  }
+}
+
 export function startWorkTimer(fiber: Fiber): void {
   if (enableUserTimingAPI) {
     if (!supportsUserTiming || shouldIgnoreFiber(fiber)) {

packages/react-reconciler/src/ReactFiberScheduler.js

@@ -33,6 +33,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 +48,8 @@ import ReactDebugCurrentFiber from './ReactDebugCurrentFiber';
 import {
   recordEffect,
   recordScheduleUpdate,
+  startRequestCallbackTimer,
+  stopRequestCallbackTimer,
   startWorkTimer,
   stopWorkTimer,
   stopFailedWorkTimer,
@@ -1337,6 +1340,7 @@ export default function<T, P, I, TI, PI, C, CC, CX, PL>(
       performWork(Sync, null);
     } else if (!isCallbackScheduled) {
       isCallbackScheduled = true;
+      startRequestCallbackTimer();
       scheduleDeferredCallback(performAsyncWork);
     }
   }
@@ -1425,8 +1429,14 @@ export default function<T, P, I, TI, PI, C, CC, CX, PL>(
     deadline = dl;
 
     // Keep working on roots until there's no more work, or until the we reach
-    // the deadlne.
+    // the deadline.
     findHighestPriorityRoot();
+
+    if (enableUserTimingAPI && deadline !== null) {
+      const didExpire = nextFlushedExpirationTime < recalculateCurrentTime();
+      stopRequestCallbackTimer(didExpire);
+    }
+
     while (
       nextFlushedRoot !== null &&
       nextFlushedExpirationTime !== NoWork &&
@@ -1449,6 +1459,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);
     }
 

packages/react-reconciler/src/__tests__/ReactIncrementalPerf-test.js

@@ -20,6 +20,7 @@ describe('ReactDebugFiberPerf', () => {
   let activeMeasure;
   let knownMarks;
   let knownMeasures;
+  let comments;
 
   function resetFlamechart() {
     root = {
@@ -35,12 +36,11 @@ describe('ReactDebugFiberPerf', () => {
     activeMeasure = root;
     knownMarks = new Set();
     knownMeasures = new Set();
+    comments = [];
   }
 
   function addComment(comment) {
-    activeMeasure.children.push(
-      `${'  '.repeat(activeMeasure.indent + 1)}// ${comment}`,
-    );
+    comments.push(comment);
   }
 
   function getFlameChart() {
@@ -67,9 +67,11 @@ describe('ReactDebugFiberPerf', () => {
           // Will be assigned on measure() call:
           label: null,
           parent: activeMeasure,
+          comments,
           toString() {
             return (
               [
+                ...this.comments.map(c => '  '.repeat(this.indent) + '// ' + c),
                 '  '.repeat(this.indent) + this.label,
                 ...this.children.map(c => c.toString()),
               ].join('\n') +
@@ -78,6 +80,7 @@ describe('ReactDebugFiberPerf', () => {
             );
           },
         };
+        comments = [];
         // Step one level deeper
         activeMeasure.children.push(measure);
         activeMeasure = measure;
@@ -546,4 +549,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();
+  });
 });