[Flight] Track Timing Information (#31716)

Stacked on #31715. This adds profiling data for Server Components to the RSC stream (but doesn't yet use it for anything). This is on behind `enableProfilerTimer` which is on for Dev and Profiling builds. However, for now there's no Profiling build of Flight so in practice only in DEV. It's gated on `enableComponentPerformanceTrack` which is experimental only for now. We first emit a timeOrigin in the beginning of the stream. This provides us a relative time to emit timestamps against for cross environment transfer so that we can log it in terms of absolute times. Using this as a separate field allows the actual relative timestamps to be a bit more compact representation and preserves floating point precision. We emit a timestamp before emitting a Server Component which represents the start time of the Server Component. The end time is either when the next Server Component starts or when we finish the task. We omit the end time for simple tasks that are outlined without Server Components. By encoding this as part of the debugInfo stream, this information can be forwarded between Server to Server RSC.
2026-09-24 17:02:27 +00:00 · 2024-12-10 20:46:19 -05:00
parent 50d0d1ceb4
commit f410fdfef0
4 changed files with 209 additions and 38 deletions
@@ -48,6 +48,8 @@ import {
  enableFlightReadableStream,
  enableOwnerStacks,
  enableServerComponentLogs,
+  enableProfilerTimer,
+  enableComponentPerformanceTrack,
 } from 'shared/ReactFeatureFlags';

 import {
@@ -286,6 +288,7 @@ export type Response = {
  _rowLength: number, // remaining bytes in the row. 0 indicates that we're looking for a newline.
  _buffer: Array<Uint8Array>, // chunks received so far as part of this row
  _tempRefs: void | TemporaryReferenceSet, // the set temporary references can be resolved from
+  _timeOrigin: number, // Profiling-only
  _debugRootOwner?: null | ReactComponentInfo, // DEV-only
  _debugRootStack?: null | Error, // DEV-only
  _debugRootTask?: null | ConsoleTask, // DEV-only
@@ -1585,6 +1588,9 @@ function ResponseInstance(
  this._rowLength = 0;
  this._buffer = [];
  this._tempRefs = temporaryReferences;
+  if (enableProfilerTimer && enableComponentPerformanceTrack) {
+    this._timeOrigin = 0;
+  }
  if (__DEV__) {
    // TODO: The Flight Client can be used in a Client Environment too and we should really support
    // getting the owner there as well, but currently the owner of ReactComponentInfo is typed as only
@@ -2512,6 +2518,16 @@ function resolveDebugInfo(
      debugInfo;
    initializeFakeStack(response, componentInfoOrAsyncInfo);
  }
+  if (enableProfilerTimer && enableComponentPerformanceTrack) {
+    if (typeof debugInfo.time === 'number') {
+      // Adjust the time to the current environment's time space.
+      // Since this might be a deduped object, we clone it to avoid
+      // applying the adjustment twice.
+      debugInfo = {
+        time: debugInfo.time + response._timeOrigin,
+      };
+    }
+  }

  const chunk = getChunk(response, id);
  const chunkDebugInfo: ReactDebugInfo =
@@ -2792,6 +2808,19 @@ function processFullStringRow(
      resolveText(response, id, row);
      return;
    }
+    case 78 /* "N" */: {
+      if (enableProfilerTimer && enableComponentPerformanceTrack) {
+        // Track the time origin for future debug info. We track it relative
+        // to the current environment's time space.
+        const timeOrigin: number = +row;
+        response._timeOrigin =
+          timeOrigin -
+          // $FlowFixMe[prop-missing]
+          performance.timeOrigin;
+        return;
+      }
+      // Fallthrough to share the error with Debug and Console entries.
+    }
    case 68 /* "D" */: {
      if (__DEV__) {
        const chunk: ResolvedModelChunk<
@@ -125,6 +125,20 @@ let assertConsoleErrorDev;

 describe('ReactFlight', () => {
  beforeEach(() => {
+    // Mock performance.now for timing tests
+    let time = 10;
+    const now = jest.fn().mockImplementation(() => {
+      return time++;
+    });
+    Object.defineProperty(performance, 'timeOrigin', {
+      value: time,
+      configurable: true,
+    });
+    Object.defineProperty(performance, 'now', {
+      value: now,
+      configurable: true,
+    });
+
    jest.resetModules();
    jest.mock('react', () => require('react/react.react-server'));
    ReactServer = require('react');
@@ -274,6 +288,7 @@ describe('ReactFlight', () => {
    });
  });

+  // @gate !__DEV__ || enableComponentPerformanceTrack
  it('can render a Client Component using a module reference and render there', async () => {
    function UserClient(props) {
      return (
@@ -300,6 +315,7 @@ describe('ReactFlight', () => {
      expect(getDebugInfo(greeting)).toEqual(
        __DEV__
          ? [
+              {time: 11},
              {
                name: 'Greeting',
                env: 'Server',
@@ -313,6 +329,7 @@ describe('ReactFlight', () => {
                  lastName: 'Smith',
                },
              },
+              {time: 12},
            ]
          : undefined,
      );
@@ -322,6 +339,7 @@ describe('ReactFlight', () => {
    expect(ReactNoop).toMatchRenderedOutput(<span>Hello, Seb Smith</span>);
  });

+  // @gate !__DEV__ || enableComponentPerformanceTrack
  it('can render a shared forwardRef Component', async () => {
    const Greeting = React.forwardRef(function Greeting(
      {firstName, lastName},
@@ -343,6 +361,7 @@ describe('ReactFlight', () => {
      expect(getDebugInfo(promise)).toEqual(
        __DEV__
          ? [
+              {time: 11},
              {
                name: 'Greeting',
                env: 'Server',
@@ -356,6 +375,7 @@ describe('ReactFlight', () => {
                  lastName: 'Smith',
                },
              },
+              {time: 12},
            ]
          : undefined,
      );
@@ -2659,6 +2679,7 @@ describe('ReactFlight', () => {
    );
  });

+  // @gate !__DEV__ || enableComponentPerformanceTrack
  it('preserves debug info for server-to-server pass through', async () => {
    function ThirdPartyLazyComponent() {
      return <span>!</span>;
@@ -2705,6 +2726,7 @@ describe('ReactFlight', () => {
      expect(getDebugInfo(promise)).toEqual(
        __DEV__
          ? [
+              {time: 18},
              {
                name: 'ServerComponent',
                env: 'Server',
@@ -2717,15 +2739,18 @@ describe('ReactFlight', () => {
                  transport: expect.arrayContaining([]),
                },
              },
+              {time: 19},
            ]
          : undefined,
      );
      const result = await promise;
+
      const thirdPartyChildren = await result.props.children[1];
      // We expect the debug info to be transferred from the inner stream to the outer.
      expect(getDebugInfo(thirdPartyChildren[0])).toEqual(
        __DEV__
          ? [
+              {time: 13},
              {
                name: 'ThirdPartyComponent',
                env: 'third-party',
@@ -2736,12 +2761,15 @@ describe('ReactFlight', () => {
                  : undefined,
                props: {},
              },
+              {time: 14},
+              {time: 21}, // This last one is when the promise resolved into the first party.
            ]
          : undefined,
      );
      expect(getDebugInfo(thirdPartyChildren[1])).toEqual(
        __DEV__
          ? [
+              {time: 15},
              {
                name: 'ThirdPartyLazyComponent',
                env: 'third-party',
@@ -2752,12 +2780,14 @@ describe('ReactFlight', () => {
                  : undefined,
                props: {},
              },
+              {time: 16},
            ]
          : undefined,
      );
      expect(getDebugInfo(thirdPartyChildren[2])).toEqual(
        __DEV__
          ? [
+              {time: 11},
              {
                name: 'ThirdPartyFragmentComponent',
                env: 'third-party',
@@ -2768,6 +2798,7 @@ describe('ReactFlight', () => {
                  : undefined,
                props: {},
              },
+              {time: 12},
            ]
          : undefined,
      );
@@ -2833,6 +2864,7 @@ describe('ReactFlight', () => {
      expect(getDebugInfo(promise)).toEqual(
        __DEV__
          ? [
+              {time: 14},
              {
                name: 'ServerComponent',
                env: 'Server',
@@ -2845,6 +2877,7 @@ describe('ReactFlight', () => {
                  transport: expect.arrayContaining([]),
                },
              },
+              {time: 15},
            ]
          : undefined,
      );
@@ -2853,6 +2886,7 @@ describe('ReactFlight', () => {
      expect(getDebugInfo(thirdPartyFragment)).toEqual(
        __DEV__
          ? [
+              {time: 16},
              {
                name: 'Keyed',
                env: 'Server',
@@ -2865,6 +2899,7 @@ describe('ReactFlight', () => {
                  children: {},
                },
              },
+              {time: 17},
            ]
          : undefined,
      );
@@ -2872,6 +2907,7 @@ describe('ReactFlight', () => {
      expect(getDebugInfo(thirdPartyFragment.props.children)).toEqual(
        __DEV__
          ? [
+              {time: 11},
              {
                name: 'ThirdPartyAsyncIterableComponent',
                env: 'third-party',
@@ -2882,6 +2918,7 @@ describe('ReactFlight', () => {
                  : undefined,
                props: {},
              },
+              {time: 12},
            ]
          : undefined,
      );
@@ -3017,6 +3054,7 @@ describe('ReactFlight', () => {
    }
  });

+  // @gate !__DEV__ || enableComponentPerformanceTrack
  it('can change the environment name inside a component', async () => {
    let env = 'A';
    function Component(props) {
@@ -3041,6 +3079,7 @@ describe('ReactFlight', () => {
      expect(getDebugInfo(greeting)).toEqual(
        __DEV__
          ? [
+              {time: 11},
              {
                name: 'Component',
                env: 'A',
@@ -3054,6 +3093,7 @@ describe('ReactFlight', () => {
              {
                env: 'B',
              },
+              {time: 12},
            ]
          : undefined,
      );
@@ -3205,6 +3245,7 @@ describe('ReactFlight', () => {
    );
  });

+  // @gate !__DEV__ || enableComponentPerformanceTrack
  it('uses the server component debug info as the element owner in DEV', async () => {
    function Container({children}) {
      return children;
@@ -3244,7 +3285,9 @@ describe('ReactFlight', () => {
          },
        };
        expect(getDebugInfo(greeting)).toEqual([
+          {time: 11},
          greetInfo,
+          {time: 12},
          {
            name: 'Container',
            env: 'Server',
@@ -3262,10 +3305,11 @@ describe('ReactFlight', () => {
              }),
            },
          },
+          {time: 13},
        ]);
        // The owner that created the span was the outer server component.
        // We expect the debug info to be referentially equal to the owner.
-        expect(greeting._owner).toBe(greeting._debugInfo[0]);
+        expect(greeting._owner).toBe(greeting._debugInfo[1]);
      } else {
        expect(greeting._debugInfo).toBe(undefined);
        expect(greeting._owner).toBe(undefined);
@@ -3531,7 +3575,7 @@ describe('ReactFlight', () => {
    expect(caughtError.digest).toBe('digest("my-error")');
  });

-  // @gate __DEV__
+  // @gate __DEV__ && enableComponentPerformanceTrack
  it('can render deep but cut off JSX in debug info', async () => {
    function createDeepJSX(n) {
      if (n <= 0) {
@@ -3555,7 +3599,7 @@ describe('ReactFlight', () => {
    await act(async () => {
      const rootModel = await ReactNoopFlightClient.read(transport);
      const root = rootModel.root;
-      const children = root._debugInfo[0].props.children;
+      const children = root._debugInfo[1].props.children;
      expect(children.type).toBe('div');
      expect(children.props.children.type).toBe('div');
      ReactNoop.render(root);
@@ -3564,7 +3608,7 @@ describe('ReactFlight', () => {
    expect(ReactNoop).toMatchRenderedOutput(<div>not using props</div>);
  });

-  // @gate __DEV__
+  // @gate __DEV__ && enableComponentPerformanceTrack
  it('can render deep but cut off Map/Set in debug info', async () => {
    function createDeepMap(n) {
      if (n <= 0) {
@@ -3603,8 +3647,8 @@ describe('ReactFlight', () => {

    await act(async () => {
      const rootModel = await ReactNoopFlightClient.read(transport);
-      const set = rootModel.set._debugInfo[0].props.set;
-      const map = rootModel.map._debugInfo[0].props.map;
+      const set = rootModel.set._debugInfo[1].props.set;
+      const map = rootModel.map._debugInfo[1].props.map;
      expect(set instanceof Set).toBe(true);
      expect(set.size).toBe(1);
      // eslint-disable-next-line no-for-of-loops/no-for-of-loops
@@ -49,6 +49,20 @@ function normalizeCodeLocInfo(str) {

 describe('ReactFlightDOMEdge', () => {
  beforeEach(() => {
+    // Mock performance.now for timing tests
+    let time = 10;
+    const now = jest.fn().mockImplementation(() => {
+      return time++;
+    });
+    Object.defineProperty(performance, 'timeOrigin', {
+      value: time,
+      configurable: true,
+    });
+    Object.defineProperty(performance, 'now', {
+      value: now,
+      configurable: true,
+    });
+
    jest.resetModules();

    reactServerAct = require('internal-test-utils').serverAct;
@@ -401,7 +415,7 @@ describe('ReactFlightDOMEdge', () => {

    const serializedContent = await readResult(stream1);

-    expect(serializedContent.length).toBeLessThan(425);
+    expect(serializedContent.length).toBeLessThan(490);
    expect(timesRendered).toBeLessThan(5);

    const model = await ReactServerDOMClient.createFromReadableStream(stream2, {
@@ -472,7 +486,7 @@ describe('ReactFlightDOMEdge', () => {
    const [stream1, stream2] = passThrough(stream).tee();

    const serializedContent = await readResult(stream1);
-    expect(serializedContent.length).toBeLessThan(__DEV__ ? 605 : 400);
+    expect(serializedContent.length).toBeLessThan(__DEV__ ? 680 : 400);
    expect(timesRendered).toBeLessThan(5);

    const model = await serverAct(() =>
@@ -506,7 +520,7 @@ describe('ReactFlightDOMEdge', () => {
      ),
    );
    const serializedContent = await readResult(stream);
-    const expectedDebugInfoSize = __DEV__ ? 300 * 20 : 0;
+    const expectedDebugInfoSize = __DEV__ ? 320 * 20 : 0;
    expect(serializedContent.length).toBeLessThan(150 + expectedDebugInfoSize);
  });

@@ -934,6 +948,7 @@ describe('ReactFlightDOMEdge', () => {
    );
  });

+  // @gate !__DEV__ || enableComponentPerformanceTrack
  it('supports async server component debug info as the element owner in DEV', async () => {
    function Container({children}) {
      return children;
@@ -989,16 +1004,19 @@ describe('ReactFlightDOMEdge', () => {
        owner: null,
      });
      expect(lazyWrapper._debugInfo).toEqual([
+        {time: 11},
        greetInfo,
+        {time: 12},
        expect.objectContaining({
          name: 'Container',
          env: 'Server',
          owner: greetInfo,
        }),
+        {time: 13},
      ]);
      // The owner that created the span was the outer server component.
      // We expect the debug info to be referentially equal to the owner.
-      expect(greeting._owner).toBe(lazyWrapper._debugInfo[0]);
+      expect(greeting._owner).toBe(lazyWrapper._debugInfo[1]);
    } else {
      expect(lazyWrapper._debugInfo).toBe(undefined);
      expect(greeting._owner).toBe(undefined);
@@ -20,6 +20,8 @@ import {
  enableTaint,
  enableServerComponentLogs,
  enableOwnerStacks,
+  enableProfilerTimer,
+  enableComponentPerformanceTrack,
 } from 'shared/ReactFeatureFlags';

 import {enableFlightReadableStream} from 'shared/ReactFeatureFlags';
@@ -345,6 +347,7 @@ type Task = {
  keyPath: null | string, // parent server component keys
  implicitSlot: boolean, // true if the root server component of this sequence had a null key
  thenableState: ThenableState | null,
+  timed: boolean, // Profiling-only. Whether we need to track the completion time of this task.
  environmentName: string, // DEV-only. Used to track if the environment for this task changed.
  debugOwner: null | ReactComponentInfo, // DEV-only
  debugStack: null | Error, // DEV-only
@@ -392,6 +395,8 @@ export type Request = {
  onPostpone: (reason: string) => void,
  onAllReady: () => void,
  onFatalError: mixed => void,
+  // Profiling-only
+  timeOrigin: number,
  // DEV-only
  environmentName: () => string,
  filterStackFrame: (url: string, functionName: string) => boolean,
@@ -517,6 +522,23 @@ function RequestInstance(
        : filterStackFrame;
    this.didWarnForKey = null;
  }
+
+  if (enableProfilerTimer && enableComponentPerformanceTrack) {
+    // We start by serializing the time origin. Any future timestamps will be
+    // emitted relatively to this origin. Instead of using performance.timeOrigin
+    // as this origin, we use the timestamp at the start of the request.
+    // This avoids leaking unnecessary information like how long the server has
+    // been running and allows for more compact representation of each timestamp.
+    // The time origin is stored as an offset in the time space of this environment.
+    const timeOrigin = (this.timeOrigin = performance.now());
+    emitTimeOriginChunk(
+      this,
+      timeOrigin +
+        // $FlowFixMe[prop-missing]
+        performance.timeOrigin,
+    );
+  }
+
  const rootTask = createTask(
    this,
    model,
@@ -690,6 +712,11 @@ function serializeThenable(
    },
  );

+  if (enableProfilerTimer && enableComponentPerformanceTrack) {
+    // If this is async we need to time when this task finishes.
+    newTask.timed = true;
+  }
+
  return newTask.id;
 }

@@ -1240,6 +1267,13 @@ function renderFunctionComponent<Props>(
      // being no references to this as an owner.

      outlineComponentInfo(request, componentDebugInfo);
+
+      // Track when we started rendering this component.
+      if (enableProfilerTimer && enableComponentPerformanceTrack) {
+        task.timed = true;
+        emitTimingChunk(request, componentDebugID, performance.now());
+      }
+
      emitDebugChunk(request, componentDebugID, componentDebugInfo);

      // We've emitted the latest environment for this task so we track that.
@@ -1769,6 +1803,10 @@ function renderElement(
 }

 function pingTask(request: Request, task: Task): void {
+  if (enableProfilerTimer && enableComponentPerformanceTrack) {
+    // If this was async we need to emit the time when it completes.
+    task.timed = true;
+  }
  const pingedTasks = request.pingedTasks;
  pingedTasks.push(task);
  if (pingedTasks.length === 1) {
@@ -1862,8 +1900,11 @@ function createTask(
    thenableState: null,
  }: Omit<
    Task,
-    'environmentName' | 'debugOwner' | 'debugStack' | 'debugTask',
+    'timed' | 'environmentName' | 'debugOwner' | 'debugStack' | 'debugTask',
  >): any);
+  if (enableProfilerTimer && enableComponentPerformanceTrack) {
+    task.timed = false;
+  }
  if (__DEV__) {
    task.environmentName = request.environmentName();
    task.debugOwner = debugOwner;
@@ -3769,6 +3810,17 @@ function emitConsoleChunk(
  request.completedRegularChunks.push(processedChunk);
 }

+function emitTimeOriginChunk(request: Request, timeOrigin: number): void {
+  // We emit the time origin once. All ReactTimeInfo timestamps later in the stream
+  // are relative to this time origin. This allows for more compact number encoding
+  // and lower precision loss.
+  request.pendingChunks++;
+  const row = ':N' + timeOrigin + '\n';
+  const processedChunk = stringToChunk(row);
+  // TODO: Move to its own priority queue.
+  request.completedRegularChunks.push(processedChunk);
+}
+
 function forwardDebugInfo(
  request: Request,
  id: number,
@@ -3776,16 +3828,38 @@ function forwardDebugInfo(
 ) {
  for (let i = 0; i < debugInfo.length; i++) {
    request.pendingChunks++;
-    if (typeof debugInfo[i].name === 'string') {
-      // We outline this model eagerly so that we can refer to by reference as an owner.
-      // If we had a smarter way to dedupe we might not have to do this if there ends up
-      // being no references to this as an owner.
-      outlineComponentInfo(request, (debugInfo[i]: any));
+    if (typeof debugInfo[i].time === 'number') {
+      // When forwarding time we need to ensure to convert it to the time space of the payload.
+      emitTimingChunk(request, id, debugInfo[i].time);
+    } else {
+      if (typeof debugInfo[i].name === 'string') {
+        // We outline this model eagerly so that we can refer to by reference as an owner.
+        // If we had a smarter way to dedupe we might not have to do this if there ends up
+        // being no references to this as an owner.
+        outlineComponentInfo(request, (debugInfo[i]: any));
+      }
+      emitDebugChunk(request, id, debugInfo[i]);
    }
-    emitDebugChunk(request, id, debugInfo[i]);
  }
 }

+function emitTimingChunk(
+  request: Request,
+  id: number,
+  timestamp: number,
+): void {
+  if (!enableProfilerTimer || !enableComponentPerformanceTrack) {
+    return;
+  }
+  request.pendingChunks++;
+  const relativeTimestamp = timestamp - request.timeOrigin;
+  const row =
+    serializeRowHeader('D', id) + '{"time":' + relativeTimestamp + '}\n';
+  const processedChunk = stringToChunk(row);
+  // TODO: Move to its own priority queue.
+  request.completedRegularChunks.push(processedChunk);
+}
+
 function emitChunk(
  request: Request,
  task: Task,
@@ -3877,6 +3951,11 @@ function emitChunk(
 }

 function erroredTask(request: Request, task: Task, error: mixed): void {
+  if (enableProfilerTimer && enableComponentPerformanceTrack) {
+    if (task.timed) {
+      emitTimingChunk(request, task.id, performance.now());
+    }
+  }
  request.abortableTasks.delete(task);
  task.status = ERRORED;
  if (
@@ -3939,21 +4018,27 @@ function retryTask(request: Request, task: Task): void {
    task.keyPath = null;
    task.implicitSlot = false;

+    if (__DEV__) {
+      const currentEnv = (0, request.environmentName)();
+      if (currentEnv !== task.environmentName) {
+        request.pendingChunks++;
+        // The environment changed since we last emitted any debug information for this
+        // task. We emit an entry that just includes the environment name change.
+        emitDebugChunk(request, task.id, {env: currentEnv});
+      }
+    }
+    // We've finished rendering. Log the end time.
+    if (enableProfilerTimer && enableComponentPerformanceTrack) {
+      if (task.timed) {
+        emitTimingChunk(request, task.id, performance.now());
+      }
+    }
+
    if (typeof resolvedModel === 'object' && resolvedModel !== null) {
      // We're not in a contextual place here so we can refer to this object by this ID for
      // any future references.
      request.writtenObjects.set(resolvedModel, serializeByValueID(task.id));

-      if (__DEV__) {
-        const currentEnv = (0, request.environmentName)();
-        if (currentEnv !== task.environmentName) {
-          request.pendingChunks++;
-          // The environment changed since we last emitted any debug information for this
-          // task. We emit an entry that just includes the environment name change.
-          emitDebugChunk(request, task.id, {env: currentEnv});
-        }
-      }
-
      // Object might contain unresolved values like additional elements.
      // This is simulating what the JSON loop would do if this was part of it.
      emitChunk(request, task, resolvedModel);
@@ -3962,17 +4047,6 @@ function retryTask(request: Request, task: Task): void {
      // We don't need to escape it again so it's not passed the toJSON replacer.
      // $FlowFixMe[incompatible-type] stringify can return null for undefined but we never do
      const json: string = stringify(resolvedModel);
-
-      if (__DEV__) {
-        const currentEnv = (0, request.environmentName)();
-        if (currentEnv !== task.environmentName) {
-          request.pendingChunks++;
-          // The environment changed since we last emitted any debug information for this
-          // task. We emit an entry that just includes the environment name change.
-          emitDebugChunk(request, task.id, {env: currentEnv});
-        }
-      }
-
      emitModelChunk(request, task.id, json);
    }

@@ -4082,6 +4156,12 @@ function abortTask(task: Task, request: Request, errorId: number): void {
    return;
  }
  task.status = ABORTED;
+  // Track when we aborted this task as its end time.
+  if (enableProfilerTimer && enableComponentPerformanceTrack) {
+    if (task.timed) {
+      emitTimingChunk(request, task.id, performance.now());
+    }
+  }
  // Instead of emitting an error per task.id, we emit a model that only
  // has a single value referencing the error.
  const ref = serializeByValueID(errorId);