Update user timing to record the timeout deadline with 'waiting' even…

…ts (#12479)

* Update user timing to record the timeout deadline with 'waiting' events

**what is the change?:**
When we are processing work during reconciliation, we have a "timeout"
deadline to finish the work. It's a safety measure that forces things to
finish up synchronously if they are taking too long.

The "timeout" is different depending on the type of interaction which
triggered the reconciliation. We currently have a shorter "timeout" for
"interactive updates", meaning we will try to finish work faster if the
reconciliation was triggered by a click or other user interaction.

For collecting more data in our logs we want to differentiate the
'waiting for async callback...' events based on the "timeout" so I'm
adding that to the logging.

One interesting note - in one of the snapshot tests the "timeout" was
super high. Going to look into that.

**why make this change?:**
Right now we are debugging cases where an interaction triggers a
reconciliation and the "waiting for async callback...' events are too
long, getting blocked because the main thread is too busy. We are
keeping logs of these user timing events and want to filter to focus on
the reconciliation triggered by interaction.

**test plan:**
Manually tested and also updated snapshot tests.

(Flarnie will insert a screenshot)

* Improve wording of message

* ran prettier

packages/react-reconciler/src/ReactDebugFiberPerf.js

@@ -248,13 +248,18 @@ export function startRequestCallbackTimer(): void {
   }
 }
 
-export function stopRequestCallbackTimer(didExpire: boolean): void {
+export function stopRequestCallbackTimer(
+  didExpire: boolean,
+  expirationTime: number,
+): 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... will force flush in ${
+          expirationTime
+        } ms)`,
         '(Waiting for async callback...)',
         warning,
       );

packages/react-reconciler/src/ReactFiberScheduler.js

@@ -1448,7 +1448,8 @@ export default function<T, P, I, TI, HI, PI, C, CC, CX, PL>(
 
     if (enableUserTimingAPI && deadline !== null) {
       const didExpire = nextFlushedExpirationTime < recalculateCurrentTime();
-      stopRequestCallbackTimer(didExpire);
+      const timeout = expirationTimeToMs(nextFlushedExpirationTime);
+      stopRequestCallbackTimer(didExpire, timeout);
     }
 
     if (isAsync) {

packages/react-reconciler/src/__tests__/__snapshots__/ReactIncrementalPerf-test.internal.js.snap

@@ -1,7 +1,7 @@
 // Jest Snapshot v1, https://goo.gl/fbAQLP
 
 exports[`ReactDebugFiberPerf captures all lifecycles 1`] = `
-"⚛ (Waiting for async callback...)
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 // Mount
 ⚛ (React Tree Reconciliation)
@@ -15,7 +15,7 @@ exports[`ReactDebugFiberPerf captures all lifecycles 1`] = `
   ⚛ (Calling Lifecycle Methods: 1 Total)
     ⚛ AllLifecycles.componentDidMount
 
-⚛ (Waiting for async callback...)
+⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 // Update
 ⚛ (React Tree Reconciliation)
@@ -31,7 +31,7 @@ exports[`ReactDebugFiberPerf captures all lifecycles 1`] = `
   ⚛ (Calling Lifecycle Methods: 2 Total)
     ⚛ AllLifecycles.componentDidUpdate
 
-⚛ (Waiting for async callback...)
+⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 // Unmount
 ⚛ (React Tree Reconciliation)
@@ -45,7 +45,7 @@ exports[`ReactDebugFiberPerf captures all lifecycles 1`] = `
 `;
 
 exports[`ReactDebugFiberPerf deduplicates lifecycle names during commit to reduce overhead 1`] = `
-"⚛ (Waiting for async callback...)
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 // The commit phase should mention A and B just once
 ⚛ (React Tree Reconciliation)
@@ -62,7 +62,7 @@ exports[`ReactDebugFiberPerf deduplicates lifecycle names during commit to reduc
     ⚛ A.componentDidUpdate
     ⚛ B.componentDidUpdate
 
-⚛ (Waiting for async callback...)
+⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 // Because of deduplication, we don't know B was cascading,
 // but we should still see the warning for the commit phase.
