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

Reset profiler timer correctly after errors #13123

Merged

Conversation

bvaughn
Copy link
Contributor

@bvaughn bvaughn commented Jun 28, 2018

I discovered a couple of problems with the profiler timer "unwinding" behavior while testing the DevTools profiler.

It's probably worth noting that the first issue below was the result of #13058, but the other two are present when using the unstable_Profiler component (even without the root-profiling changes from #13058).

1: An error while profiling the host root

When the DevTools hook is present, host roots are automatically opted into profiling mode in order to support the DevTools profiler UI.

However, in the event of an error, the in-progress root is just nulled out without its render timer being stopped. In DEV mode, this will cause the subsequent render to warn about a non-empty stack.

I think the most straight forward solution here is to just add an explicit, DEV-only reset method (similar to what we do in ReactFiberStack). See commit a94b1b7.

2: Failures during "complete" phase

React Native does special View/Text nesting validation during the "complete" phase. If this fails, our unwinding logic previously recorded the elapsed duration twice– once at the start of the "complete" phase (before the error) and once while unwinding (after the error).

I've updated the noop renderer to support triggering this behavior intentionally, and I've added a new test for it as well. Initially, I tried tracking completion in the scheduler but this felt hacky. I think the best solution here is to move the actual time recording to the end of completeWork so that it won't be called twice in the event of an error. See commit 0b40c11.

3: Interleaved batched and yielded async work

There is one additional case in which the profiler stack isn't being emptied correctly:

  1. Batched work on one root is completed, but yields before committing.
  2. Async work on another root begins and yields before completing.
  3. Work on the initial, batched root is committed.

At this point, the profiler's DEV fiber stack contains the in-progress fibers (from the yielded async render), so we shouldn't assert that the stack is empty. The in-progress time measurements for the yielded fibers are also incorrect because they include the time spent finishing up the batched commit.

I believe the appropriate way to fix the first issue is to only check for an empty stack when we don't have any remaining, yielded async fibers. I think the best way to fix the second issue is to explicitly not count time spent processing batch work (or any sync work) against yielded async fibers. See commit 08febda.

Other changes

