Commit Graph

12 Commits

Author SHA1 Message Date
Sebastian Markbåge
2a911f27dd
[Flight] Send the awaited Promise to the client as additional debug information (#33592)
Stacked on #33588, #33589 and #33590.

This lets us automatically show the resolved value in the UI.

<img width="863" alt="Screenshot 2025-06-22 at 12 54 41 AM"
src="https://github.com/user-attachments/assets/a66d1d5e-0513-4767-910c-5c7169fc2df4"
/>

We can also show rejected I/O that may or may not have been handled with
the error message.

<img width="838" alt="Screenshot 2025-06-22 at 12 55 06 AM"
src="https://github.com/user-attachments/assets/e0a8b6ae-08ba-46d8-8cc5-efb60956a1d1"
/>

To get this working we need to keep the Promise around for longer so
that we can access it once we want to emit an async sequence. I do this
by storing the WeakRefs but to ensure that the Promise doesn't get
garbage collected, I keep a WeakMap of Promise to the Promise that it
depended on. This lets the VM still clean up any Promise chains that
have leaves that are cleaned up. So this makes Promises live until the
last Promise downstream is done. At that point we can go back up the
chain to read the values out of them.

Additionally, to get the best possible value we don't want to get a
Promise that's used by internals of a third-party function. We want the
value that the first party gets to observe. To do this I had to change
the logic for which "await" to use, to be the one that is the first
await that happened in user space. It's not enough that the await has
any first party at all on the stack - it has to be the very first frame.
This is a little sketchy because it relies on the `.then()` call or
`await` call not having any third party wrappers. But it gives the best
object since it hides all the internals. For example when you call
`fetch()` we now log that actual `Response` object.
2025-06-23 10:12:45 -04:00
Sebastian Markbåge
9cc74fec74
[Flight] Emit the time we awaited something inside a Server Component (#33402)
Stacked on #33400. 

<img width="1261" alt="Screenshot 2025-06-01 at 10 27 47 PM"
src="https://github.com/user-attachments/assets/a5a73ee2-49e0-4851-84ac-e0df6032efb5"
/>

This is emitted with the start/end time and stack of the "await". Which
may be different than the thing that started the I/O.

These awaits aren't quite as simple as just every await since you can
start a sequence in parallel there can actually be multiple overlapping
awaits and there can be CPU work interleaved with the await on the same
component.

```js
function getData() {
  await fetch(...);
  await fetch(...);
}
const promise = getData();
doWork();
await promise;
```

This has two "I/O" awaits but those are actually happening in parallel
with `doWork()`.

Since these also could have started before we started rendering this
sequence (e.g. a component) we have to clamp it so that we don't
consider awaits that start before the component.

What we're conceptually trying to convey is the time this component was
blocked due to that I/O resource. Whether it's blocked from completing
the last result or if it's blocked from issuing a waterfall request.
2025-06-03 17:29:41 -04:00
Sebastian Markbåge
157ac578de
[Flight] Include env in ReactAsyncInfo and ReactIOInfo (#33400)
Stacked on #33395.

This lets us keep track of which environment this was fetched and
awaited.

Currently the IO and await is in the same environment. It's just kept
when forwarded. Once we support forwarding information from a Promise
fetched from another environment and awaited in this environment then
the await can end up being in a different environment.

There's a question of when the await is inside Flight itself such as
when you return a promise fetched from another environment whether that
should mean that the await is in the current environment. I don't think
so since the original stack trace is the best stack trace. It's only if
you `await` it in user space in this environment first that this might
happen and even then it should only be considered if there wasn't a
better await earlier or if reading from the other environment was itself
I/O.

The timing of *when* we read `environmentName()` is a little interesting
here too.
2025-06-03 17:28:46 -04:00
Sebastian Markbåge
d8919a0a68
[Flight] Log "Server Requests" Track (#33394)
Stacked on #33392.

This adds another track to the Performance Track called `"Server
Requests"`.

<img width="1015" alt="Screenshot 2025-06-01 at 12 02 14 AM"
src="https://github.com/user-attachments/assets/c4d164c4-cfdf-4e14-9a87-3f011f65fd20"
/>

This logs the flat list of I/O awaited on by Server Components. There
will be other views that are more focused on what data blocks a specific
Component or Suspense boundary but this is just the list of all the I/O
basically so you can get an overview of those waterfalls without the
noise of all the Component trees and rendering. It's similar to what the
"Network" track is on the client.

I've been going back and forth on what to call this track but I went
with `"Server Requests"` for now. The idea is that the name should
communicate that this is something that happens on the server and is a
pairing with the `"Server Components"` track. Although we don't use that
feature, since it's missing granularity, it's also similar to "Server
Timings".
2025-06-03 15:31:12 -04:00
Sebastian Markbåge
62960c67c8
Run Component Track Logs in the console.createTask() of the Fiber (#32809)
Stacked on #32736.

That way you can find the owner stack of each component that rerendered
for context.

In addition to the JSX callsite tasks that we already track, I also
added tracking of the first `setState` call before rendering.

We then run the "Update" entries in that task. That way you can find the
callsite of the first setState and therefore the "cause" of a render
starting by selecting the "Update" track.

Unfortunately this is blocked on bugs in Chrome that makes it so that
these stacks are not reliable in the Performance tab. It basically just
doesn't work.
2025-04-29 22:17:17 -04:00
Sebastian Markbåge
cd4e4d7599
Use console.timeStamp instead of performance.measure in Component Performance Track (#32736)
This is a new extension that Chrome added to the existing
`console.timeStamp` similar to the extensions added to
`performance.measure`. This one should be significantly faster because
it doesn't have the extra object indirection, it doesn't return a
`PerformanceMeasure` entry and doesn't register itself with the global
system of entries.

I also use `performance.measure` in DEV for errors since we can attach
the error to the `properties` extension which doesn't exist for
`console.timeStamp`.

A downside of using this API is that there's no programmatic API for the
site itself to collect its own logs from React. Which the previous
allowed us to use the standard `performance.getEntries()` for. The
recommendation instead will be for the site to patch `console.timeStamp`
if it wants to collect measurements from React just like you're
recommended to patch `console.error` or `fetch` or whatever to collect
other instrumentation metrics.

This extension works in Chrome canary but it doesn't yet work fully in
Chrome stable. We might want to wait until it has propagated to Chrome
to stable. It should be in Chrome 136.
2025-04-29 21:40:10 -04:00
Sebastian Markbåge
50f00fd876
[Flight] Mark Errored Server Components (#31879)
This is similar to #31876 but for Server Components.

It marks them as errored and puts the error message in the Summary
properties.

<img width="1511" alt="Screenshot 2024-12-20 at 5 05 35 PM"
src="https://github.com/user-attachments/assets/92f11e42-0e23-41c7-bfd4-09effb25e024"
/>

This only looks at the current chunk for rejections. That means that
there might still be promises deeper that rejected but it's only the
immediate return value of the Server Component that's considered a
rejection of the component itself.
2024-12-28 02:02:16 -05:00
Sebastian Markbåge
54e86bd0d0
[Flight] Color and badge non-primary environments (#31738)
Stacked on #31737.

<img width="987" alt="Screenshot 2024-12-11 at 8 41 15 PM"
src="https://github.com/user-attachments/assets/438379a9-0138-4d02-a53a-419402839558"
/>

When mixing environments (like "use cache" or third party RSC) it's
useful to color and badge those components differently to differentiate.

I'm not putting them in separate tracks because when they do actually
execute, like cache misses or third party RSCs, they behave like they're
part of the same tree.
2024-12-16 13:39:19 -05:00
Sebastian Markbåge
bdf187174d
[Flight] Emit Deduped Server Components Marker (#31737)
Stacked on #31736.

<img width="1223" alt="Screenshot 2024-12-11 at 8 21 12 PM"
src="https://github.com/user-attachments/assets/a7cbc04b-c831-476b-aa2f-baddec9461c9"
/>

This emits a placeholder when we're deduping a component. This starts
when the parent's self time ends, where we would've started rendering
this component if it wasn't already started. The end time is when the
actual render ends since the parent is also blocked by it.
2024-12-16 13:16:53 -05:00
Sebastian Markbåge
07facb52d3
[Flight] Sort Server Components Track Group ahead of Client Scheduler/Components Tracks (#31736)
Stacked on #31735.

This ensures that Server Components Track comes first. Since it's
typically rendered first on the server for initial load and then flows
into scheduler and client components work. Also puts it closer to the
Network and further away from "Main" JS.

<img width="769" alt="Screenshot 2024-12-11 at 5 31 41 PM"
src="https://github.com/user-attachments/assets/7198db0f-075e-4a78-8ea4-3bfbf06727cb"
/>

Same trick as in #31615.
2024-12-16 12:39:15 -05:00
Sebastian Markbåge
031230d2e0
[Flight] Stack Parallel Components in Separate Tracks (#31735)
Stacked on https://github.com/facebook/react/pull/31729

<img width="1436" alt="Screenshot 2024-12-11 at 3 36 41 PM"
src="https://github.com/user-attachments/assets/0a201913-0076-4bbf-be18-8f1df6c58313"
/>

The Server Components visualization is currently a tree flame graph
where parent spans the child. This makes it equivalent to the Client
Components visualization.

However, since Server Components can be async and therefore parallel, we
need to do something when two children are executed in parallel. This PR
bumps parallel children into a separate track and then within that track
if that child has more children it can grow within that track.

I currently just cut off more than 10 parallel tracks.

Synchronous Server Components are still in sequence but it's unlikely
because even a simple microtasky Async Component is still parallel.

<img width="959" alt="Screenshot 2024-12-11 at 4 31 17 PM"
src="https://github.com/user-attachments/assets/5ad6a7f8-7fa0-46dc-af51-78caf9849176"
/>

I think this is probably not a very useful visualization for Server
Components but we can try it out.

I'm also going to try a different visualization where parent-child
relationship is horizontal and parallel vertical instead, but it might
not be possible to make that line up in this tool. It makes it a little
harder to see how much different components (including their children)
impact the overall tree. If that's the only visualization it's also
confusing why it's different dimensions than the Client Component
version.
2024-12-16 11:58:25 -05:00
Sebastian Markbåge
6928bf2f7c
[Flight] Log Server Component into Performance Track (#31729)
<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.
2024-12-12 14:03:18 -05:00