[Flight] Emit timestamps only in forwards advancing time in debug info

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 = {