Invalid actualDuration+treeBaseDuration for hidden+suspended trees #14065

bvaughn · 2018-11-01T22:16:04Z

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 · 2018-11-01T22:23:12Z

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

sophiebits · 2018-11-01T22:30:33Z

packages/react-reconciler/src/ReactFiberBeginWork.js

@@ -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


bvaughn · 2018-11-02T20:27:49Z

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. 😄

acdlite · 2018-11-05T18:44:34Z

packages/react-reconciler/src/ReactFiberBeginWork.js

+          // Otherwise the profiler's onRender metrics will be off,
+          // and the DevTools Profiler flamegraph will visually break as well.
+          primaryChildFragment.treeBaseDuration =
+            currentPrimaryChild.treeBaseDuration;


Need to transfer from the siblings, too.

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

acdlite · 2018-11-05T18:47:11Z

packages/react-reconciler/src/ReactFiberBeginWork.js

+        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.


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

acdlite · 2018-11-05T18:50:46Z

packages/react-reconciler/src/ReactFiberScheduler.js

+        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);


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

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.

acdlite · 2018-11-05T18:53:45Z

packages/react-reconciler/src/ReactFiberScheduler.js

+
+          // 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.


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

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.

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

bvaughn · 2018-11-06T21:18:51Z

Rebased to account for improvements made in e9a2ec9 😄

acdlite · 2018-11-06T21:46:02Z

packages/react-reconciler/src/ReactFiberBeginWork.js

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


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.

…apper

…for all children

Initial suspended tree is no longer sync-committed before fallback UI, so tests needed to remove this assumption.

bvaughn · 2018-11-07T23:31:32Z

Rebasing one last time

…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.

bvaughn requested review from sebmarkbage and acdlite November 1, 2018 22:16

facebook-github-bot added the CLA Signed label Nov 1, 2018

bvaughn force-pushed the suspense-treeBaseDuration-fix branch from 95303e1 to 2a955dd Compare November 1, 2018 22:29

sophiebits reviewed Nov 1, 2018

View reviewed changes

bvaughn mentioned this pull request Nov 2, 2018

Support React.memo and timed-out Suspense trees facebook/react-devtools#1207

Merged

bvaughn force-pushed the suspense-treeBaseDuration-fix branch from d9ee3db to 9af69ea Compare November 2, 2018 21:27

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 changed the title ~~Fix invalid actualDuration and treeBaseDuration with hidden, suspended trees~~ Invalid actualDuration+treeBaseDuration for hidden+suspended trees Nov 2, 2018

acdlite requested changes Nov 5, 2018

View reviewed changes

bvaughn force-pushed the suspense-treeBaseDuration-fix branch from 85c5831 to 7be6879 Compare November 5, 2018 19:14

bvaughn requested review from acdlite and removed request for sebmarkbage November 5, 2018 23:15

bvaughn force-pushed the suspense-treeBaseDuration-fix branch 2 times, most recently from 37ab9da to b51501b Compare November 6, 2018 21:18

acdlite reviewed Nov 6, 2018

View reviewed changes

bvaughn requested a review from acdlite November 7, 2018 02:40

bvaughn force-pushed the suspense-treeBaseDuration-fix branch from 2b52374 to 103d9d2 Compare November 7, 2018 18:49

acdlite approved these changes Nov 7, 2018

View reviewed changes

Brian Vaughn added 7 commits November 7, 2018 15:31

Fixed invalid treeBaseDuration for hidden, suspended tree Fragment wr…

a5d97db

…apper

Include time spent rendering suspending component in actualDuration

325975e

Hacky fix for actualDuration in a suspended concurrent tree

dfa9a4e

Temp Fragment wrapper for hidden, suspended UI gets treeBaseDuration …

8c17479

…for all children

Moved actualDuration bubbling to completeUnitOfWork error branch

5fe6eda

Updated ReactSuspensePlaceholder to account for changes from e9a2ec9

aa2ef2f

Initial suspended tree is no longer sync-committed before fallback UI, so tests needed to remove this assumption.

Updated treeBaseTime bubbling behavior to handle update cases too

f64f3e2

bvaughn force-pushed the suspense-treeBaseDuration-fix branch from 103d9d2 to f64f3e2 Compare November 7, 2018 23:31

bvaughn merged commit 3ff2c7c into facebook:master Nov 7, 2018

bvaughn deleted the suspense-treeBaseDuration-fix branch November 7, 2018 23:46

gaearon mentioned this pull request Nov 13, 2018

Add 16.6.3 Changelog #14223

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Invalid actualDuration+treeBaseDuration for hidden+suspended trees #14065

Invalid actualDuration+treeBaseDuration for hidden+suspended trees #14065

bvaughn commented Nov 1, 2018 •

edited

sizebot commented Nov 1, 2018 •

edited

react-dom

react-art

react-test-renderer

react-reconciler

react-native-renderer

scheduler

sophiebits Nov 1, 2018

bvaughn commented Nov 2, 2018 •

edited

acdlite Nov 5, 2018

bvaughn Nov 5, 2018 •

edited

acdlite Nov 5, 2018

acdlite Nov 5, 2018

bvaughn Nov 5, 2018

acdlite Nov 5, 2018

bvaughn Nov 5, 2018 •

edited

bvaughn Nov 5, 2018

bvaughn commented Nov 6, 2018

acdlite Nov 6, 2018

bvaughn commented Nov 7, 2018

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

Invalid actualDuration+treeBaseDuration for hidden+suspended trees #14065

Invalid actualDuration+treeBaseDuration for hidden+suspended trees #14065

Conversation

bvaughn commented Nov 1, 2018 • edited

sizebot commented Nov 1, 2018 • edited

react-dom

react-art

react-test-renderer

react-reconciler

react-native-renderer

scheduler

Choose a reason for hiding this comment

bvaughn commented Nov 2, 2018 • edited

Choose a reason for hiding this comment

bvaughn Nov 5, 2018 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bvaughn Nov 5, 2018 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bvaughn commented Nov 6, 2018

Choose a reason for hiding this comment

bvaughn commented Nov 7, 2018

bvaughn commented Nov 1, 2018 •

edited

sizebot commented Nov 1, 2018 •

edited

bvaughn commented Nov 2, 2018 •

edited

bvaughn Nov 5, 2018 •

edited

bvaughn Nov 5, 2018 •

edited