Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Fiber] Log Component Renders to Custom Performance Track #30967

Merged
merged 8 commits into from
Sep 16, 2024

Conversation

sebmarkbage
Copy link
Collaborator

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.

Screenshot 2024-09-15 at 10 55 55 PM Screenshot 2024-09-15 at 10 56 27 PM

Copy link

vercel bot commented Sep 16, 2024

The latest updates on your projects. Learn more about Vercel for Git ↗︎

Name Status Preview Comments Updated (UTC)
react-compiler-playground ✅ Ready (Inspect) Visit Preview 💬 Add feedback Sep 16, 2024 3:16pm

@react-sizebot
Copy link

react-sizebot commented Sep 16, 2024

Comparing: ee1a403...d0ec308

Critical size changes

Includes critical production bundles, as well as any change greater than 2%:

Name +/- Base Current +/- gzip Base gzip Current gzip
oss-stable/react-dom/cjs/react-dom.production.js = 6.68 kB 6.68 kB +0.05% 1.82 kB 1.82 kB
oss-stable/react-dom/cjs/react-dom-client.production.js = 509.35 kB 509.31 kB = 91.10 kB 91.10 kB
oss-experimental/react-dom/cjs/react-dom.production.js = 6.69 kB 6.69 kB +0.05% 1.83 kB 1.83 kB
oss-experimental/react-dom/cjs/react-dom-client.production.js = 514.28 kB 514.28 kB = 91.82 kB 91.82 kB
facebook-www/ReactDOM-prod.classic.js = 604.85 kB 604.86 kB = 106.86 kB 106.86 kB
facebook-www/ReactDOM-prod.modern.js = 581.12 kB 581.16 kB = 103.01 kB 103.01 kB

Significant size changes

Includes any change greater than 0.2%:

Expand to show
Name +/- Base Current +/- gzip Base gzip Current gzip
oss-experimental/react-reconciler/cjs/react-reconciler.profiling.js +0.74% 408.75 kB 411.78 kB +0.95% 66.84 kB 67.48 kB
oss-experimental/react-dom/cjs/react-dom-profiling.profiling.js +0.54% 537.85 kB 540.75 kB +0.68% 95.82 kB 96.47 kB
oss-experimental/react-art/cjs/react-art.development.js +0.29% 558.32 kB 559.92 kB +0.51% 90.23 kB 90.69 kB
oss-experimental/react-reconciler/cjs/react-reconciler.development.js +0.25% 639.86 kB 641.49 kB +0.48% 102.73 kB 103.22 kB

Generated by 🚫 dangerJS against 2a1903d

OffscreenLane |
DeferredLane)
) {
return 'Idle';
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What do you thinking about splitting 'hidden' out for offscreen?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There's actually quite a lot of "Idle" work like hydration and the prerender. I think we'll actually put other lanes here too that end up suspending because that work weren't necessarily blocking anything - the suspended thing was.

There's too much nuance to communicate here but the one thing they have in common is that it's not directly connected to an outcome like a navigation. They're all warming up for some future work and so you shouldn't be too concerned about them taking a long time. They're red herrings.

…ssive phase

This lets us log all those nodes.

actualDuration includes anything in the subtree as well.

The parent path to a Profiler component won't have actualDuration set but
it'll instead have the Passive flag set which is used for onPostCommit.
We'll need this to know when the last component's end time is.
The endTime is defined as just the next sibling's start time or if this is
the terminal leaf then it is the complete time of the whole render.

It is not enough to use actualStartTime + actualDuration because that number
doesn't include yields. So this time is the time including any yields.
This way we can compute the end time of the next sibling.

In the case where DEV or DevTools is installed this is on everywhere anyway
but it is unfortunate that if you run Profiling build without a Profiler
this would track every component anyway.
* @emails react-core
* @jest-environment node
*/

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This mattered because without the node environment it didn't have performance.measure. However, I now feature test it too.

@sebmarkbage sebmarkbage merged commit f2df569 into facebook:main Sep 16, 2024
184 checks passed
github-actions bot pushed a commit that referenced this pull request Sep 16, 2024
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">

DiffTrain build for commit f2df569.
github-actions bot pushed a commit that referenced this pull request Sep 16, 2024
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">

DiffTrain build for [f2df569](f2df569)
sebmarkbage added a commit that referenced this pull request Sep 17, 2024
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.
github-actions bot pushed a commit that referenced this pull request Sep 17, 2024
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.

DiffTrain build for [e1c2090](e1c2090)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
CLA Signed React Core Team Opened by a member of the React Core Team
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants