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

Invalid actualDuration+treeBaseDuration for hidden+suspended trees #14065

Merged
merged 7 commits into from
Nov 7, 2018

Conversation

bvaughn
Copy link
Contributor

@bvaughn bvaughn commented Nov 1, 2018

While testing some of our new APIs in DevTools, I noticed that the profiler (both the API and the DevTools visual profiler) reported invalid actualDuration and treeBaseDuration values when suspending.

The treeBaseDuration was incorrect for the fallback commit. It only included the fallback subtree duration, when it should also include the time spent rendering the hidden subtree.

The actualDuration value was incorrect for both the fallback commit and the final, resolved commit. It didn't include time spent rendering the component that actually read from the cache (the one that threw).

  • Fixed treeBaseDuration by propagating its value from the suspended tree to the Fragment React temporarily wraps around it when showing the fallback UI.
  • Fixed actualDuration by recording elapsed profiler time in the event of an error.
  • Fixed actualDuration in concurrent mode by propagating the time spent rendering the suspending component to its parent.

Also updated ReactSuspensePlaceholder-test.internal to cover these new cases.

@sizebot
Copy link

sizebot commented Nov 1, 2018

Details of bundled changes.

Comparing: 5afa1c4...f64f3e2

react-dom

File Filesize Diff Gzip Diff Prev Size Current Size Prev Gzip Current Gzip ENV
react-dom.development.js +0.2% +0.1% 707.3 KB 708.8 KB 163.63 KB 163.87 KB UMD_DEV
react-dom.development.js +0.2% +0.1% 702.61 KB 704.11 KB 162.26 KB 162.5 KB NODE_DEV
ReactDOM-dev.js +0.2% +0.1% 723.34 KB 724.84 KB 163.39 KB 163.62 KB FB_WWW_DEV
react-dom.profiling.min.js +0.2% +0.2% 100.34 KB 100.57 KB 31.83 KB 31.91 KB NODE_PROFILING
ReactDOM-profiling.js +0.2% +0.3% 315.79 KB 316.36 KB 58.25 KB 58.42 KB FB_WWW_PROFILING
react-dom.profiling.min.js +0.2% +0.3% 100.25 KB 100.48 KB 32.38 KB 32.46 KB UMD_PROFILING

react-art

File Filesize Diff Gzip Diff Prev Size Current Size Prev Gzip Current Gzip ENV
react-art.development.js +0.3% +0.2% 494.44 KB 495.94 KB 109.26 KB 109.49 KB UMD_DEV
react-art.development.js +0.4% +0.2% 426.22 KB 427.72 KB 92.24 KB 92.46 KB NODE_DEV
ReactART-dev.js +0.3% +0.3% 433.36 KB 434.86 KB 91.13 KB 91.37 KB FB_WWW_DEV

react-test-renderer

File Filesize Diff Gzip Diff Prev Size Current Size Prev Gzip Current Gzip ENV
react-test-renderer.development.js +0.3% +0.2% 438.88 KB 440.38 KB 94.92 KB 95.15 KB UMD_DEV
react-test-renderer.development.js +0.3% +0.2% 434.1 KB 435.6 KB 93.78 KB 94.01 KB NODE_DEV
ReactTestRenderer-dev.js +0.3% +0.2% 441.43 KB 442.93 KB 92.98 KB 93.21 KB FB_WWW_DEV

react-reconciler

File Filesize Diff Gzip Diff Prev Size Current Size Prev Gzip Current Gzip ENV
react-reconciler.development.js +0.4% +0.3% 424.06 KB 425.56 KB 90.71 KB 90.94 KB NODE_DEV
react-reconciler-persistent.development.js +0.4% +0.3% 422.51 KB 424.01 KB 90.09 KB 90.31 KB NODE_DEV

react-native-renderer

File Filesize Diff Gzip Diff Prev Size Current Size Prev Gzip Current Gzip ENV
ReactNativeRenderer-dev.js +0.3% +0.2% 558.55 KB 560.05 KB 121.8 KB 122.04 KB RN_FB_DEV
ReactNativeRenderer-dev.js +0.3% +0.2% 558.25 KB 559.75 KB 121.71 KB 121.95 KB RN_OSS_DEV
ReactFabric-dev.js +0.3% +0.2% 548.87 KB 550.37 KB 119.31 KB 119.55 KB RN_FB_DEV
ReactFabric-dev.js +0.3% +0.2% 548.9 KB 550.4 KB 119.32 KB 119.56 KB RN_OSS_DEV
ReactNativeRenderer-profiling.js +0.2% +0.4% 229.44 KB 229.83 KB 40.14 KB 40.28 KB RN_OSS_PROFILING
ReactFabric-profiling.js +0.2% +0.4% 222.78 KB 223.17 KB 38.88 KB 39.03 KB RN_OSS_PROFILING
ReactNativeRenderer-profiling.js +0.2% +0.3% 244.24 KB 244.63 KB 43.22 KB 43.36 KB RN_FB_PROFILING
ReactFabric-profiling.js +0.2% +0.4% 222.74 KB 223.13 KB 38.87 KB 39.01 KB RN_FB_PROFILING

scheduler

File Filesize Diff Gzip Diff Prev Size Current Size Prev Gzip Current Gzip ENV
scheduler.development.js n/a n/a 0 B 19.17 KB 0 B 5.74 KB UMD_DEV
scheduler.production.min.js n/a n/a 0 B 3.16 KB 0 B 1.53 KB UMD_PROD

Generated by 🚫 dangerJS

@bvaughn bvaughn force-pushed the suspense-treeBaseDuration-fix branch from 95303e1 to 2a955dd Compare November 1, 2018 22:29
@@ -753,7 +753,7 @@ function mountLazyComponent(
) {
if (_current !== null) {
// An lazy component only mounts if it suspended inside a non-
// concurrent tree, in an inconsistent state. We want to tree it like
Copy link
Collaborator

Choose a reason for hiding this comment

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

🌳

@bvaughn
Copy link
Contributor Author

bvaughn commented Nov 2, 2018

I've updated my new test to cover actualDuration too.

Are there any special concurrent rendering cases that I'm overlooking? Initially, it looks like the actualDuration is still a little off for concurrent mode– since it doesn't propagate the time spent rendering the component that throws. Not sure yet how easy this would be to detect and handle (or how important it is to get exactly right).

It looks like resetChildExpirationTime() isn't being called in concurrent mode, so actualDuration is "wrong" for the suspending render. I could "fix" this by propagating actualDuration in the renderRoot() catch, but this seems a bit sketchy and it would break sync mode (where resetChildExpirationTime() does get called) so I'm unsure of the best way forward at the moment.

I'm going to add a hacky fix for this as a conversation start, @acdlite. We can talk more about a better fix when you get a chance to look at this PR. 😄

@bvaughn bvaughn force-pushed the suspense-treeBaseDuration-fix branch from d9ee3db to 9af69ea Compare November 2, 2018 21:27
@bvaughn bvaughn changed the title Fixed invalid treeBaseDuration for Fragment wrapper around hidden, suspended tree Fix invalid actualDuration and treeBaseDuration with hidden, suspended trees Nov 2, 2018
@bvaughn bvaughn changed the title Fix invalid actualDuration and treeBaseDuration with hidden, suspended trees Invalid actualDuration+treeBaseDuration for hidden+suspended trees Nov 2, 2018
// Otherwise the profiler's onRender metrics will be off,
// and the DevTools Profiler flamegraph will visually break as well.
primaryChildFragment.treeBaseDuration =
currentPrimaryChild.treeBaseDuration;
Copy link
Collaborator

Choose a reason for hiding this comment

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

Need to transfer from the siblings, too.

Copy link
Contributor Author

@bvaughn bvaughn Nov 5, 2018

Choose a reason for hiding this comment

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

Good catch. Fixed and updated tests to cover this via 7be6879

if (enableProfilerTimer && workInProgress.mode & ProfileMode) {
// Fiber treeBaseDuration must be at least as large as the sum of children treeBaseDurations.
// Otherwise the profiler's onRender metrics will be off,
// and the DevTools Profiler flamegraph will visually break as well.
Copy link
Collaborator

Choose a reason for hiding this comment

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

Could you rewrite this comment in terms of what it means semantically instead of what will break if it goes wrong?

"treeBaseDuration is the sum of all the children durations" would be sufficient

if (enableProfilerTimer && nextUnitOfWork.mode & ProfileMode) {
// Record the time spent rendering before an error was thrown.
// This avoids inaccurate Profiler durations in the case of a suspended render.
stopProfilerTimerIfRunningAndRecordDelta(nextUnitOfWork, true);
Copy link
Collaborator

Choose a reason for hiding this comment

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

This gets called again in completeUnitOfWork, with no work in between. Seems wrong?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I don't think so, because completeUnitOfWork also calls startProfilerTimer before it starts working on the complete phase.

This clears out the previous timer, erasing any time spent in the "begin" phase. That's what we're recording here.


// HACK Also propagate actualDuration for the time spent in the fiber that errored.
// This avoids inaccurate Profiler durations in the case of a suspended render.
// This happens automatically for sync renders, because of resetChildExpirationTime.
Copy link
Collaborator

Choose a reason for hiding this comment

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

Suggested alternative: bubble this in completeUnitOfWork, where resetChildExpirationTime would normally go for a completed fiber.

Copy link
Contributor Author

@bvaughn bvaughn Nov 5, 2018

Choose a reason for hiding this comment

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

We already have a similar bubbling there to ensure that actualDuration bubbles all the way up to the Suspense component (or error boundary).

I think it's tricky to propagate this specific value (from the fiber that threw) in completeUnitOfWork without counting it too many times (since we unwind and process ancestors between the fiber that throws and either Suspense or an error boundary).

We know we've reached the ancestor boundary when next != null but...I'm not sure of a heuristic to only update for the fiber that threw. Conceptually, it feels like the right place to do this is where we catch.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Scratch that, I misunderstood your initial suggestion. You're right!

@bvaughn bvaughn force-pushed the suspense-treeBaseDuration-fix branch from 85c5831 to 7be6879 Compare November 5, 2018 19:14
@bvaughn bvaughn requested review from acdlite and removed request for sebmarkbage November 5, 2018 23:15
@bvaughn bvaughn force-pushed the suspense-treeBaseDuration-fix branch 2 times, most recently from 37ab9da to b51501b Compare November 6, 2018 21:18
@bvaughn
Copy link
Contributor Author

bvaughn commented Nov 6, 2018

Rebased to account for improvements made in e9a2ec9 😄

@@ -1246,6 +1251,18 @@ function updateSuspenseComponent(
NoWork,
null,
);

Copy link
Collaborator

Choose a reason for hiding this comment

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

Suggested comment:

Because primaryChildFragment is a new fiber that we're inserting as the parent of a new tree, we need to set its treeBaseDuration.

@bvaughn bvaughn requested a review from acdlite November 7, 2018 02:40
@bvaughn bvaughn force-pushed the suspense-treeBaseDuration-fix branch from 2b52374 to 103d9d2 Compare November 7, 2018 18:49
@bvaughn bvaughn force-pushed the suspense-treeBaseDuration-fix branch from 103d9d2 to f64f3e2 Compare November 7, 2018 23:31
@bvaughn
Copy link
Contributor Author

bvaughn commented Nov 7, 2018

Rebasing one last time

@bvaughn bvaughn merged commit 3ff2c7c into facebook:master Nov 7, 2018
@bvaughn bvaughn deleted the suspense-treeBaseDuration-fix branch November 7, 2018 23:46
@gaearon gaearon mentioned this pull request Nov 13, 2018
jetoneza pushed a commit to jetoneza/react that referenced this pull request Jan 23, 2019
…acebook#14065)

* Fixed `treeBaseDuration` by propagating its value from the suspended tree to the Fragment React temporarily wraps around it when showing the fallback UI.
* Fixed `actualDuration` by recording elapsed profiler time in the event of an error.
* Fixed `actualDuration` in concurrent mode by propagating the time spent rendering the suspending component to its parent.

Also updated ReactSuspensePlaceholder-test.internal to cover these new cases.
n8schloss pushed a commit to n8schloss/react that referenced this pull request Jan 31, 2019
…acebook#14065)

* Fixed `treeBaseDuration` by propagating its value from the suspended tree to the Fragment React temporarily wraps around it when showing the fallback UI.
* Fixed `actualDuration` by recording elapsed profiler time in the event of an error.
* Fixed `actualDuration` in concurrent mode by propagating the time spent rendering the suspending component to its parent.

Also updated ReactSuspensePlaceholder-test.internal to cover these new cases.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants