diff --git a/fixtures/flight/src/App.js b/fixtures/flight/src/App.js
index 833c655cbffc7..2f29de7abaffe 100644
--- a/fixtures/flight/src/App.js
+++ b/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 {children}
;
}
diff --git a/packages/react-client/src/ReactFlightClient.js b/packages/react-client/src/ReactFlightClient.js
index a69ede9efdf9d..1171f933d2712 100644
--- a/packages/react-client/src/ReactFlightClient.js
+++ b/packages/react-client/src/ReactFlightClient.js
@@ -2902,6 +2902,46 @@ function resolveTypedArray(
resolveBuffer(response, id, view);
}
+function logComponentInfo(
+ response: Response,
+ root: SomeChunk,
+ 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,
@@ -2957,21 +2997,20 @@ 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--) {
@@ -2979,6 +3018,7 @@ function flushComponentPerformance(
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;
diff --git a/packages/react-server/src/ReactFlightAsyncSequence.js b/packages/react-server/src/ReactFlightAsyncSequence.js
index 215af7f7953b3..5785ba072c626 100644
--- a/packages/react-server/src/ReactFlightAsyncSequence.js
+++ b/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 = {
diff --git a/packages/react-server/src/ReactFlightServer.js b/packages/react-server/src/ReactFlightServer.js
index 5a9d0082ad4fc..3a56148f7101d 100644
--- a/packages/react-server/src/ReactFlightServer.js
+++ b/packages/react-server/src/ReactFlightServer.js
@@ -777,6 +777,10 @@ function serializeThenable(
}
}
if (newTask.status === PENDING) {
+ if (enableProfilerTimer && enableComponentPerformanceTrack) {
+ // If this is async we need to time when this task finishes.
+ newTask.timed = true;
+ }
// We expect that the only status it might be otherwise is ABORTED.
// When we abort we emit chunks in each pending task slot and don't need
// to do so again here.
@@ -786,11 +790,6 @@ function serializeThenable(
},
);
- if (enableProfilerTimer && enableComponentPerformanceTrack) {
- // If this is async we need to time when this task finishes.
- newTask.timed = true;
- }
-
return newTask.id;
}
@@ -1341,12 +1340,7 @@ function renderFunctionComponent(
// Track when we started rendering this component.
if (enableProfilerTimer && enableComponentPerformanceTrack) {
- task.timed = true;
- emitTimingChunk(
- request,
- componentDebugID,
- (task.time = performance.now()),
- );
+ advanceTaskTime(request, task, performance.now());
}
emitDebugChunk(request, componentDebugID, componentDebugInfo);
@@ -1890,8 +1884,8 @@ function visitAsyncNode(
request: Request,
task: Task,
node: AsyncSequence,
- cutOff: number,
visited: Set,
+ cutOff: number,
): null | PromiseNode | IONode {
if (visited.has(node)) {
// It's possible to visit them same node twice when it's part of both an "awaited" path
@@ -1900,11 +1894,11 @@ function visitAsyncNode(
}
visited.add(node);
// First visit anything that blocked this sequence to start in the first place.
- if (node.previous !== null) {
+ if (node.previous !== null && node.end > request.timeOrigin) {
// We ignore the return value here because if it wasn't awaited in user space, then we don't log it.
// It also means that it can just have been part of a previous component's render.
// TODO: This means that some I/O can get lost that was still blocking the sequence.
- visitAsyncNode(request, task, node.previous, cutOff, visited);
+ visitAsyncNode(request, task, node.previous, visited, cutOff);
}
switch (node.tag) {
case IO_NODE: {
@@ -1923,24 +1917,23 @@ function visitAsyncNode(
const awaited = node.awaited;
let match = null;
if (awaited !== null) {
- const ioNode = visitAsyncNode(request, task, awaited, cutOff, visited);
+ const ioNode = visitAsyncNode(request, task, awaited, visited, cutOff);
if (ioNode !== null) {
// This Promise was blocked on I/O. That's a signal that this Promise is interesting to log.
// We don't log it yet though. We return it to be logged by the point where it's awaited.
// The ioNode might be another PromiseNode in the case where none of the AwaitNode had
// unfiltered stacks.
- if (
+ if (ioNode.tag === PROMISE_NODE) {
+ // If the ioNode was a Promise, then that means we found one in user space since otherwise
+ // we would've returned an IO node. We assume this has the best stack.
+ match = ioNode;
+ } else if (
filterStackTrace(request, parseStackTrace(node.stack, 1)).length ===
0
) {
- // Typically we assume that the outer most Promise that was awaited in user space has the
- // most actionable stack trace for the start of the operation. However, if this Promise
- // was created inside only third party code, then try to use the inner node instead.
- // This could happen if you pass a first party Promise into a third party to be awaited there.
- if (ioNode.end < 0) {
- // If we haven't defined an end time, use the resolve of the outer Promise.
- ioNode.end = node.end;
- }
+ // If this Promise was created inside only third party code, then try to use
+ // the inner I/O node instead. This could happen if third party calls into first
+ // party to perform some I/O.
match = ioNode;
} else {
match = node;
@@ -1955,30 +1948,17 @@ function visitAsyncNode(
}
return match;
}
- case UNRESOLVED_AWAIT_NODE:
- // We could be inside the .then() which is about to resolve this node.
- // TODO: We could call emitAsyncSequence in a microtask to avoid this issue.
- // Fallthrough to the resolved path.
+ case UNRESOLVED_AWAIT_NODE: {
+ return null;
+ }
case AWAIT_NODE: {
const awaited = node.awaited;
let match = null;
if (awaited !== null) {
- const ioNode = visitAsyncNode(request, task, awaited, cutOff, visited);
+ const ioNode = visitAsyncNode(request, task, awaited, visited, cutOff);
if (ioNode !== null) {
const startTime: number = node.start;
- let endTime: number;
- if (node.tag === UNRESOLVED_AWAIT_NODE) {
- // If we haven't defined an end time, use the resolve of the inner Promise.
- // This can happen because the ping gets invoked before the await gets resolved.
- if (ioNode.end < node.start) {
- // If we're awaiting a resolved Promise it could have finished before we started.
- endTime = node.start;
- } else {
- endTime = ioNode.end;
- }
- } else {
- endTime = node.end;
- }
+ const endTime: number = node.end;
if (endTime <= request.timeOrigin) {
// This was already resolved when we started this render. It must have been either something
// that's part of a start up sequence or externally cached data. We exclude that information.
@@ -2002,14 +1982,12 @@ function visitAsyncNode(
match = ioNode;
} else {
// Outline the IO node.
- if (ioNode.end < 0) {
- ioNode.end = endTime;
- }
serializeIONode(request, ioNode);
+
// We log the environment at the time when the last promise pigned ping which may
// be later than what the environment was when we actually started awaiting.
const env = (0, request.environmentName)();
- emitTimingChunk(request, task.id, startTime);
+ advanceTaskTime(request, task, startTime);
// Then emit a reference to us awaiting it in the current task.
request.pendingChunks++;
emitDebugChunk(request, task.id, {
@@ -2018,23 +1996,14 @@ function visitAsyncNode(
owner: node.owner,
stack: stack,
});
- emitTimingChunk(request, task.id, endTime);
+ markOperationEndTime(request, task, endTime);
}
}
}
}
// We need to forward after we visit awaited nodes because what ever I/O we requested that's
// the thing that generated this node and its virtual children.
- let debugInfo: null | ReactDebugInfo;
- if (node.tag === UNRESOLVED_AWAIT_NODE) {
- const promise = node.debugInfo.deref();
- debugInfo =
- promise === undefined || promise._debugInfo === undefined
- ? null
- : promise._debugInfo;
- } else {
- debugInfo = node.debugInfo;
- }
+ const debugInfo: null | ReactDebugInfo = node.debugInfo;
if (debugInfo !== null) {
forwardDebugInfo(request, task, debugInfo);
}
@@ -2051,37 +2020,23 @@ function emitAsyncSequence(
request: Request,
task: Task,
node: AsyncSequence,
- cutOff: number,
): void {
const visited: Set = new Set();
- const awaitedNode = visitAsyncNode(request, task, node, cutOff, visited);
+ const awaitedNode = visitAsyncNode(request, task, node, visited, task.time);
if (awaitedNode !== null) {
// Nothing in user space (unfiltered stack) awaited this.
- if (awaitedNode.end < 0) {
- // If this was I/O directly without a Promise, then it means that some custom Thenable
- // called our ping directly and not from a native .then(). We use the current ping time
- // as the end time and treat it as an await with no stack.
- // TODO: If this I/O is recurring then we really should have different entries for
- // each occurrence. Right now we'll only track the first time it is invoked.
- awaitedNode.end = performance.now();
- }
serializeIONode(request, awaitedNode);
request.pendingChunks++;
// We log the environment at the time when we ping which may be later than what the
// environment was when we actually started awaiting.
const env = (0, request.environmentName)();
// If we don't have any thing awaited, the time we started awaiting was internal
- // when we yielded after rendering. The cutOff time is basically that.
- const awaitStartTime = cutOff;
- // If the end time finished before we started, it could've been a cached thing so
- // we clamp it to the cutOff time. Effectively leading to a zero-time await.
- const awaitEndTime = awaitedNode.end < cutOff ? cutOff : awaitedNode.end;
- emitTimingChunk(request, task.id, awaitStartTime);
+ // when we yielded after rendering. The current task time is basically that.
emitDebugChunk(request, task.id, {
awaited: ((awaitedNode: any): ReactIOInfo), // This is deduped by this reference.
env: env,
});
- emitTimingChunk(request, task.id, awaitEndTime);
+ markOperationEndTime(request, task, awaitedNode.end);
}
}
@@ -2092,7 +2047,7 @@ function pingTask(request: Request, task: Task): void {
if (enableAsyncDebugInfo) {
const sequence = getCurrentAsyncSequence();
if (sequence !== null) {
- emitAsyncSequence(request, task, sequence, task.time);
+ emitAsyncSequence(request, task, sequence);
}
}
}
@@ -4295,19 +4250,13 @@ function forwardDebugInfo(
debugInfo: ReactDebugInfo,
) {
const id = task.id;
- const minimumTime =
- enableProfilerTimer && enableComponentPerformanceTrack ? task.time : 0;
for (let i = 0; i < debugInfo.length; i++) {
const info = debugInfo[i];
if (typeof info.time === 'number') {
// When forwarding time we need to ensure to convert it to the time space of the payload.
// We clamp the time to the starting render of the current component. It's as if it took
// no time to render and await if we reuse cached content.
- emitTimingChunk(
- request,
- id,
- info.time < minimumTime ? minimumTime : info.time,
- );
+ markOperationEndTime(request, task, info.time);
} else {
if (typeof info.name === 'string') {
// We outline this model eagerly so that we can refer to by reference as an owner.
@@ -4384,6 +4333,40 @@ function emitTimingChunk(
request.completedRegularChunks.push(processedChunk);
}
+function advanceTaskTime(
+ request: Request,
+ task: Task,
+ timestamp: number,
+): void {
+ if (!enableProfilerTimer || !enableComponentPerformanceTrack) {
+ return;
+ }
+ // Emits a timing chunk, if the new timestamp is higher than the previous timestamp of this task.
+ if (timestamp > task.time) {
+ emitTimingChunk(request, task.id, timestamp);
+ task.time = timestamp;
+ } else if (!task.timed) {
+ // If it wasn't timed before, e.g. an outlined object, we need to emit the first timestamp and
+ // it is now timed.
+ emitTimingChunk(request, task.id, task.time);
+ }
+ task.timed = true;
+}
+
+function markOperationEndTime(request: Request, task: Task, timestamp: number) {
+ if (!enableProfilerTimer || !enableComponentPerformanceTrack) {
+ return;
+ }
+ // This is like advanceTaskTime() but always emits a timing chunk even if it doesn't advance.
+ // This ensures that the end time of the previous entry isn't implied to be the start of the next one.
+ if (timestamp > task.time) {
+ emitTimingChunk(request, task.id, timestamp);
+ task.time = timestamp;
+ } else {
+ emitTimingChunk(request, task.id, task.time);
+ }
+}
+
function emitChunk(
request: Request,
task: Task,
@@ -4475,7 +4458,7 @@ function emitChunk(
function erroredTask(request: Request, task: Task, error: mixed): void {
if (enableProfilerTimer && enableComponentPerformanceTrack) {
if (task.timed) {
- emitTimingChunk(request, task.id, (task.time = performance.now()));
+ markOperationEndTime(request, task, performance.now());
}
}
task.status = ERRORED;
@@ -4558,7 +4541,7 @@ function retryTask(request: Request, task: Task): void {
// We've finished rendering. Log the end time.
if (enableProfilerTimer && enableComponentPerformanceTrack) {
if (task.timed) {
- emitTimingChunk(request, task.id, (task.time = performance.now()));
+ markOperationEndTime(request, task, performance.now());
}
}
@@ -4685,7 +4668,7 @@ function abortTask(task: Task, request: Request, errorId: number): void {
// Track when we aborted this task as its end time.
if (enableProfilerTimer && enableComponentPerformanceTrack) {
if (task.timed) {
- emitTimingChunk(request, task.id, (task.time = performance.now()));
+ markOperationEndTime(request, task, performance.now());
}
}
// Instead of emitting an error per task.id, we emit a model that only
diff --git a/packages/react-server/src/ReactFlightServerConfigDebugNode.js b/packages/react-server/src/ReactFlightServerConfigDebugNode.js
index 3bf84962bbed0..ddcf256525b6d 100644
--- a/packages/react-server/src/ReactFlightServerConfigDebugNode.js
+++ b/packages/react-server/src/ReactFlightServerConfigDebugNode.js
@@ -30,6 +30,27 @@ import {enableAsyncDebugInfo} from 'shared/ReactFeatureFlags';
const pendingOperations: Map =
__DEV__ && enableAsyncDebugInfo ? new Map() : (null: any);
+// Keep the last resolved await as a workaround for async functions missing data.
+let lastRanAwait: null | AwaitNode = null;
+
+function resolvePromiseOrAwaitNode(
+ unresolvedNode: UnresolvedAwaitNode | UnresolvedPromiseNode,
+ endTime: number,
+): AwaitNode | PromiseNode {
+ const resolvedNode: AwaitNode | PromiseNode = (unresolvedNode: any);
+ resolvedNode.tag = ((unresolvedNode.tag === UNRESOLVED_PROMISE_NODE
+ ? PROMISE_NODE
+ : AWAIT_NODE): any);
+ // The Promise can be garbage collected after this so we should extract debugInfo first.
+ const promise = unresolvedNode.debugInfo.deref();
+ resolvedNode.debugInfo =
+ promise === undefined || promise._debugInfo === undefined
+ ? null
+ : promise._debugInfo;
+ resolvedNode.end = endTime;
+ return resolvedNode;
+}
+
// Initialize the tracing of async operations.
// We do this globally since the async work can potentially eagerly
// start before the first request and once requests start they can interleave.
@@ -129,42 +150,76 @@ export function initAsyncDebugInfo(): void {
}
pendingOperations.set(asyncId, node);
},
- promiseResolve(asyncId: number): void {
+ before(asyncId: number): void {
const node = pendingOperations.get(asyncId);
if (node !== undefined) {
- let resolvedNode: AwaitNode | PromiseNode;
switch (node.tag) {
+ case IO_NODE: {
+ lastRanAwait = null;
+ // Log the end time when we resolved the I/O. This can happen
+ // more than once if it's a recurring resource like a connection.
+ const ioNode: IONode = (node: any);
+ ioNode.end = performance.now();
+ break;
+ }
case UNRESOLVED_AWAIT_NODE: {
- const awaitNode: AwaitNode = (node: any);
- awaitNode.tag = AWAIT_NODE;
- resolvedNode = awaitNode;
+ // If we begin before we resolve, that means that this is actually already resolved but
+ // the promiseResolve hook is called at the end of the execution. So we track the time
+ // in the before call instead.
+ // $FlowFixMe
+ lastRanAwait = resolvePromiseOrAwaitNode(node, performance.now());
break;
}
- case UNRESOLVED_PROMISE_NODE: {
- const promiseNode: PromiseNode = (node: any);
- promiseNode.tag = PROMISE_NODE;
- resolvedNode = promiseNode;
+ case AWAIT_NODE: {
+ lastRanAwait = node;
break;
}
- case IO_NODE:
- // eslint-disable-next-line react-internal/prod-error-codes
- throw new Error(
- 'A Promise should never be an IO_NODE. This is a bug in React.',
+ case UNRESOLVED_PROMISE_NODE: {
+ // We typically don't expected Promises to have an execution scope since only the awaits
+ // have a then() callback. However, this can happen for native async functions. The last
+ // piece of code that executes the return after the last await has the execution context
+ // of the Promise.
+ const resolvedNode = resolvePromiseOrAwaitNode(
+ node,
+ performance.now(),
);
+ // We are missing information about what this was unblocked by but we can guess that it
+ // was whatever await we ran last since this will continue in a microtask after that.
+ // This is not perfect because there could potentially be other microtasks getting in
+ // between.
+ resolvedNode.previous = lastRanAwait;
+ lastRanAwait = null;
+ break;
+ }
+ default: {
+ lastRanAwait = null;
+ }
+ }
+ }
+ },
+
+ promiseResolve(asyncId: number): void {
+ const node = pendingOperations.get(asyncId);
+ if (node !== undefined) {
+ let resolvedNode: AwaitNode | PromiseNode;
+ switch (node.tag) {
+ case UNRESOLVED_AWAIT_NODE:
+ case UNRESOLVED_PROMISE_NODE: {
+ resolvedNode = resolvePromiseOrAwaitNode(node, performance.now());
+ break;
+ }
+ case AWAIT_NODE:
+ case PROMISE_NODE: {
+ // We already resolved this in the before hook.
+ resolvedNode = node;
+ break;
+ }
default:
// eslint-disable-next-line react-internal/prod-error-codes
throw new Error(
- 'A Promise should never be resolved twice. This is a bug in React or Node.js.',
+ 'A Promise should never be an IO_NODE. This is a bug in React.',
);
}
- // Log the end time when we resolved the promise.
- resolvedNode.end = performance.now();
- // The Promise can be garbage collected after this so we should extract debugInfo first.
- const promise = node.debugInfo.deref();
- resolvedNode.debugInfo =
- promise === undefined || promise._debugInfo === undefined
- ? null
- : promise._debugInfo;
const currentAsyncId = executionAsyncId();
if (asyncId !== currentAsyncId) {
// If the promise was not resolved by itself, then that means that
diff --git a/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js b/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js
index 989dbdf19cbff..05f31ff7def9d 100644
--- a/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js
+++ b/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js
@@ -419,7 +419,7 @@ describe('ReactFlightAsyncDebugInfo', () => {
"awaited": {
"end": 0,
"env": "Server",
- "name": "getData",
+ "name": "delay",
"owner": {
"env": "Server",
"key": null,
@@ -438,19 +438,19 @@ describe('ReactFlightAsyncDebugInfo', () => {
},
"stack": [
[
- "getData",
+ "delay",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 156,
- 27,
- 156,
- 5,
+ 133,
+ 12,
+ 132,
+ 3,
],
[
- "Component",
+ "getData",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 165,
- 22,
- 163,
+ 158,
+ 21,
+ 156,
5,
],
],
@@ -547,9 +547,6 @@ describe('ReactFlightAsyncDebugInfo', () => {
],
],
},
- {
- "time": 0,
- },
{
"awaited": {
"end": 0,
@@ -637,9 +634,9 @@ describe('ReactFlightAsyncDebugInfo', () => {
[
"Object.",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 608,
+ 605,
109,
- 599,
+ 596,
94,
],
],
@@ -708,9 +705,9 @@ describe('ReactFlightAsyncDebugInfo', () => {
[
"Object.",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 679,
+ 676,
109,
- 655,
+ 652,
50,
],
],
@@ -790,9 +787,9 @@ describe('ReactFlightAsyncDebugInfo', () => {
[
"Object.",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 761,
+ 758,
109,
- 744,
+ 741,
63,
],
],
@@ -817,9 +814,9 @@ describe('ReactFlightAsyncDebugInfo', () => {
[
"Component",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 757,
+ 754,
24,
- 756,
+ 753,
5,
],
],
@@ -849,9 +846,9 @@ describe('ReactFlightAsyncDebugInfo', () => {
[
"Component",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 757,
+ 754,
24,
- 756,
+ 753,
5,
],
],
@@ -868,17 +865,17 @@ describe('ReactFlightAsyncDebugInfo', () => {
[
"getData",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 746,
+ 743,
13,
- 745,
+ 742,
5,
],
[
"ThirdPartyComponent",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 752,
+ 749,
24,
- 751,
+ 748,
5,
],
],
@@ -902,9 +899,9 @@ describe('ReactFlightAsyncDebugInfo', () => {
[
"Component",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 757,
+ 754,
24,
- 756,
+ 753,
5,
],
],
@@ -913,17 +910,17 @@ describe('ReactFlightAsyncDebugInfo', () => {
[
"getData",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 746,
+ 743,
13,
- 745,
+ 742,
5,
],
[
"ThirdPartyComponent",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 752,
+ 749,
24,
- 751,
+ 748,
5,
],
],
@@ -956,9 +953,9 @@ describe('ReactFlightAsyncDebugInfo', () => {
[
"Component",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 757,
+ 754,
24,
- 756,
+ 753,
5,
],
],
@@ -975,17 +972,17 @@ describe('ReactFlightAsyncDebugInfo', () => {
[
"getData",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 747,
+ 744,
13,
- 745,
+ 742,
5,
],
[
"ThirdPartyComponent",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 752,
+ 749,
18,
- 751,
+ 748,
5,
],
],
@@ -1009,9 +1006,9 @@ describe('ReactFlightAsyncDebugInfo', () => {
[
"Component",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 757,
+ 754,
24,
- 756,
+ 753,
5,
],
],
@@ -1020,17 +1017,17 @@ describe('ReactFlightAsyncDebugInfo', () => {
[
"getData",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 747,
+ 744,
13,
- 745,
+ 742,
5,
],
[
"ThirdPartyComponent",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 752,
+ 749,
18,
- 751,
+ 748,
5,
],
],
@@ -1108,9 +1105,9 @@ describe('ReactFlightAsyncDebugInfo', () => {
[
"Object.",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 1074,
+ 1071,
40,
- 1052,
+ 1049,
62,
],
],
@@ -1132,9 +1129,9 @@ describe('ReactFlightAsyncDebugInfo', () => {
[
"Object.",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 1074,
+ 1071,
40,
- 1052,
+ 1049,
62,
],
],
@@ -1151,17 +1148,17 @@ describe('ReactFlightAsyncDebugInfo', () => {
[
"getData",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 1059,
+ 1056,
13,
- 1055,
+ 1052,
25,
],
[
"Component",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 1069,
+ 1066,
13,
- 1068,
+ 1065,
5,
],
],
@@ -1177,9 +1174,9 @@ describe('ReactFlightAsyncDebugInfo', () => {
[
"Object.",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 1074,
+ 1071,
40,
- 1052,
+ 1049,
62,
],
],
@@ -1188,17 +1185,17 @@ describe('ReactFlightAsyncDebugInfo', () => {
[
"getData",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 1059,
+ 1056,
13,
- 1055,
+ 1052,
25,
],
[
"Component",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 1069,
+ 1066,
13,
- 1068,
+ 1065,
5,
],
],
@@ -1218,9 +1215,9 @@ describe('ReactFlightAsyncDebugInfo', () => {
[
"Component",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 1070,
+ 1067,
60,
- 1068,
+ 1065,
5,
],
],
@@ -1232,7 +1229,7 @@ describe('ReactFlightAsyncDebugInfo', () => {
"awaited": {
"end": 0,
"env": "Server",
- "name": "getData",
+ "name": "delay",
"owner": {
"env": "Server",
"key": null,
@@ -1242,28 +1239,36 @@ describe('ReactFlightAsyncDebugInfo', () => {
[
"Object.",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 1074,
+ 1071,
40,
- 1052,
+ 1049,
62,
],
],
},
"stack": [
+ [
+ "delay",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 133,
+ 12,
+ 132,
+ 3,
+ ],
[
"getData",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 1055,
- 47,
- 1055,
+ 1056,
+ 13,
+ 1052,
25,
],
[
"Component",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 1069,
+ 1066,
13,
- 1068,
+ 1065,
5,
],
],
@@ -1279,9 +1284,9 @@ describe('ReactFlightAsyncDebugInfo', () => {
[
"Component",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 1070,
+ 1067,
60,
- 1068,
+ 1065,
5,
],
],
@@ -1290,9 +1295,346 @@ describe('ReactFlightAsyncDebugInfo', () => {
[
"Child",
"/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
- 1064,
+ 1061,
28,
- 1063,
+ 1060,
+ 5,
+ ],
+ ],
+ },
+ {
+ "time": 0,
+ },
+ {
+ "time": 0,
+ },
+ ]
+ `);
+ }
+ });
+
+ it('can track implicit returned promises that are blocked by previous data', async () => {
+ 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 delayTrice();
+ return 'hi';
+ }
+
+ const stream = ReactServerDOMServer.renderToPipeableStream(
+ ,
+ {},
+ {
+ filterStackFrame,
+ },
+ );
+
+ const readable = new Stream.PassThrough(streamOptions);
+
+ const result = ReactServerDOMClient.createFromNodeStream(readable, {
+ moduleMap: {},
+ moduleLoading: {},
+ });
+ stream.pipe(readable);
+
+ expect(await result).toBe('hi');
+ if (
+ __DEV__ &&
+ gate(
+ flags =>
+ flags.enableComponentPerformanceTrack && flags.enableAsyncDebugInfo,
+ )
+ ) {
+ expect(getDebugInfo(result)).toMatchInlineSnapshot(`
+ [
+ {
+ "time": 0,
+ },
+ {
+ "env": "Server",
+ "key": null,
+ "name": "Bar",
+ "props": {},
+ "stack": [
+ [
+ "Object.",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 1334,
+ 40,
+ 1316,
+ 80,
+ ],
+ ],
+ },
+ {
+ "time": 0,
+ },
+ {
+ "awaited": {
+ "end": 0,
+ "env": "Server",
+ "name": "delay",
+ "owner": {
+ "env": "Server",
+ "key": null,
+ "name": "Bar",
+ "props": {},
+ "stack": [
+ [
+ "Object.",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 1334,
+ 40,
+ 1316,
+ 80,
+ ],
+ ],
+ },
+ "stack": [
+ [
+ "delay",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 133,
+ 12,
+ 132,
+ 3,
+ ],
+ [
+ "delayTrice",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 1324,
+ 13,
+ 1322,
+ 5,
+ ],
+ [
+ "Bar",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 1329,
+ 13,
+ 1328,
+ 5,
+ ],
+ ],
+ "start": 0,
+ },
+ "env": "Server",
+ "owner": {
+ "env": "Server",
+ "key": null,
+ "name": "Bar",
+ "props": {},
+ "stack": [
+ [
+ "Object.",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 1334,
+ 40,
+ 1316,
+ 80,
+ ],
+ ],
+ },
+ "stack": [
+ [
+ "delayTrice",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 1324,
+ 13,
+ 1322,
+ 5,
+ ],
+ [
+ "Bar",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 1329,
+ 13,
+ 1328,
+ 5,
+ ],
+ ],
+ },
+ {
+ "time": 0,
+ },
+ {
+ "awaited": {
+ "end": 0,
+ "env": "Server",
+ "name": "delay",
+ "owner": {
+ "env": "Server",
+ "key": null,
+ "name": "Bar",
+ "props": {},
+ "stack": [
+ [
+ "Object.",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 1334,
+ 40,
+ 1316,
+ 80,
+ ],
+ ],
+ },
+ "stack": [
+ [
+ "delay",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 133,
+ 12,
+ 132,
+ 3,
+ ],
+ [
+ "delayTwice",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 1318,
+ 13,
+ 1317,
+ 5,
+ ],
+ [
+ "delayTrice",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 1323,
+ 15,
+ 1322,
+ 5,
+ ],
+ [
+ "Bar",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 1329,
+ 13,
+ 1328,
+ 5,
+ ],
+ ],
+ "start": 0,
+ },
+ "env": "Server",
+ "owner": {
+ "env": "Server",
+ "key": null,
+ "name": "Bar",
+ "props": {},
+ "stack": [
+ [
+ "Object.",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 1334,
+ 40,
+ 1316,
+ 80,
+ ],
+ ],
+ },
+ "stack": [
+ [
+ "delayTwice",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 1318,
+ 13,
+ 1317,
+ 5,
+ ],
+ [
+ "delayTrice",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 1323,
+ 15,
+ 1322,
+ 5,
+ ],
+ [
+ "Bar",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 1329,
+ 13,
+ 1328,
+ 5,
+ ],
+ ],
+ },
+ {
+ "time": 0,
+ },
+ {
+ "awaited": {
+ "end": 0,
+ "env": "Server",
+ "name": "delay",
+ "owner": {
+ "env": "Server",
+ "key": null,
+ "name": "Bar",
+ "props": {},
+ "stack": [
+ [
+ "Object.",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 1334,
+ 40,
+ 1316,
+ 80,
+ ],
+ ],
+ },
+ "stack": [
+ [
+ "delay",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 133,
+ 12,
+ 132,
+ 3,
+ ],
+ [
+ "delayTwice",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 1319,
+ 13,
+ 1317,
+ 5,
+ ],
+ ],
+ "start": 0,
+ },
+ "env": "Server",
+ "owner": {
+ "env": "Server",
+ "key": null,
+ "name": "Bar",
+ "props": {},
+ "stack": [
+ [
+ "Object.",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 1334,
+ 40,
+ 1316,
+ 80,
+ ],
+ ],
+ },
+ "stack": [
+ [
+ "delayTwice",
+ "/packages/react-server/src/__tests__/ReactFlightAsyncDebugInfo-test.js",
+ 1319,
+ 13,
+ 1317,
5,
],
],