I also added a couple of new APIs to the noop renderer to support new tests:

  • The ability to trigger an error during the "complete" phase (to mimic RN's Text/View nesting logic) - ca91139
  • A new flushWithoutCommitting API to mimic React DOM's batched commits - 2aa075d

@bvaughn
Copy link
Contributor Author

bvaughn commented Jun 28, 2018

Should we add the ability to run our tests against a profiler+DevTools type bundle? I found the 2nd bug by doing that locally.

@pull-bot
Copy link

pull-bot commented Jun 28, 2018

ReactDOM: size: -0.2%, gzip: 0.0%

Details of bundled changes.

Comparing: 85fe4dd...def0b6c

react-dom

File Filesize Diff Gzip Diff Prev Size Current Size Prev Gzip Current Gzip ENV
react-dom.development.js +0.2% +0.3% 637.93 KB 639.16 KB 149.33 KB 149.71 KB UMD_DEV
react-dom.production.min.js -0.2% 0.0% 95.56 KB 95.4 KB 30.88 KB 30.89 KB UMD_PROD
react-dom.development.js +0.2% +0.2% 634.05 KB 635.29 KB 148.15 KB 148.52 KB NODE_DEV
react-dom.production.min.js -0.2% -0.0% 95.54 KB 95.38 KB 30.4 KB 30.4 KB NODE_PROD
ReactDOM-dev.js +0.2% +0.2% 640.7 KB 641.93 KB 146.54 KB 146.89 KB FB_WWW_DEV
ReactDOM-prod.js 🔺+0.1% 🔺+0.2% 274.73 KB 274.91 KB 51.46 KB 51.56 KB FB_WWW_PROD
react-dom.profiling.min.js -0.1% +0.2% 96.51 KB 96.43 KB 30.75 KB 30.79 KB NODE_PROFILING
ReactDOM-profiling.js +0.2% +0.4% 277.35 KB 277.9 KB 52.03 KB 52.22 KB FB_WWW_PROFILING

react-art

File Filesize Diff Gzip Diff Prev Size Current Size Prev Gzip Current Gzip ENV
react-art.development.js +0.3% +0.4% 422.62 KB 423.86 KB 95.02 KB 95.38 KB UMD_DEV
react-art.production.min.js -0.2% -0.1% 82.71 KB 82.58 KB 25.47 KB 25.46 KB UMD_PROD
react-art.development.js +0.3% +0.5% 354.6 KB 355.84 KB 77.89 KB 78.25 KB NODE_DEV
react-art.production.min.js -0.3% -0.0% 47.69 KB 47.56 KB 14.85 KB 14.84 KB NODE_PROD
ReactART-dev.js +0.4% +0.5% 344.08 KB 345.32 KB 72.73 KB 73.09 KB FB_WWW_DEV
ReactART-prod.js 🔺+0.1% 🔺+0.3% 145.96 KB 146.14 KB 24.79 KB 24.86 KB FB_WWW_PROD

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.5% 359.11 KB 360.35 KB 78.44 KB 78.8 KB UMD_DEV
react-test-renderer.production.min.js -0.3% 🔺+0.1% 48.58 KB 48.44 KB 14.93 KB 14.94 KB UMD_PROD
react-test-renderer.development.js +0.3% +0.5% 355.23 KB 356.47 KB 77.48 KB 77.84 KB NODE_DEV
react-test-renderer.production.min.js -0.3% 🔺+0.2% 48.29 KB 48.15 KB 14.74 KB 14.77 KB NODE_PROD
ReactTestRenderer-dev.js +0.3% +0.5% 359.13 KB 360.37 KB 76.33 KB 76.68 KB FB_WWW_DEV

react-noop-renderer

File Filesize Diff Gzip Diff Prev Size Current Size Prev Gzip Current Gzip ENV
react-noop-renderer.development.js +5.9% +3.9% 19.53 KB 20.69 KB 4.9 KB 5.09 KB NODE_DEV
react-noop-renderer.production.min.js 🔺+7.6% 🔺+5.9% 7.21 KB 7.76 KB 2.72 KB 2.88 KB NODE_PROD
react-noop-renderer-persistent.development.js +5.9% +3.9% 19.66 KB 20.81 KB 4.91 KB 5.1 KB NODE_DEV
react-noop-renderer-persistent.production.min.js 🔺+7.6% 🔺+5.8% 7.23 KB 7.78 KB 2.73 KB 2.89 KB NODE_PROD

react-reconciler

File Filesize Diff Gzip Diff Prev Size Current Size Prev Gzip Current Gzip ENV
react-reconciler.development.js +0.4% +0.5% 343.42 KB 344.66 KB 73.87 KB 74.23 KB NODE_DEV
react-reconciler.production.min.js -0.4% -0.3% 47.23 KB 47.06 KB 14.16 KB 14.12 KB NODE_PROD
react-reconciler-persistent.development.js +0.4% +0.5% 342.04 KB 343.27 KB 73.31 KB 73.67 KB NODE_DEV
react-reconciler-persistent.production.min.js -0.4% -0.3% 47.24 KB 47.07 KB 14.16 KB 14.12 KB NODE_PROD

react-native-renderer

File Filesize Diff Gzip Diff Prev Size Current Size Prev Gzip Current Gzip ENV
ReactNativeRenderer-dev.js +0.3% +0.4% 477.59 KB 478.83 KB 105.39 KB 105.76 KB RN_FB_DEV
ReactNativeRenderer-prod.js 🔺+0.6% 🔺+0.5% 209.82 KB 211.08 KB 36.69 KB 36.86 KB RN_FB_PROD
ReactNativeRenderer-dev.js +0.3% +0.4% 477.33 KB 478.56 KB 105.32 KB 105.7 KB RN_OSS_DEV
ReactNativeRenderer-prod.js 🔺+0.6% 🔺+0.6% 199.71 KB 200.96 KB 35.06 KB 35.28 KB RN_OSS_PROD
ReactFabric-dev.js +0.3% +0.4% 467.87 KB 469.11 KB 102.98 KB 103.36 KB RN_FB_DEV
ReactFabric-prod.js 🔺+0.1% 🔺+0.1% 191.97 KB 192.14 KB 33.64 KB 33.69 KB RN_FB_PROD
ReactFabric-dev.js +0.3% +0.4% 467.91 KB 469.14 KB 102.99 KB 103.37 KB RN_OSS_DEV
ReactFabric-prod.js 🔺+0.1% 🔺+0.1% 192 KB 192.18 KB 33.66 KB 33.71 KB RN_OSS_PROD
ReactNativeRenderer-profiling.js +0.8% +0.9% 202.38 KB 204.01 KB 35.65 KB 35.96 KB RN_OSS_PROFILING
ReactFabric-profiling.js +0.3% +0.5% 194.35 KB 194.92 KB 34.16 KB 34.31 KB RN_OSS_PROFILING
ReactNativeRenderer-profiling.js +0.8% +0.7% 212.46 KB 214.09 KB 37.29 KB 37.55 KB RN_FB_PROFILING
ReactFabric-profiling.js +0.3% +0.4% 194.31 KB 194.88 KB 34.14 KB 34.29 KB RN_FB_PROFILING

Generated by 🚫 dangerJS

@bvaughn
Copy link
Contributor Author

bvaughn commented Jul 3, 2018

The way batched roots and yielded async roots interleave is tricky. I'm posting PR #13145 as a temporary alternative to this PR that disables the auto-profiling behavior when DevTools are present. Once I've identified a fix for the 3rd case mentioned in the PR description, we can back that change out (assuming the PR has been merged). I just don't want this issue to block a potential FB sync.

@bvaughn
Copy link
Contributor Author

bvaughn commented Jul 5, 2018

(ce694c9) The profiler timer now differentiates between batched commits and in-progress async work. This required a two-part change:

  1. Don't count time spent working on a batched commit against yielded async work.
  2. Don't assert an empty stack after processing a batched commit (because there may be yielded async work)

This is kind of a hacky solution, and may have problems that I haven't thought of yet. I need to commit this so I can mentally clock out for a bit without worrying about it. I will think about it more when I'm back from PTO. In the meanwhile, input is welcome.

Edit: I realized after pushing the previous Map solution that I could fix the problem with a boolean, so I pushed an update (004538c).

@@ -1784,7 +1799,7 @@ function flushRoot(root: FiberRoot, expirationTime: ExpirationTime) {
performWorkOnRoot(root, expirationTime, false);
// Flush any sync work that was scheduled by lifecycles
performSyncWork();
finishRendering();
Copy link
Contributor Author

Choose a reason for hiding this comment

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

This change wasn't strictly necessary, but I noticed while tracing through that this finishRendering call was redundant, since performWork (called by performSyncWork) also calls finishRendering.

@@ -55,6 +56,7 @@ if (__DEV__) {
fiberStack = [];
}

let rootStartTimes: Map<FiberRoot | null, number> = new Map();
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 think I can replace this Map with a batchStartTime number field. The only case we really need to handle is processing a batch commit while async work is yielded. Other root changes will unwind the yielded work, which w already handled.

This was just a hacky first attempt to make tests pass. 😄

Brian Vaughn added 14 commits July 5, 2018 09:40
… async work

This was a two-part change:
1) Don't count time spent working on a batched commit against yielded async work.
2) Don't assert an empty stack after processing a batched commit (because there may be yielded async work)

This is kind of a hacky solution, and may have problems that I haven't thought of yet. I need to commit this so I can mentally clock out for a bit without worrying about it. I will think about it more when I'm back from PTO. In the meanwhile, input is welcome.
@bvaughn bvaughn force-pushed the reset-profiler-timer-fiber-stack-after-error branch from 004538c to def0b6c Compare July 5, 2018 16:43
@bvaughn bvaughn requested a review from flarnie July 5, 2018 16:45
@bvaughn
Copy link
Contributor Author

bvaughn commented Jul 5, 2018

Ok @acdlite and @flarnie ~ this PR should be ready for review now, I think.


function span(prop) {
return {type: 'span', children: [], prop};
}
Copy link
Contributor Author

Choose a reason for hiding this comment

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

This was dead code so I just removed it ^

@@ -1892,7 +1906,7 @@ function flushRoot(root: FiberRoot, expirationTime: ExpirationTime) {
performWorkOnRoot(root, expirationTime, true);
// Flush any sync work that was scheduled by lifecycles
performSyncWork();
finishRendering();
Copy link
Contributor Author

Choose a reason for hiding this comment

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

This was unnecessary, since performWork (called by performSyncWork) calls finishRendering at the end.

failInBeginPhase = true;
try {
fn();
} finally {
failInBeginPhase = false;
}
},

