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.
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.
We've known we've wanted this for many years and most of the
implementation was already done for Suspensey CSS. This waits to commit
until images have decoded by default or up to 500ms timeout (same as
suspensey fonts).
It only applies to Transitions, Retries (Suspense), Gesture Transitions
(flag) and Idle (doesn't exist). Sync updates just commit immediately.
`<img loading="lazy" src="..." />` opts out since you explicitly want it
to load lazily in that case.
`<img onLoad={...} src="..." />` also opts out since that implies you're
ok with managing your own reveal.
In the future, we may add an opt in e.g. `<img blocking="render"
src="..." />` that opts into longer timeouts and re-suspends even sync
updates. Perhaps also triggering error boundaries on errors.
The rollout for this would have to go in a major and we may have to
relax the default timeout to not delay too much by default. However, we
can also make this part of `enableViewTransition` so that if you opt-in
by using View Transitions then those animations will suspend on images.
That we could ship in a minor.
Stacked on #32815.
To be able to differentiate mounted subtrees from updated subtrees. This
adds a yellow entry above the component subtree that mounted. This is
added both to the render phase, mutation effect phase, layout effect
phase and passive effect phase.
<img width="962" alt="Screenshot 2025-04-03 at 10 41 02 PM"
src="https://github.com/user-attachments/assets/13777347-07e8-458c-9127-8675ef08b54f"
/>
Ideally we could probably give an annotation to the component instead of
adding a whole other line which is also a color that's kind of
distracting. However, not all components are included and keeping track
of which one is the first one below is kind of annoying. Adding a marker
to all components is kind of noisy. So this is a compromise. It's only
one per depth so it won't make it too deep even on larger trees.
If this is an unmount, those are added to the mutation effect phase for
the layout unmounts and passive unmount effect phase. Since these never
have a render, they're not in the render phase.
<img width="1010" alt="Screenshot 2025-04-03 at 11 05 57 PM"
src="https://github.com/user-attachments/assets/ab39f27e-13be-4281-94fa-9391bb293fd2"
/>
For showing / hiding `<Activity>` the terminology "Reconnect" and
"Disconnect" is used instead.
Rename "Suspended" commit to "Suspended on CSS" since that's the only
reason for this particular branch. This will not hold true because with
suspended images and with view transitions those can also be the reason.
So in the future we need to add those.
Only log "Blocked" in the components track if we yield for 3ms or
longer. It's common to have like 1-2ms yield times for various reasons
going on which is not worth the noise to consider "blocking".
Rename "Blocked" to "Update" in the Blocking/Transition tracks. This is
when a setState happens and with stack traces it's where you should look
for the stack trace of the setState. So we want to indicate that this is
the "Update".
I only added the "Blocked" part if we're blocked for more than 5ms
before we can start rendering - indicating that some other track was
working at the same time and preventing us from rendering.
This tracks commit phase errors and marks the component that errored as
red. These also get the errors attached to the entry.
<img width="1505" alt="Screenshot 2024-12-20 at 2 40 14 PM"
src="https://github.com/user-attachments/assets/cac3ead7-a024-4e33-ab27-2e95293c4299"
/>
In the render phase I just mark the Error Boundary that caught the
error. We don't have access to the actual error since it's locked behind
closures in the update queue. We could probably expose that someway.
<img width="949" alt="Screenshot 2024-12-20 at 1 49 05 PM"
src="https://github.com/user-attachments/assets/3032455d-d9f2-462b-9c07-7be23663ecd3"
/>
Follow ups:
Since the Error Boundary doesn't commit its attempted render, we don't
log those. If we did then maybe we should just mark the errored
component like I do for the commit phase. We could potentially walk the
list of errors and log the captured fibers and just log their entries as
children.
We could also potentially walk the uncommitted Fiber tree by stashing it
somewhere or even getting it from the alternate. This could be done on
Suspense boundaries too to track failed hydrations.
---------
Co-authored-by: Ricky <rickhanlonii@gmail.com>
A common source of performance problems is due to cascading renders from
calling `setState` in `useLayoutEffect` or `useEffect`. This marks the
entry from the update to when we start the render as red and `"Cascade"`
to highlight this.
<img width="964" alt="Screenshot 2024-12-19 at 10 54 59 PM"
src="https://github.com/user-attachments/assets/2bfa91e6-1dc1-4b7f-a659-50aaf2a97e83"
/>
In addition to this case, there's another case where you call `setState`
multiple times in the same event causing multiple renders. This might be
due to multiple `flushSync`, or spawned a microtasks from a
`useLayoutEffect`. In theory it could also be from a microtask scheduled
after the first `setState`. This one we can only detect if it's from an
event that has a `window.event` since otherwise it's hard to know if
we're still in the same event.
<img width="1210" alt="Screenshot 2024-12-19 at 11 38 44 PM"
src="https://github.com/user-attachments/assets/ee188bc4-8ebb-4e95-b5a5-4d724856c27d"
/>
I decided against making a ping in a microtask considered a cascade.
Because that should ideally be using the Suspense Optimization and so
wouldn't be considered multi-pass.
<img width="1284" alt="Screenshot 2024-12-19 at 11 07 30 PM"
src="https://github.com/user-attachments/assets/2d173750-a475-41a0-b6cf-679d15c4ca97"
/>
We might consider making the whole render phase and maybe commit phase
red but that should maybe reserved for actual errors. The "Blocked"
phase really represents the `setState` and so will have the stack trace
of the first update.
This is a follow up to #31752.
This keeps track in the commit phase whether this subtree was hydrated.
If it was, then we mark those components in the Components track as
green. Just like the phase itself is marked as green.
If the boundary client rendered we instead mark it as "errored" and its
children given the plain primary render color (blue). I also collect the
hydration error for this case so we can include its message in the
details view. (Unfortunately this doesn't support newlines atm.)
Most of the time this happens in separate commits for each boundary but
it is possible to force a client render in the same pass as a hydration.
Such as if an update flows into a boundary that has been put into
fallback state after it was initially attempted.
<img width="1487" alt="Screenshot 2024-12-18 at 12 06 54 AM"
src="https://github.com/user-attachments/assets/74c57291-4d11-414c-9751-3dac3285a89a"
/>
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.
This highlights the render phase as the tertiary color (green) when
we're render a hydration lane or offscreen lane.
I call the "Render" phase "Hydrated" instead in this case. For the
offscreen case we don't currently have a differentiation between
hydrated or activity. I just called that "Prepared". Even for the
hydration case where there's no discovered client rendered boundaries
it's more like it's preparing for an interaction rather than blocking
one. Where as for the other lanes the hydration might block something.
<img width="1173" alt="Screenshot 2024-12-12 at 11 23 14 PM"
src="https://github.com/user-attachments/assets/49ab1508-840f-4188-a085-18fe94b14187"
/>
In a follow up I'd like to color the components in the Components tree
green if they were hydrated but not the ones that was actually client
rendered e.g. due to a mismatch or forced client rendering so you can
tell the difference. Unfortunately, the current signals we have for this
get reset earlier in the commit phase than when we log these.
Another thing is that a failed hydration should probably be colored red
even though it ends up committing successfully. I.e. a recoverable
error.
This is a hack that ensures that all four lanes as visible whether you
have any tracks in them or not, and that they're in the priority order
within the Scheduler track group. We do want to show all even if they're
not used because it shows what options you're missing out on.
<img width="1035" alt="Screenshot 2024-11-22 at 12 38 30 PM"
src="https://github.com/user-attachments/assets/f30ab0b9-af5e-48ed-b042-138444352575">
In Chrome, the order of tracks within a group are determined by the
earliest start time. We add fake markers at start time zero in that
order eagerly. Ideally we could do this only once but because calls that
aren't recorded aren't considered for ordering purposes, we need to keep
adding these over and over again in case recording has just started. We
can't tell when recording starts.
Currently performance.mark() are in first insertion order but
performance.measure() are in the reverse order. I'm not sure that's
intentional. We can always add the 0 time slot even if it's in the past.
That's still considered for ordering purposes as long as the measurement
is recorded at the time we call it.
Stacked on #31552. Must be tested with `enableSiblingPrerendering` off
since the `use()` optimization is not on there yet.
This adds a span to the Components track when we yield in the middle of
the event loop. In this scenario, the "Render" span continues through
out the Scheduler track. So you can see that the Component itself might
not take a long time but yielding inside of it might.
This lets you see if something was blocking the React render loop while
yielding. If we're blocked 1ms or longer we log that as "Blocked".
If we're yielding due to suspending in the middle of the work loop we
log this as "Suspended".
<img width="837" alt="Screenshot 2024-11-16 at 1 15 14 PM"
src="https://github.com/user-attachments/assets/45a858ea-17e6-416c-af1a-78c126e033f3">
If the render doesn't commit because it restarts due to some other
prewarming or because some non-`use()` suspends, it doesn't have from
context components.
<img width="971" alt="Screenshot 2024-11-16 at 1 13 55 PM"
src="https://github.com/user-attachments/assets/a67724f8-702e-4e7d-9499-9ffc09541a61">
The `useActionState` path doesn't work yet because the `use()`
optimization doesn't work there for some reason. But the idea is that it
should mark the time that the component is blocked as Action instead of
Suspended.
When we suspend the render with delay, we won't do any more work until
we get some kind of another update/ping. It's because conceptually
something is suspended and then will update later. We need to highlight
this period to show why it's not doing any work. We fill the empty space
with "Suspended". This stops whenever the same lane group starts
rendering again. Clamped by the preceeding start time/event time/update
time.
<img width="902" alt="Screenshot 2024-11-15 at 1 01 29 PM"
src="https://github.com/user-attachments/assets/acf9dc9a-8fc3-4367-a8b0-d19f9c9eac73">
Ideally we would instead start the next render and suspend the work loop
at all places we suspend. In that mode this will instead show up as a
very long "Render" with a "Suspended" period instead highlighted in the
Components track as one component is suspended. We'll soon have that for
`use()` but not all updates so this covers the rest.
One issue with `useActionState` is that it is implemented as suspending
at the point of the `useActionState` which means that the period of the
Action shows up as a suspended render instead of as an Action which
happens for raw actions. This is not really how you conceptually think
about it so we need some special case for `useActionState`. In the
screenshot above, the first "Suspended" is actually awaiting an Action
and the second "Suspended" is awaiting the data from it.
This includes:
- `Interrupted Render`: Interrupted Renders (setState or ping at higher
priority)
- `Prewarm`: Suspended Renders outside a Suspense boundary
(RootSuspendedWithDelay/RootSuspendedAtTheShell)
- `Errored Render`: Render that errored somewhere in the tree (Fatal or
Not) (which may or may not be retried and then complete)
- `Teared Render`: Due to useSyncExternalStore not matching (which will
do another sync attempt)
Suspended Commit:
<img width="893" alt="Screenshot 2024-11-14 at 11 47 40 PM"
src="https://github.com/user-attachments/assets/b25a6a8b-a5e9-4d66-b325-57aef4bf9dad">
Errored with a second recovery attempt that also errors:
<img width="976" alt="Screenshot 2024-11-15 at 12 09 06 AM"
src="https://github.com/user-attachments/assets/9ce52cbb-b587-4f1e-8b67-e51d9073ae5b">
It's useful to quickly see where new events are kicking off new
rendering. This uses the new "warning" color (yellow) to do that. This
is to help distinguish it from the purple (secondary color) which is
used for the commit phase which is more of a follow up and it's often
that you have several rerenders within one event which makes it hard to
tell a part where it starts and event otherwise.
For the span marking between previous render within the same event and
the next setState, I use secondary-light (light purple) since it's kind
of still part of the same sequence at that point. It's usually a spawned
render (e.g. setState in useEffect or microtask) but it can also be
sequential flushSync.
I was bothered by that the event name is the only thing that's lower
case so I prefixed it with `Event: ` like the JS traces are.
<img width="1499" alt="Screenshot 2024-11-13 at 7 15 45 PM"
src="https://github.com/user-attachments/assets/0c81c810-6b5d-4fc7-9bc0-d15b53844ade">
It might be a little confusing why our track starts earlier than the JS
one below in the "Main Thread" flamegraph which looks the same. That's
because ours is the start of the event time which is when the click
happens where as the Main Thread one is when the JS event loop gets
around to processing the event.
When you schedule a microtask from render or effect and then call
setState (or ping) from there, the "event" is the event that React
scheduled (which will be a postMessage). The event time of this new
render will be before the last render finished.
We usually clamp these but in this scenario the update doesn't happen
while a render is happening. Causing overlapping events.
Before:
<img width="1229" alt="Screenshot 2024-11-12 at 11 01 30 PM"
src="https://github.com/user-attachments/assets/9652cf3b-b358-453c-b295-1239cbb15952">
Therefore when we finalize a render we need to store the end of the last
render so when we a new update comes in later with an event time earlier
than that, we know to clamp it.
There's also a special case here where when we enter the
`RootDidNotComplete` or `RootSuspendedWithDelay` case we neither leave
the root as in progress nor commit it. Those needs to finalize too.
Really this should be modeled as a suspended track that we haven't added
yet. That's the gap between "Blocked" and "message" below.
After:
<img width="1471" alt="Screenshot 2024-11-13 at 12 31 34 AM"
src="https://github.com/user-attachments/assets/b24f994e-9055-4b10-ad29-ad9b36302ffc">
I also fixed an issue where we may log the same event name multiple
times if we're rendering more than once in the same event. In this case
I just leave a blank trace between the last commit and the next update.
I also adding ignoring of the "message" event at all in these cases when
the event is from React's scheduling itself.
Fixes a bug.
We're supposed to not log "Waiting for Paint" if the passive effect
phase was forced since we weren't really waiting until the paint.
Instead we just log an empty string when we force it to still ensure
continuity.
We should always log the passive phase. This check was in the wrong
place.
Previously we were showing Components inside each lane track but that
meant that as soon as you expanded a lane you couldn't see the other
line so you couldn't get an overview over how well things were
scheduled.
This instead moves all the Components into a single top-level track and
renames the previous one to a "Scheduler" track group.
<img width="1352" alt="Screenshot 2024-11-12 at 8 26 05 PM"
src="https://github.com/user-attachments/assets/590bc6d3-3540-4ee4-b474-5d733b8d8d8d">
That way you can get an overview over what React is working on first and
then right below see which Component is being worked on.
Ideally the "Scheduler" track would be always expanded since each Track
is always just a single row. Now you have to expand each lane to see the
labels but then you're wasting a lot of vertical real estate. There's
currently no option to create this with the Chrome performance.measure
extensions.
<img width="1277" alt="Screenshot 2024-11-12 at 8 26 16 PM"
src="https://github.com/user-attachments/assets/4fc39e35-10ec-4452-ad32-c1c2e6b5e1a8">
A slight behavior change here too is that I now mark the start of the
commit phase before the BeforeMutationEffect phase. This affects
`<Profiler>` too.
The named sequences are as follows:
Render -> Suspended or Throttled -> Commit -> Waiting for Paint ->
Remaining Effects
The Suspended phase is only logged if we delay the Commit due to CSS /
images.
The Throttled phase is only logged if we delay the commit due to the
Suspense throttling timer.
<img width="1246" alt="Screenshot 2024-09-20 at 9 14 23 PM"
src="https://github.com/user-attachments/assets/8d01f444-bb85-472b-9b42-6157d92c81b4">
I don't yet log render phases that don't complete. I think I also need
to special case renders that or don't commit after being suspended.
This tracks the current window.event.timeStamp the first time we
setState or call startTransition. For either the blocking track or
transition track. We can use this to show how long we were blocked by
other events or overhead from when the user interacted until we got
called into React.
Then we track the time we start awaiting a Promise returned from
startTransition. We can use this track how long we waited on an Action
to complete before setState was called.
Then finally we track when setState was called so we can track how long
we were blocked by other word before we could actually start rendering.
For a Transition this might be blocked by Blocking React render work.
We only log these once a subsequent render actually happened. If no
render was actually scheduled, then we don't log these. E.g. if an
isomorphic Action doesn't call startTransition there's no render so we
don't log it.
We only log the first event/update/transition even if multiple are
batched into it later. If multiple Actions are entangled they're all
treated as one until an update happens. If no update happens and all
entangled actions finish, we clear the transition so that the next time
a new sequence starts we can log it.
We also clamp these (start the track later) if they were scheduled
within a render/commit. Since we share a single track we don't want to
create overlapping tracks.
The purpose of this is not to show every event/action that happens but
to show a prelude to how long we were blocked before a render started.
So you can follow the first event to commit.
<img width="674" alt="Screenshot 2024-09-20 at 1 59 58 AM"
src="https://github.com/user-attachments/assets/151ba9e8-6b3c-4fa1-9f8d-e3602745eeb7">
I still need to add the rendering/suspended phases to the timeline which
why this screenshot has a gap.
<img width="993" alt="Screenshot 2024-09-20 at 12 50 27 AM"
src="https://github.com/user-attachments/assets/155b6675-b78a-4a22-a32b-212c15051074">
In this case it's a Form Action which started a render into the form
which then suspended on the action. The action then caused a refresh,
which interrupts with its own update that's blocked before rendering.
Suspended roots like this is interesting because we could in theory
start working on a different root in the meantime which makes this
timeline less linear.
Stacked on #30981. Same as #30967 but for effects.
This logs a tree of components using `performance.measure()`.
In addition to the previous render phase this logs one tree for each
commit phase:
- Mutation Phase
- Layout Effect
- Passive Unmounts
- Passive Mounts
I currently skip the Before Mutation phase since the snapshots are so
unusual it's not worth creating trees for those.
The mechanism is that I reuse the timings we track for
`enableProfilerCommitHooks`. I track first and last effect timestamp
within each component subtree. Then on the way up do we log the entry.
This means that we don't include overhead to find our way down to a
component and that we don't need to add any additional overhead by
reading timestamps.
To ensure that the entries get ordered correctly we need to ensure that
the start time of each parent is slightly before the inner one.
Stacked on #30960 and #30966. Behind the enableComponentPerformanceTrack
flag.
This is the first step of performance logging. This logs the start and
end time of a component render in the passive effect phase. We use the
data we're already tracking on components when the Profiler component or
DevTools is active in the Profiling or Dev builds. By backdating this
after committing we avoid adding more overhead in the hot path. By only
logging things that actually committed, we avoid the costly unwinding of
an interrupted render which was hard to maintain in earlier versions.
We already have the start time but we don't have the end time. That's
because `actualStartTime + actualDuration` isn't enough since
`actualDuration` counts the actual CPU time excluding yields and
suspending in the render.
Instead, we infer the end time to be the start time of the next sibling
or the complete time of the whole root if there are no more siblings. We
need to pass this down the passive effect tree. This will mean that any
overhead and yields are attributed to this component's span. In a follow
up, we'll need to start logging these yields to make it clear that this
is not part of the component's self-time.
In follow ups, I'll do the same for commit phases. We'll also need to
log more information about the phases in the top track. We'll also need
to filter out more components from the trees that we don't need to
highlight like the internal Offscreen components. It also needs polish
on colors etc.
Currently, I place the components into separate tracks depending on
which lane currently committed. That way you can see what was blocking
Transitions or Suspense etc. One problem that I've hit with the new
performance.measure extensions is that these tracks show up in the order
they're used which is not the order of priority that we use. Even when
you add fake markers they have to actually be within the performance run
since otherwise the calls are noops so it's not enough to do that once.
However, I think this visualization is actually not good because these
trees end up so large that you can't see any other lanes once you expand
one. Therefore, I think in a follow up I'll actually instead switch to a
model where Components is a single track regardless of lane since we
don't currently have overlap anyway. Then the description about what is
actually rendering can be separate lanes.
<img width="1512" alt="Screenshot 2024-09-15 at 10 55 55 PM"
src="https://github.com/user-attachments/assets/5ca3fa74-97ce-40c7-97f7-80c1dd7d6470">
<img width="1512" alt="Screenshot 2024-09-15 at 10 56 27 PM"
src="https://github.com/user-attachments/assets/557ad65b-4190-465f-843c-0bc6cbb9326d">
