777
}
778
}
779
if (newTask.status === PENDING) {
780
+ if (enableProfilerTimer && enableComponentPerformanceTrack) {
781
+ // If this is async we need to time when this task finishes.
782
+ newTask.timed = true;
783
+ }
784
// We expect that the only status it might be otherwise is ABORTED.
785
// When we abort we emit chunks in each pending task slot and don't need
786
// to do so again here.
790
},
791
);
792
789
- if (enableProfilerTimer && enableComponentPerformanceTrack) {
790
- // If this is async we need to time when this task finishes.
791
- newTask.timed = true;
792
- }
793
-
793
return newTask.id;
794
}
795
1340
1341
// Track when we started rendering this component.
1342
if (enableProfilerTimer && enableComponentPerformanceTrack) {
1344
- task.timed = true;
1345
- emitTimingChunk(
1346
- request,
1347
- componentDebugID,
1348
- (task.time = performance.now()),
1349
- );
1343
+ advanceTaskTime(request, task, performance.now());
1344
}
1345
1346
emitDebugChunk(request, componentDebugID, componentDebugInfo);
1884
request: Request,
1885
task: Task,
1886
node: AsyncSequence,
1893
- cutOff: number,
1887
visited: Set<AsyncSequence>,
1888
+ cutOff: number,
1889
): null | PromiseNode | IONode {
1890
if (visited.has(node)) {
1891
// It's possible to visit them same node twice when it's part of both an "awaited" path
1894
}
1895
visited.add(node);
1896
// First visit anything that blocked this sequence to start in the first place.
1903
- if (node.previous !== null) {
1897
+ if (node.previous !== null && node.end > request.timeOrigin) {
1898
// We ignore the return value here because if it wasn't awaited in user space, then we don't log it.
1899
// It also means that it can just have been part of a previous component's render.
1900
// TODO: This means that some I/O can get lost that was still blocking the sequence.
1907
- visitAsyncNode(request, task, node.previous, cutOff, visited);
1901
+ visitAsyncNode(request, task, node.previous, visited, cutOff);
1902
}
1903
switch (node.tag) {
1904
case IO_NODE: {
1917
const awaited = node.awaited;
1918
let match = null;
1919
if (awaited !== null) {
1926
- const ioNode = visitAsyncNode(request, task, awaited, cutOff, visited);
1920
+ const ioNode = visitAsyncNode(request, task, awaited, visited, cutOff);
1921
if (ioNode !== null) {
1922
// This Promise was blocked on I/O. That's a signal that this Promise is interesting to log.
1923
// We don't log it yet though. We return it to be logged by the point where it's awaited.
1924
// The ioNode might be another PromiseNode in the case where none of the AwaitNode had
1925
// unfiltered stacks.
1932
- if (
1926
+ if (ioNode.tag === PROMISE_NODE) {
1927
+ // If the ioNode was a Promise, then that means we found one in user space since otherwise
1928
+ // we would've returned an IO node. We assume this has the best stack.
1929
+ match = ioNode;
1930
+ } else if (
1931
filterStackTrace(request, parseStackTrace(node.stack, 1)).length ===
1932
0
1933
) {
1936
- // Typically we assume that the outer most Promise that was awaited in user space has the
1937
- // most actionable stack trace for the start of the operation. However, if this Promise
1938
- // was created inside only third party code, then try to use the inner node instead.
1939
- // This could happen if you pass a first party Promise into a third party to be awaited there.
1940
- if (ioNode.end < 0) {
1941
- // If we haven't defined an end time, use the resolve of the outer Promise.
1942
- ioNode.end = node.end;
1943
- }
1934
+ // If this Promise was created inside only third party code, then try to use
1935
+ // the inner I/O node instead. This could happen if third party calls into first
1936
+ // party to perform some I/O.
1937
match = ioNode;
1938
} else {
1939
match = node;
1948
}
1949
return match;
1950
}
1958
- case UNRESOLVED_AWAIT_NODE:
1959
- // We could be inside the .then() which is about to resolve this node.
1960
- // TODO: We could call emitAsyncSequence in a microtask to avoid this issue.
1961
- // Fallthrough to the resolved path.
1951
+ case UNRESOLVED_AWAIT_NODE: {
1952
+ return null;
1953
+ }
1954
case AWAIT_NODE: {
1955
const awaited = node.awaited;
1956
let match = null;
1957
if (awaited !== null) {
1966
- const ioNode = visitAsyncNode(request, task, awaited, cutOff, visited);
1958
+ const ioNode = visitAsyncNode(request, task, awaited, visited, cutOff);
1959
if (ioNode !== null) {
1960
const startTime: number = node.start;
1969
- let endTime: number;
1970
- if (node.tag === UNRESOLVED_AWAIT_NODE) {
1971
- // If we haven't defined an end time, use the resolve of the inner Promise.
1972
- // This can happen because the ping gets invoked before the await gets resolved.
1973
- if (ioNode.end < node.start) {
1974
- // If we're awaiting a resolved Promise it could have finished before we started.
1975
- endTime = node.start;
1976
- } else {
1977
- endTime = ioNode.end;
1978
- }
1979
- } else {
1980
- endTime = node.end;
1981
- }
1961
+ const endTime: number = node.end;
1962
if (endTime <= request.timeOrigin) {
1963
// This was already resolved when we started this render. It must have been either something
1964
// that's part of a start up sequence or externally cached data. We exclude that information.
1982
match = ioNode;
1983
} else {
1984
// Outline the IO node.
2005
- if (ioNode.end < 0) {
2006
- ioNode.end = endTime;
2007
- }
1985
serializeIONode(request, ioNode);
1986
+
1987
// We log the environment at the time when the last promise pigned ping which may
1988
// be later than what the environment was when we actually started awaiting.
1989
const env = (0, request.environmentName)();
2012
- emitTimingChunk(request, task.id, startTime);
1990
+ advanceTaskTime(request, task, startTime);
1991
// Then emit a reference to us awaiting it in the current task.
1992
request.pendingChunks++;
1993
emitDebugChunk(request, task.id, {
1996
owner: node.owner,
1997
stack: stack,
1998
});
2021
- emitTimingChunk(request, task.id, endTime);
1999
+ markOperationEndTime(request, task, endTime);
2000
}
2001
}
2002
}
2003
}
2004
// We need to forward after we visit awaited nodes because what ever I/O we requested that's
2005
// the thing that generated this node and its virtual children.
2028
- let debugInfo: null | ReactDebugInfo;
2029
- if (node.tag === UNRESOLVED_AWAIT_NODE) {
2030
- const promise = node.debugInfo.deref();
2031
- debugInfo =
2032
- promise === undefined || promise._debugInfo === undefined
2033
- ? null
2034
- : promise._debugInfo;
2035
- } else {
2036
- debugInfo = node.debugInfo;
2037
- }
2006
+ const debugInfo: null | ReactDebugInfo = node.debugInfo;
2007
if (debugInfo !== null) {
2008
forwardDebugInfo(request, task, debugInfo);
2009
}
2020
request: Request,
2021
task: Task,
2022
node: AsyncSequence,
2054
- cutOff: number,
2023
): void {
2024
const visited: Set<AsyncSequence> = new Set();
2057
- const awaitedNode = visitAsyncNode(request, task, node, cutOff, visited);
2025
+ const awaitedNode = visitAsyncNode(request, task, node, visited, task.time);
2026
if (awaitedNode !== null) {
2027
// Nothing in user space (unfiltered stack) awaited this.
2060
- if (awaitedNode.end < 0) {
2061
- // If this was I/O directly without a Promise, then it means that some custom Thenable
2062
- // called our ping directly and not from a native .then(). We use the current ping time
2063
- // as the end time and treat it as an await with no stack.
2064
- // TODO: If this I/O is recurring then we really should have different entries for
2065
- // each occurrence. Right now we'll only track the first time it is invoked.
2066
- awaitedNode.end = performance.now();
2067
- }
2028
serializeIONode(request, awaitedNode);
2029
request.pendingChunks++;
2030
// We log the environment at the time when we ping which may be later than what the
2031
// environment was when we actually started awaiting.
2032
const env = (0, request.environmentName)();
2033
// If we don't have any thing awaited, the time we started awaiting was internal
2074
- // when we yielded after rendering. The cutOff time is basically that.
2075
- const awaitStartTime = cutOff;
2076
- // If the end time finished before we started, it could've been a cached thing so
2077
- // we clamp it to the cutOff time. Effectively leading to a zero-time await.
2078
- const awaitEndTime = awaitedNode.end < cutOff ? cutOff : awaitedNode.end;
2079
- emitTimingChunk(request, task.id, awaitStartTime);
2034
+ // when we yielded after rendering. The current task time is basically that.
2035
emitDebugChunk(request, task.id, {
2036
awaited: ((awaitedNode: any): ReactIOInfo), // This is deduped by this reference.
2037
env: env,
2038
});
2084
- emitTimingChunk(request, task.id, awaitEndTime);
2039
+ markOperationEndTime(request, task, awaitedNode.end);
2040
}
2041
}
2042
2047
if (enableAsyncDebugInfo) {
2048
const sequence = getCurrentAsyncSequence();
2049
if (sequence !== null) {
2095
- emitAsyncSequence(request, task, sequence, task.time);
2050
+ emitAsyncSequence(request, task, sequence);
2051
}
2052
}
2053
}
4250
debugInfo: ReactDebugInfo,
4251
) {
4252
const id = task.id;
4298
- const minimumTime =
4299
- enableProfilerTimer && enableComponentPerformanceTrack ? task.time : 0;
4253
for (let i = 0; i < debugInfo.length; i++) {
4254
const info = debugInfo[i];
4255
if (typeof info.time === 'number') {
4256
// When forwarding time we need to ensure to convert it to the time space of the payload.
4257
// We clamp the time to the starting render of the current component. It's as if it took
4258
// no time to render and await if we reuse cached content.
4306
- emitTimingChunk(
4307
- request,
4308
- id,
4309
- info.time < minimumTime ? minimumTime : info.time,
4310
- );
4259
+ markOperationEndTime(request, task, info.time);
4260
} else {
4261
if (typeof info.name === 'string') {
4262
// We outline this model eagerly so that we can refer to by reference as an owner.
4333
request.completedRegularChunks.push(processedChunk);
4334
}
4335
4336
+function advanceTaskTime(
4337
+ request: Request,
4338
+ task: Task,
4339
+ timestamp: number,
4340
+): void {
4341
+ if (!enableProfilerTimer || !enableComponentPerformanceTrack) {
4342
+ return;
4343
+ }
4344
+ // Emits a timing chunk, if the new timestamp is higher than the previous timestamp of this task.
4345
+ if (timestamp > task.time) {
4346
+ emitTimingChunk(request, task.id, timestamp);
4347
+ task.time = timestamp;
4348
+ } else if (!task.timed) {
4349
+ // If it wasn't timed before, e.g. an outlined object, we need to emit the first timestamp and
4350
+ // it is now timed.
4351
+ emitTimingChunk(request, task.id, task.time);
4352
+ }
4353
+ task.timed = true;
4354
+}
4355
+
4356
+function markOperationEndTime(request: Request, task: Task, timestamp: number) {
4357
+ if (!enableProfilerTimer || !enableComponentPerformanceTrack) {
4358
+ return;
4359
+ }
4360
+ // This is like advanceTaskTime() but always emits a timing chunk even if it doesn't advance.
4361
+ // This ensures that the end time of the previous entry isn't implied to be the start of the next one.
4362
+ if (timestamp > task.time) {
4363
+ emitTimingChunk(request, task.id, timestamp);
4364
+ task.time = timestamp;
4365
+ } else {
4366
+ emitTimingChunk(request, task.id, task.time);
4367
+ }
4368
+}
4369
+
4370
function emitChunk(
4371
request: Request,
4372
task: Task,
4458
function erroredTask(request: Request, task: Task, error: mixed): void {
4459
if (enableProfilerTimer && enableComponentPerformanceTrack) {
4460
if (task.timed) {
4478
- emitTimingChunk(request, task.id, (task.time = performance.now()));
4461
+ markOperationEndTime(request, task, performance.now());
4462
}
4463
}
4464
task.status = ERRORED;
4541
// We've finished rendering. Log the end time.
4542
if (enableProfilerTimer && enableComponentPerformanceTrack) {
4543
if (task.timed) {
4561
- emitTimingChunk(request, task.id, (task.time = performance.now()));
4544
+ markOperationEndTime(request, task, performance.now());
4545
}
4546
}
4547
4668
// Track when we aborted this task as its end time.
4669
if (enableProfilerTimer && enableComponentPerformanceTrack) {
4670
if (task.timed) {
4688
- emitTimingChunk(request, task.id, (task.time = performance.now()));
4671
+ markOperationEndTime(request, task, performance.now());
4672
}
4673
}
4674
// Instead of emitting an error per task.id, we emit a model that only