simulateErrorInHostConfigDuringCompletePhase(fn: () => void) {
Copy link
Contributor Author

Choose a reason for hiding this comment

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

This new method was necessary to write a test that mimicked RN's Text/View nesting validation.

// Certain renderers may error during this phase (i.e. ReactNative View/Text nesting validation).
// If an error occurs, we'll mark the time while unwinding.
// This simplifies the unwinding logic and ensures consistency.
recordElapsedActualRenderTime(workInProgress);
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Moving this to the end of completeWork was necessary to avoid double-popping in the event of an error (like RN's Text/View validation).

@@ -1817,7 +1831,7 @@ function performWork(minExpirationTime: ExpirationTime, dl: Deadline | null) {
findHighestPriorityRoot();

if (enableProfilerTimer) {
resumeActualRenderTimerIfPaused();
resumeActualRenderTimerIfPaused(minExpirationTime === Sync);
Copy link
Contributor Author

Choose a reason for hiding this comment

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

Letting the profiler timer know when it's processing sync work enables it to deduct that time from pending async work (by adding it onto the total pause time later). This ensures we don't count time spent processing a batch commit against yielded async work.


// Reset the DEV fiber stack in case we're profiling roots.
// (We do this for profiling bulds when DevTools is detected.)
resetActualRenderTimerStackAfterFatalErrorInDev();
Copy link
Contributor Author

Choose a reason for hiding this comment

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

This clears out the host root from the profiler timer's DEV-only fiberStack in the event of an error (which prevents us from incorrectly warning on the next render).

}

function resumeActualRenderTimerIfPaused(): void {
Copy link
Contributor Author

Choose a reason for hiding this comment

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

This method didn't really feel necessary, so I removed it.

@acdlite
Copy link
Collaborator

acdlite commented Jul 5, 2018

I don't think the fix for number 3 is correct (or maybe I don't fully understand it) but I'm going to merge it anyway to unblock this week's sync. Let's discuss once you get back from vacation.

@acdlite acdlite merged commit 9faf389 into facebook:master Jul 5, 2018
@bvaughn bvaughn deleted the reset-profiler-timer-fiber-stack-after-error branch July 5, 2018 22:17
@bvaughn
Copy link
Contributor Author

bvaughn commented Jul 5, 2018

Sure thing! Much appreciated. Happy to explain my train of thought for this one on Monday. I think it makes sense, but maybe you know of a use case I haven't considered. (Or maybe I just need to add better inline documentation...)

@bvaughn
Copy link
Contributor Author

bvaughn commented Jul 5, 2018

I don't think the fix for number 3 is correct (or maybe I don't fully understand it)

I see what you did there 😛

screen shot 2018-07-05 at 3 19 42 pm

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.

4 participants