[Flight] Emit timestamps only in forwards advancing time in debug info (#33482)

Previously you weren't guaranteed to have only advancing time entries,
you could jump back in time, but now it omits unnecessary duplicates and
clamps automatically if you emit a previous time entry to enforce
forwards order only.

The reason I didn't do this originally is because `await` can jump in
the order because we're trying to encode a graph into a flat timeline
for simplicity of the protocol and consumers.

```js
async function a() {
  await fetch1();
  await fetch2();
}

async function b() {
  await fetch3();
}

async function foo() {
  const p = a();
  await b();
  return p;
}
```

This can effectively create two parallel sequences:

```
--1.................----2.......--
------3......---------------------
```

This can now be flattened to either:

```
--1.................3---2.......--
```

Or:

```
------3......1......----2.......--
```

Depending on which one we visit first. Regardless, information is lost.

I'd say that the second one is worse encoding of this scenario because
it pretends that we weren't waiting for part of the timespan that we
were. To solve this I think we should probably make `emitAsyncSequence`
create a temporary flat list and then sort it by start time before
emitting.

Although we weren't actually blocked since there was some CPU time that
was able to proceed to get to 3. So maybe the second one is actually
better. If we wanted that consistently we'd have to figure out what the
intersection was.

---------

Co-authored-by: Hendrik Liebau <[email protected]>

Author: sebmarkbage

fixtures/flight/src/App.js

@@ -37,8 +37,19 @@ async function delay(text, ms) {
   return new Promise(resolve => setTimeout(() => resolve(text), ms));
 }
 
+async function delayTwice() {
+  await delay('', 20);
+  await delay('', 10);
+}
+
+async function delayTrice() {
+  const p = delayTwice();
+  await delay('', 40);
+  return p;
+}
+
 async function Bar({children}) {
-  await delay('deferred text', 10);
+  await delayTrice();
   return <div>{children}</div>;
 }
 

packages/react-client/src/ReactFlightClient.js

@@ -2902,6 +2902,46 @@ function resolveTypedArray(
   resolveBuffer(response, id, view);
 }
 
+function logComponentInfo(
+  response: Response,
+  root: SomeChunk<any>,
+  componentInfo: ReactComponentInfo,
+  trackIdx: number,
+  startTime: number,
+  componentEndTime: number,
+  childrenEndTime: number,
+  isLastComponent: boolean,
+): void {
+  // $FlowFixMe: Refined.
+  if (
+    isLastComponent &&
+    root.status === ERRORED &&
+    root.reason !== response._closedReason
+  ) {
+    // If this is the last component to render before this chunk rejected, then conceptually
+    // this component errored. If this was a cancellation then it wasn't this component that
+    // errored.
+    logComponentErrored(
+      componentInfo,
+      trackIdx,
+      startTime,
+      componentEndTime,
+      childrenEndTime,
+      response._rootEnvironmentName,
+      root.reason,
+    );
+  } else {
+    logComponentRender(
+      componentInfo,
+      trackIdx,
+      startTime,
+      componentEndTime,
+      childrenEndTime,
+      response._rootEnvironmentName,
+    );
+  }
+}
+
 function flushComponentPerformance(
   response: Response,
   root: SomeChunk<any>,
@@ -2957,28 +2997,28 @@ function flushComponentPerformance(
   // in parallel with the previous.
   const debugInfo = __DEV__ && root._debugInfo;
   if (debugInfo) {
-    for (let i = 1; i < debugInfo.length; i++) {
+    let startTime = 0;
+    for (let i = 0; i < debugInfo.length; i++) {
       const info = debugInfo[i];
+      if (typeof info.time === 'number') {
+        startTime = info.time;
+      }
       if (typeof info.name === 'string') {
-        // $FlowFixMe: Refined.
-        const startTimeInfo = debugInfo[i - 1];
-        if (typeof startTimeInfo.time === 'number') {
-          const startTime = startTimeInfo.time;
-          if (startTime < trackTime) {
-            // The start time of this component is before the end time of the previous
-            // component on this track so we need to bump the next one to a parallel track.
-            trackIdx++;
-          }
-          trackTime = startTime;
-          break;
+        if (startTime < trackTime) {
+          // The start time of this component is before the end time of the previous
+          // component on this track so we need to bump the next one to a parallel track.
+          trackIdx++;
         }
+        trackTime = startTime;
+        break;
       }
     }
     for (let i = debugInfo.length - 1; i >= 0; i--) {
       const info = debugInfo[i];
       if (typeof info.time === 'number') {
         if (info.time > parentEndTime) {
           parentEndTime = info.time;
+          break; // We assume the highest number is at the end.
         }
       }
     }
@@ -3006,85 +3046,72 @@ function flushComponentPerformance(
     }
     childTrackIdx = childResult.track;
     const childEndTime = childResult.endTime;
-    childTrackTime = childEndTime;
+    if (childEndTime > childTrackTime) {
+      childTrackTime = childEndTime;
+    }
     if (childEndTime > childrenEndTime) {
       childrenEndTime = childEndTime;
     }
   }
 
   if (debugInfo) {
-    let endTime = 0;
+    // Write debug info in reverse order (just like stack traces).
+    let componentEndTime = 0;
     let isLastComponent = true;
+    let endTime = -1;
+    let endTimeIdx = -1;
     for (let i = debugInfo.length - 1; i >= 0; i--) {
       const info = debugInfo[i];
-      if (typeof info.time === 'number') {
-        if (info.time > childrenEndTime) {
-          childrenEndTime = info.time;
-        }
-        if (endTime === 0) {
-          // Last timestamp is the end of the last component.
-          endTime = info.time;
-        }
+      if (typeof info.time !== 'number') {
+        continue;
       }
-      if (typeof info.name === 'string' && i > 0) {
-        // $FlowFixMe: Refined.
-        const componentInfo: ReactComponentInfo = info;
-        const startTimeInfo = debugInfo[i - 1];
-        if (typeof startTimeInfo.time === 'number') {
-          const startTime = startTimeInfo.time;
-          if (
-            isLastComponent &&
-            root.status === ERRORED &&
-            root.reason !== response._closedReason
-          ) {
-            // If this is the last component to render before this chunk rejected, then conceptually
-            // this component errored. If this was a cancellation then it wasn't this component that
-            // errored.
-            logComponentErrored(
+      if (componentEndTime === 0) {
+        // Last timestamp is the end of the last component.
+        componentEndTime = info.time;
+      }
+      const time = info.time;
+      if (endTimeIdx > -1) {
+        // Now that we know the start and end time, we can emit the entries between.
+        for (let j = endTimeIdx - 1; j > i; j--) {
+          const candidateInfo = debugInfo[j];
+          if (typeof candidateInfo.name === 'string') {
+            if (componentEndTime > childrenEndTime) {
+              childrenEndTime = componentEndTime;
+            }
+            // $FlowFixMe: Refined.
+            const componentInfo: ReactComponentInfo = candidateInfo;
+            logComponentInfo(
+              response,
+              root,
               componentInfo,
               trackIdx,
-              startTime,
-              endTime,
+              time,
+              componentEndTime,
               childrenEndTime,
-              response._rootEnvironmentName,
-              root.reason,
+              isLastComponent,
             );
-          } else {
-            logComponentRender(
-              componentInfo,
+            componentEndTime = time; // The end time of previous component is the start time of the next.
+            // Track the root most component of the result for deduping logging.
+            result.component = componentInfo;
+            isLastComponent = false;
+          } else if (candidateInfo.awaited) {
+            if (endTime > childrenEndTime) {
+              childrenEndTime = endTime;
+            }
+            // $FlowFixMe: Refined.
+            const asyncInfo: ReactAsyncInfo = candidateInfo;
+            logComponentAwait(
+              asyncInfo,
               trackIdx,
-              startTime,
+              time,
               endTime,
-              childrenEndTime,
               response._rootEnvironmentName,
             );
           }
-          // Track the root most component of the result for deduping logging.
-          result.component = componentInfo;
-          // Set the end time of the previous component to the start of the previous.
-          endTime = startTime;
-        }
-        isLastComponent = false;
-      } else if (info.awaited && i > 0 && i < debugInfo.length - 2) {
-        // $FlowFixMe: Refined.
-        const asyncInfo: ReactAsyncInfo = info;
-        const startTimeInfo = debugInfo[i - 1];
-        const endTimeInfo = debugInfo[i + 1];
-        if (
-          typeof startTimeInfo.time === 'number' &&
-          typeof endTimeInfo.time === 'number'
-        ) {
-          const awaitStartTime = startTimeInfo.time;
-          const awaitEndTime = endTimeInfo.time;
-          logComponentAwait(
-            asyncInfo,
-            trackIdx,
-            awaitStartTime,
-            awaitEndTime,
-            response._rootEnvironmentName,
-          );
         }
       }
+      endTime = time; // The end time of the next entry is this time.
+      endTimeIdx = i;
     }
   }
   result.endTime = childrenEndTime;

packages/react-server/src/ReactFlightAsyncSequence.js

@@ -38,7 +38,7 @@ export type PromiseNode = {
   start: number, // start time when the Promise was created
   end: number, // end time when the Promise was resolved.
   awaited: null | AsyncSequence, // the thing that ended up resolving this promise
-  previous: null, // where we created the promise is not interesting since creating it doesn't mean waiting.
+  previous: null | AsyncSequence, // represents what the last return of an async function depended on before returning
 };
 
 export type AwaitNode = {