[Flight] Log Server Component into Performance Track (#31729)

sebmarkbage · web-flow · commit 6928bf2f7c73 · 2024-12-12T14:03:18.000-05:00
<img width="966" alt="Screenshot 2024-12-10 at 10 49 19 PM" src="https://github.com/user-attachments/assets/27a21bdf-86b9-4203-893b-89523e698138"> This emits a tree view visualization of the timing information for each Server Component provided in the RSC payload. The unique thing about this visualization is that the end time of each Server Component spans the end of the last child. Now what is conceptually a blocking child is kind of undefined in RSC. E.g. if you're not using a Promise on the client, or if it is wrapped in Suspense, is it really blocking the parent? Here I reconstruct parent-child relationship by which chunks reference other chunks. A child can belong to more than one parent like when we dedupe the result of a Server Component. Then I wait until the whole RSC payload has streamed in, and then I traverse the tree collecting the end time from children as I go and emit the `performance.measure()` calls on the way up. There's more work for this visualization in follow ups but this is the basics. For example, since the Server Component time span includes async work it's possible for siblings to execute their span in parallel (Foo and Bar in the screenshot are parallel siblings). To deal with this we need to spawn parallel work into separate tracks. Each one can be deep due to large trees. This can makes this type of visualization unwieldy when you have a lot of parallelism. Therefore I also plan another flatter Timeline visualization in a follow up.
diff --git a/fixtures/flight/src/App.js b/fixtures/flight/src/App.js
@@ -20,12 +20,26 @@ import {like, greet, increment} from './actions.js';
 import {getServerState} from './ServerState.js';
 
 const promisedText = new Promise(resolve =>
-  setTimeout(() => resolve('deferred text'), 100)
+  setTimeout(() => resolve('deferred text'), 50)
 );
 
+function Foo({children}) {
+  return <div>{children}</div>;
+}
+
+function Bar({children}) {
+  return <div>{children}</div>;
+}
+
+async function ServerComponent() {
+  await new Promise(resolve => setTimeout(() => resolve('deferred text'), 50));
+}
+
 export default async function App({prerender}) {
   const res = await fetch('http://localhost:3001/todos');
   const todos = await res.json();
+
+  const dedupedChild = <ServerComponent />;
   return (
     <html lang="en">
       <head>
@@ -66,6 +80,8 @@ export default async function App({prerender}) {
           </div>
           <Client />
           <Note />
+          <Foo>{dedupedChild}</Foo>
+          <Bar>{dedupedChild}</Bar>
         </Container>
       </body>
     </html>
diff --git a/packages/react-client/src/ReactFlightClient.js b/packages/react-client/src/ReactFlightClient.js
@@ -71,6 +71,8 @@ import {createBoundServerReference} from './ReactFlightReplyClient';
 
 import {readTemporaryReference} from './ReactFlightTemporaryReferences';
 
+import {logComponentRender} from './ReactFlightPerformanceTrack';
+
 import {
   REACT_LAZY_TYPE,
   REACT_ELEMENT_TYPE,
@@ -124,6 +126,10 @@ export type JSONValue =
   | {+[key: string]: JSONValue}
   | $ReadOnlyArray<JSONValue>;
 
+type ProfilingResult = {
+  endTime: number,
+};
+
 const ROW_ID = 0;
 const ROW_TAG = 1;
 const ROW_LENGTH = 2;
@@ -144,39 +150,44 @@ type PendingChunk<T> = {
   value: null | Array<(T) => mixed>,
   reason: null | Array<(mixed) => mixed>,
   _response: Response,
-  _debugInfo?: null | ReactDebugInfo,
+  _children: Array<SomeChunk<any>> | ProfilingResult, // Profiling-only
+  _debugInfo?: null | ReactDebugInfo, // DEV-only
   then(resolve: (T) => mixed, reject?: (mixed) => mixed): void,
 };
 type BlockedChunk<T> = {
   status: 'blocked',
   value: null | Array<(T) => mixed>,
   reason: null | Array<(mixed) => mixed>,
   _response: Response,
-  _debugInfo?: null | ReactDebugInfo,
+  _children: Array<SomeChunk<any>> | ProfilingResult, // Profiling-only
+  _debugInfo?: null | ReactDebugInfo, // DEV-only
   then(resolve: (T) => mixed, reject?: (mixed) => mixed): void,
 };
 type ResolvedModelChunk<T> = {
   status: 'resolved_model',
   value: UninitializedModel,
   reason: null,
   _response: Response,
-  _debugInfo?: null | ReactDebugInfo,
+  _children: Array<SomeChunk<any>> | ProfilingResult, // Profiling-only
+  _debugInfo?: null | ReactDebugInfo, // DEV-only
   then(resolve: (T) => mixed, reject?: (mixed) => mixed): void,
 };
 type ResolvedModuleChunk<T> = {
   status: 'resolved_module',
   value: ClientReference<T>,
   reason: null,
   _response: Response,
-  _debugInfo?: null | ReactDebugInfo,
+  _children: Array<SomeChunk<any>> | ProfilingResult, // Profiling-only
+  _debugInfo?: null | ReactDebugInfo, // DEV-only
   then(resolve: (T) => mixed, reject?: (mixed) => mixed): void,
 };
 type InitializedChunk<T> = {
   status: 'fulfilled',
   value: T,
   reason: null | FlightStreamController,
   _response: Response,
-  _debugInfo?: null | ReactDebugInfo,
+  _children: Array<SomeChunk<any>> | ProfilingResult, // Profiling-only
+  _debugInfo?: null | ReactDebugInfo, // DEV-only
   then(resolve: (T) => mixed, reject?: (mixed) => mixed): void,
 };
 type InitializedStreamChunk<
@@ -186,15 +197,17 @@ type InitializedStreamChunk<
   value: T,
   reason: FlightStreamController,
   _response: Response,
-  _debugInfo?: null | ReactDebugInfo,
+  _children: Array<SomeChunk<any>> | ProfilingResult, // Profiling-only
+  _debugInfo?: null | ReactDebugInfo, // DEV-only
   then(resolve: (ReadableStream) => mixed, reject?: (mixed) => mixed): void,
 };
 type ErroredChunk<T> = {
   status: 'rejected',
   value: null,
   reason: mixed,
   _response: Response,
-  _debugInfo?: null | ReactDebugInfo,
+  _children: Array<SomeChunk<any>> | ProfilingResult, // Profiling-only
+  _debugInfo?: null | ReactDebugInfo, // DEV-only
   then(resolve: (T) => mixed, reject?: (mixed) => mixed): void,
 };
 type SomeChunk<T> =
@@ -216,6 +229,9 @@ function ReactPromise(
   this.value = value;
   this.reason = reason;
   this._response = response;
+  if (enableProfilerTimer && enableComponentPerformanceTrack) {
+    this._children = [];
+  }
   if (__DEV__) {
     this._debugInfo = null;
   }
@@ -548,9 +564,11 @@ type InitializationHandler = {
   errored: boolean,
 };
 let initializingHandler: null | InitializationHandler = null;
+let initializingChunk: null | BlockedChunk<any> = null;
 
 function initializeModelChunk<T>(chunk: ResolvedModelChunk<T>): void {
   const prevHandler = initializingHandler;
+  const prevChunk = initializingChunk;
   initializingHandler = null;
 
   const resolvedModel = chunk.value;
@@ -563,6 +581,10 @@ function initializeModelChunk<T>(chunk: ResolvedModelChunk<T>): void {
   cyclicChunk.value = null;
   cyclicChunk.reason = null;
 
+  if (enableProfilerTimer && enableComponentPerformanceTrack) {
+    initializingChunk = cyclicChunk;
+  }
+
   try {
     const value: T = parseModel(chunk._response, resolvedModel);
     // Invoke any listeners added while resolving this model. I.e. cyclic
@@ -595,6 +617,9 @@ function initializeModelChunk<T>(chunk: ResolvedModelChunk<T>): void {
     erroredChunk.reason = error;
   } finally {
     initializingHandler = prevHandler;
+    if (enableProfilerTimer && enableComponentPerformanceTrack) {
+      initializingChunk = prevChunk;
+    }
   }
 }
 
@@ -622,6 +647,9 @@ export function reportGlobalError(response: Response, error: Error): void {
       triggerErrorOnChunk(chunk, error);
     }
   });
+  if (enableProfilerTimer && enableComponentPerformanceTrack) {
+    flushComponentPerformance(getChunk(response, 0));
+  }
 }
 
 function nullRefGetter() {
@@ -1210,6 +1238,11 @@ function getOutlinedModel<T>(
   const path = reference.split(':');
   const id = parseInt(path[0], 16);
   const chunk = getChunk(response, id);
+  if (enableProfilerTimer && enableComponentPerformanceTrack) {
+    if (initializingChunk !== null && isArray(initializingChunk._children)) {
+      initializingChunk._children.push(chunk);
+    }
+  }
   switch (chunk.status) {
     case RESOLVED_MODEL:
       initializeModelChunk(chunk);
@@ -1359,6 +1392,14 @@ function parseModelString(
         // Lazy node
         const id = parseInt(value.slice(2), 16);
         const chunk = getChunk(response, id);
+        if (enableProfilerTimer && enableComponentPerformanceTrack) {
+          if (
+            initializingChunk !== null &&
+            isArray(initializingChunk._children)
+          ) {
+            initializingChunk._children.push(chunk);
+          }
+        }
         // We create a React.lazy wrapper around any lazy values.
         // When passed into React, we'll know how to suspend on this.
         return createLazyChunkWrapper(chunk);
@@ -1371,6 +1412,14 @@ function parseModelString(
         }
         const id = parseInt(value.slice(2), 16);
         const chunk = getChunk(response, id);
+        if (enableProfilerTimer && enableComponentPerformanceTrack) {
+          if (
+            initializingChunk !== null &&
+            isArray(initializingChunk._children)
+          ) {
+            initializingChunk._children.push(chunk);
+          }
+        }
         return chunk;
       }
       case 'S': {
@@ -2704,6 +2753,67 @@ function resolveTypedArray(
   resolveBuffer(response, id, view);
 }
 
+function flushComponentPerformance(root: SomeChunk<any>): number {
+  if (!enableProfilerTimer || !enableComponentPerformanceTrack) {
+    return 0;
+  }
+  // Write performance.measure() entries for Server Components in tree order.
+  // This must be done at the end to collect the end time from the whole tree.
+  if (!isArray(root._children)) {
+    // We have already written this chunk. If this was a cycle, then this will
+    // be -Infinity and it won't contribute to the parent end time.
+    // If this was already emitted by another sibling then we reused the same
+    // chunk in two places. We should extend the current end time as if it was
+    // rendered as part of this tree.
+    const previousResult: ProfilingResult = root._children;
+    return previousResult.endTime;
+  }
+  const children = root._children;
+  if (root.status === RESOLVED_MODEL) {
+    // If the model is not initialized by now, do that now so we can find its
+    // children. This part is a little sketchy since it significantly changes
+    // the performance characteristics of the app by profiling.
+    initializeModelChunk(root);
+  }
+  const result: ProfilingResult = {endTime: -Infinity};
+  root._children = result;
+  let childrenEndTime = -Infinity;
+  for (let i = 0; i < children.length; i++) {
+    const childEndTime = flushComponentPerformance(children[i]);
+    if (childEndTime > childrenEndTime) {
+      childrenEndTime = childEndTime;
+    }
+  }
+  const debugInfo = root._debugInfo;
+  if (debugInfo) {
+    let endTime = 0;
+    for (let i = debugInfo.length - 1; i >= 0; i--) {
+      const info = debugInfo[i];
+      if (typeof info.time === 'number') {
+        endTime = info.time;
+        if (endTime > childrenEndTime) {
+          childrenEndTime = endTime;
+        }
+      }
+      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;
+          logComponentRender(
+            componentInfo,
+            startTime,
+            endTime,
+            childrenEndTime,
+          );
+        }
+      }
+    }
+  }
+  return (result.endTime = childrenEndTime);
+}
+
 function processFullBinaryRow(
   response: Response,
   id: number,
diff --git a/packages/react-client/src/ReactFlightPerformanceTrack.js b/packages/react-client/src/ReactFlightPerformanceTrack.js
@@ -0,0 +1,56 @@
+/**
+ * Copyright (c) Meta Platforms, Inc. and affiliates.
+ *
+ * This source code is licensed under the MIT license found in the
+ * LICENSE file in the root directory of this source tree.
+ *
+ * @flow
+ */
+
+import type {ReactComponentInfo} from 'shared/ReactTypes';
+
+import {enableProfilerTimer} from 'shared/ReactFeatureFlags';
+
+const supportsUserTiming =
+  enableProfilerTimer &&
+  typeof performance !== 'undefined' &&
+  // $FlowFixMe[method-unbinding]
+  typeof performance.measure === 'function';
+
+const COMPONENTS_TRACK = 'Server Components ⚛';
+
+// Reused to avoid thrashing the GC.
+const reusableComponentDevToolDetails = {
+  color: 'primary',
+  track: COMPONENTS_TRACK,
+};
+const reusableComponentOptions = {
+  start: -0,
+  end: -0,
+  detail: {
+    devtools: reusableComponentDevToolDetails,
+  },
+};
+
+export function logComponentRender(
+  componentInfo: ReactComponentInfo,
+  startTime: number,
+  endTime: number,
+  childrenEndTime: number,
+): void {
+  if (supportsUserTiming && childrenEndTime >= 0) {
+    const name = componentInfo.name;
+    const selfTime = endTime - startTime;
+    reusableComponentDevToolDetails.color =
+      selfTime < 0.5
+        ? 'primary-light'
+        : selfTime < 50
+          ? 'primary'
+          : selfTime < 500
+            ? 'primary-dark'
+            : 'error';
+    reusableComponentOptions.start = startTime < 0 ? 0 : startTime;
+    reusableComponentOptions.end = childrenEndTime;
+    performance.measure(name, reusableComponentOptions);
+  }
+}