@@ -112,7 +112,7 @@ exports[`ReactDebugFiberPerf does not schedule an extra callback if setState is
 `;
 
 exports[`ReactDebugFiberPerf does not treat setState from cWM or cWRP as cascading 1`] = `
-"⚛ (Waiting for async callback...)
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 // Should not print a warning
 ⚛ (React Tree Reconciliation)
@@ -125,7 +125,7 @@ exports[`ReactDebugFiberPerf does not treat setState from cWM or cWRP as cascadi
   ⚛ (Committing Host Effects: 1 Total)
   ⚛ (Calling Lifecycle Methods: 0 Total)
 
-⚛ (Waiting for async callback...)
+⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 // Should not print a warning
 ⚛ (React Tree Reconciliation)
@@ -141,7 +141,7 @@ exports[`ReactDebugFiberPerf does not treat setState from cWM or cWRP as cascadi
 `;
 
 exports[`ReactDebugFiberPerf measures a simple reconciliation 1`] = `
-"⚛ (Waiting for async callback...)
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 // Mount
 ⚛ (React Tree Reconciliation)
@@ -153,7 +153,7 @@ exports[`ReactDebugFiberPerf measures a simple reconciliation 1`] = `
   ⚛ (Committing Host Effects: 1 Total)
   ⚛ (Calling Lifecycle Methods: 0 Total)
 
-⚛ (Waiting for async callback...)
+⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 // Update
 ⚛ (React Tree Reconciliation)
@@ -165,7 +165,7 @@ exports[`ReactDebugFiberPerf measures a simple reconciliation 1`] = `
   ⚛ (Committing Host Effects: 2 Total)
   ⚛ (Calling Lifecycle Methods: 2 Total)
 
-⚛ (Waiting for async callback...)
+⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 // Unmount
 ⚛ (React Tree Reconciliation)
@@ -178,22 +178,22 @@ exports[`ReactDebugFiberPerf measures a simple reconciliation 1`] = `
 `;
 
 exports[`ReactDebugFiberPerf measures deferred work in chunks 1`] = `
-"⚛ (Waiting for async callback...)
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 // Start mounting Parent and A
 ⚛ (React Tree Reconciliation)
   ⚛ Parent [mount]
     ⚛ A [mount]
       ⚛ Child [mount]
 
-⚛ (Waiting for async callback...)
+⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 // Mount B just a little (but not enough to memoize)
 ⚛ (React Tree Reconciliation)
   ⚛ Parent [mount]
     ⚛ B [mount]
 
-⚛ (Waiting for async callback...)
+⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 // Complete B and Parent
 ⚛ (React Tree Reconciliation)
@@ -218,7 +218,7 @@ exports[`ReactDebugFiberPerf measures deprioritized work 1`] = `
   ⚛ (Committing Host Effects: 1 Total)
   ⚛ (Calling Lifecycle Methods: 0 Total)
 
-⚛ (Waiting for async callback...)
+⚛ (Waiting for async callback... will force flush in 10737418210 ms)
 
 // Flush the child
 ⚛ (React Tree Reconciliation)
@@ -232,7 +232,7 @@ exports[`ReactDebugFiberPerf measures deprioritized work 1`] = `
 `;
 
 exports[`ReactDebugFiberPerf recovers from caught errors 1`] = `
-"⚛ (Waiting for async callback...)
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 // Stop on Baddie and restart from Boundary
 ⚛ (React Tree Reconciliation)
@@ -262,7 +262,7 @@ exports[`ReactDebugFiberPerf recovers from caught errors 1`] = `
 `;
 
 exports[`ReactDebugFiberPerf recovers from fatal errors 1`] = `
-"⚛ (Waiting for async callback...)
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 // Will fatal
 ⚛ (React Tree Reconciliation)
@@ -276,7 +276,7 @@ exports[`ReactDebugFiberPerf recovers from fatal errors 1`] = `
   ⚛ (Committing Host Effects: 1 Total)
   ⚛ (Calling Lifecycle Methods: 0 Total)
 
-⚛ (Waiting for async callback...)
+⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 // Will reconcile from a clean state
 ⚛ (React Tree Reconciliation)
@@ -291,7 +291,7 @@ exports[`ReactDebugFiberPerf recovers from fatal errors 1`] = `
 `;
 
 exports[`ReactDebugFiberPerf skips parents during setState 1`] = `
-"⚛ (Waiting for async callback...)
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 // Should include just A and B, no Parents
 ⚛ (React Tree Reconciliation)
@@ -306,7 +306,7 @@ exports[`ReactDebugFiberPerf skips parents during setState 1`] = `
 `;
 
 exports[`ReactDebugFiberPerf supports portals 1`] = `
-"⚛ (Waiting for async callback...)
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 ⚛ (React Tree Reconciliation)
   ⚛ Parent [mount]
@@ -320,7 +320,7 @@ exports[`ReactDebugFiberPerf supports portals 1`] = `
 `;
 
 exports[`ReactDebugFiberPerf supports returns 1`] = `
-"⚛ (Waiting for async callback...)
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 ⚛ (React Tree Reconciliation)
   ⚛ App [mount]
@@ -339,12 +339,12 @@ exports[`ReactDebugFiberPerf supports returns 1`] = `
 `;
 
 exports[`ReactDebugFiberPerf warns if an in-progress update is interrupted 1`] = `
-"⚛ (Waiting for async callback...)
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 ⚛ (React Tree Reconciliation)
   ⚛ Foo [mount]
 
-⚛ (Waiting for async callback...)
+⚛ (Waiting for async callback... will force flush in 5230 ms)
   ⛔ (React Tree Reconciliation) Warning: A top-level update interrupted the previous render
     ⚛ Foo [mount]
   ⚛ (Committing Changes)
@@ -362,7 +362,7 @@ exports[`ReactDebugFiberPerf warns if an in-progress update is interrupted 1`] =
 `;
 
 exports[`ReactDebugFiberPerf warns if async work expires (starvation) 1`] = `
-"⛔ (Waiting for async callback...) Warning: React was blocked by main thread
+"⛔ (Waiting for async callback... will force flush in 5230 ms) Warning: React was blocked by main thread
 
 ⚛ (React Tree Reconciliation)
   ⚛ Foo [mount]
@@ -375,7 +375,7 @@ exports[`ReactDebugFiberPerf warns if async work expires (starvation) 1`] = `
 `;
 
 exports[`ReactDebugFiberPerf warns on cascading renders from setState 1`] = `
-"⚛ (Waiting for async callback...)
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 // Should print a warning
 ⚛ (React Tree Reconciliation)
@@ -399,7 +399,7 @@ exports[`ReactDebugFiberPerf warns on cascading renders from setState 1`] = `
 `;
 
 exports[`ReactDebugFiberPerf warns on cascading renders from top-level render 1`] = `
-"⚛ (Waiting for async callback...)
+"⚛ (Waiting for async callback... will force flush in 5230 ms)
 
 // Rendering the first root
 ⚛ (React Tree Reconciliation)