[Flight] Emit timestamps only in forwards advancing time in debug info #33482
Conversation
github-actions
bot
added
the
React Core Team
sebmarkbage
force-pushed
the
flattendebugtime
branch
from
8f47c23 to
edcb8c8
Compare
sebmarkbage
force-pushed
the
flattendebugtime
branch
from
edcb8c8 to
734ab71
Compare
|
Another possible representation would be: Where it's as if we re-awaited on 1. |
sebmarkbage
force-pushed
the
flattendebugtime
branch
4 times, most recently
from
d70bf88 to
f269fe7
Compare
| childTrackTime = childEndTime; | ||
| if (childEndTime > childTrackTime) { | ||
| childTrackTime = childEndTime; | ||
| } |
There was a problem hiding this comment.
This fixes the bug where there could end up being overlapping components when they should've been bumped to a parallel track.
(I do think this type of view is not good for this since any async micro-task can cause them to start overlapping and spawn too many parallel tracks. I have another view in mind for the future)
sebmarkbage
force-pushed
the
flattendebugtime
branch
from
89217f0 to
a889bb2
Compare
| 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; |
There was a problem hiding this comment.
This fixes the issue where the ThirdPartyComponent's delay call showed up as ThirdPartyComponent as the I/O's name instead of delay.
That was because if there's no explicit await then we picked the outer most Promise as the stack. That made no sense since that could just be the top component. We want the inner one and we hope that it has an "async stack" which includes higher up abstractions as well.
sebmarkbage
force-pushed
the
flattendebugtime
branch
2 times, most recently
from
fa5159a to
a902c81
Compare
| @@ -129,42 +147,50 @@ export function initAsyncDebugInfo(): void { | |||
| } | |||
| pendingOperations.set(asyncId, node); | |||
| }, | |||
| before(asyncId: number): void { | |||
There was a problem hiding this comment.
I was trying to avoid implementing this phase which requires a lot more look ups into the map all the time.
However, it simplifies a lot by just putting the resolution here. It avoids all the special cases of when we have unresolved promises inside the thing that's currently being resolved and special cases for lazily filling in the IO end time.
What could happen before is that the end time for a already resolved await would be marked after it finished its then callback. However, that means that any awaits started inside of the then would get cut out since they started before the previously emitted await.
|
I've added overlapping I/O to the How do we expect this to be flattened? It currently looks suboptimal, and inconsistent between the Requests track and the Components track: |
This adds some I/O to go get the third party thing to test how it overlaps. With #33482, this is what it looks like. The await gets cut off when the third party component starts rendering. I.e. after the latency to start. <img width="735" alt="Screenshot 2025-06-08 at 5 42 46 PM" src="https://github.com/user-attachments/assets/f68d9a84-05a1-4125-b3f0-8f3e4eaaa5c1" /> This doesn't fully simulate everything because it should actually also simulate each chunk of the stream coming back too. We could wrap the ReadableStream to simulate that. In that scenario, it would probably get some awaits on the chunks at the end too.
This is tricky because there can be parallel visits and really we should probably generate a list, sort and then emit the sorted list.
Only count something as contributing to the children end time if it was actually logged This excludes timing of promises that we didn't log an await for such as microtasks. Avoids bumping too many parallel levels.
promiseResolve, for already resolved promises, is invoked at the end of its execution phase. That means that any awaits that happen inside would have their start time below the end time which cuts them off.
``` -1..........-2.....------ ---3....................- ```
sebmarkbage
force-pushed
the
flattendebugtime
branch
from
f3afbd6 to
e26fa0d
Compare
|
It's expected to be suboptimal and very inconsistent when making small changes to the order. The Requests are never flattened but they can be excluded if the await started before the last await and then its I/O is excluded too. It's similar to In this case we could help this by collecting etnries before we advance the task time to include more but it shouldn't be necessary if they're not part of the waterfall. But this is still not showing what I'd expect because I think we should've started by visiting the "twice" first. However, there's a big difference between returning a promise and using an explicit It's also possible for the awaits to have different time spans than the Requests. Because their microtasks that unblock them can be blocked by other CPU work. So it's often you'd see an await end later than the Request. However not this much when there's nothing else going on. I think the end time of the "10ms" one is unexpected. Because while the end time of the outer await will be at the 40ms mark, what we're logging is the inner await which would end earlier. I'd expect us to log 10ms and then leave it blank for the remaining 10ms (which is ofc also suboptimal). |
|
Other than just the general inconsistencies that need follow ups. I think the main flaw was that an await that don't get a resolve before the begin phase would use its own start time as the end. It's actually not quite right because there seems to be possible to get a sequence where begin happens first even though it was delayed. Also, if the end time is the same as the current time, then we don't emit another timestamp after which would then use the next time stamp as the implicit end. We need to always emit a time stamp after the await to get an end time. We solve both these issues by just using the begin time as the end time of awaits. |
sebmarkbage
force-pushed
the
flattendebugtime
branch
from
6eda72c to
b0943c2
Compare
advanceTaskTime should be used before an operation to advance time before emitting that operation. markOperationEndTime should be used as its own marker after an operation. This needs to always be emitted even if it doesn't advance time.
sebmarkbage
force-pushed
the
flattendebugtime
branch
from
b0943c2 to
35719f2
Compare
An async function's last piece of code doesn't have any way to trace it back to the last await it was waiting for inside the body. Instead we guess this from whatever executed last.
sebmarkbage
force-pushed
the
flattendebugtime
branch
from
420f5ab to
0090784
Compare
|
Ok, I figured out a way to workaround the lack of await. The last piece of code inside an async function runs in the execution of the async function Promise itself. If you did this in user space, there would have to be another Promise around there but the internal V8 thing doesn't do that. Unfortunately, this means that there's no meta data about what that scope was depending on. Its trigger is whatever called the async function and not the await inside of it. My hacky workaround is to track whatever executed last and assume that is what ultimately unblocked the next task. It's not flawless but it's something. Now we can track that the returning of the first promise was blocked on the second promise. Therefore, now we consistently print the long blocking period first and then a zero-width period since the second returned promise was already resolved by the time we got there. 
|
…itted This lets us include zero width entries for parallel things that weren't blocking but might still be interesting.
|
I also went back to making the cut off for whether to include an await, the time stamp at the start of the sequence instead of the one that's updating as we go. That way we can include all the awaits inside this component. Those awaits are now zero width. 
|
We visit all the previous nodes before making any decisions about what to include so we potentially visit a lot of nodes over and over. We can optimize a bit by just stopping for anything that finished before the request start.
| [ | ||
| "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, | ||
| ], |
There was a problem hiding this comment.
This is missing the stack frames for delayTrice and Bar. Is this an accepted limitation or a bug?
There was a problem hiding this comment.
This is a limitation of async stacks in V8. It essentially resumes from the await and since there's no await here, it can't resume the async stack. So unfortunately we're stuck with it unless we disable them in V8 and then reimplement them ourselves by stitching together stacks from the async hooks. Not worth it.
Co-authored-by: Hendrik Liebau <[email protected]>
Stacked on #33482. There's a flaw with getting information from the execution context of the ping. For the soft-deprecated "throw a promise" technique, this is a bit unreliable because you could in theory throw the same one multiple times. Similarly, a more fundamental flaw with that API is that it doesn't allow for tracking the information of Promises that are already synchronously able to resolve. This stops tracking the async debug info in the case of throwing a Promise and only when you render a Promise. That means some loss of data but we should just warn for throwing a Promise anyway. Instead, this also adds support for tracking `use()`d thenables and forwarding `_debugInfo` from then. This is done by extracting the info from the Promise after the fact instead of in the resolve so that it only happens once at the end after the pings are done. This also supports passing the same Promise in multiple places and tracking the debug info at each location, even if it was already instrumented with a synchronous value by the time of the second use.
Previously you weren't guaranteed to have only advancing time entries, you could jump back in time, but now it omits unnecessary duplicates and clamps automatically if you emit a previous time entry to enforce forwards order only.
The reason I didn't do this originally is because
awaitcan jump in the order because we're trying to encode a graph into a flat timeline for simplicity of the protocol and consumers.This can effectively create two parallel sequences:
This can now be flattened to either:
Or:
Depending on which one we visit first. Regardless, information is lost.
I'd say that the second one is worse encoding of this scenario because it pretends that we weren't waiting for part of the timespan that we were. To solve this I think we should probably make
emitAsyncSequencecreate a temporary flat list and then sort it by start time before emitting.Although we weren't actually blocked since there was some CPU time that was able to proceed to get to 3. So maybe the second one is actually better. If we wanted that consistently we'd have to figure out what the intersection was.