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

Add ProfileRoot component for collecting new time metrics #12745

Merged
merged 72 commits into from May 10, 2018

Conversation

bvaughn
Copy link
Contributor

@bvaughn bvaughn commented May 4, 2018

Add a new component type, Profiler, that can be used to collect new render time metrics. Since this is a new, experimental API, it will be exported as React.unstable_Profiler initially.

Most of the functionality for this component has been added behind a feature flag, enableProfileModeMetrics. When the feature flag is disabled, the component will just render its children with no additional behavior. When the flag is enabled, React will also collect timing information and pass it to the onRender function (as described below).

This flag will be enabled for the DEV bundle in the future. A special profiling+production build will likely be created as well, in order to use these new metrics in production mode without impacting existing applications.

How is it used?

const Profiler = React.unstable_Profiler;

render(
  {/* Components not measured... */}
  <Profiler id="some identifier" onRender={loggingFunction}>
    {/* Components to be measured... */}
  </Profiler>
  {/* Components not measured... */}
);

Profiler can be declared anywhere within a React tree and can be nested to measure multiple components within the same tree.

The onRender callback is called each time the root renders. It receives the following parameters:

  • id: string - The id value of the Profiler tag that was measured.
  • phase: string - Either "mount" or "update" (depending on whether this root was newly mounted or has just been updated).
  • actualTime: number - Time spent rendering the Profiler and its descendants for the most recent "mount" or "update" render. 1
  • baseTime: number - Duration of the most recent render time for each individual component within the Profiler tree. 1

1: See below for more detailed information about what this time represents.

Timing metrics

Here is a review of the types of timing React is now capable of reporting:

User Timing API

Measures start/stop times for each component lifecycle.

  • Opt in mechanism: Feature flag (typically DEV mode only)
  • Scope: Tracked for all components in an app
  • How is it measured?
    • Start/stop times for each component lifecycle
    • Measured as a realtime graph
  • When is it recorded?
    • Realtime graph is recorded after each lifecycle call.
  • What does it tell us?
    • Flame graph paints a useful picture of how events (e.g. mouse clicks) tie together with rendering.

“Actual” render time (new)

Time spent rendering the Profiler and its descendants for the most recent render/update.

  • Opt in mechanism: Wrap a component with <Profiler>
  • Scope: Measured for descendants of Profiler only
  • How is it measured?
    • Start timer during “begin” phase, stop during “complete” phase
    • Paused (and accumulated) for scheduling/timing interruptions 2
    • Paused (and accumulated) for aborted renders (e.g. suspense)
  • When is it recorded?
    • A new snapshot is recorded each time a Profiler is re-rendered
  • What does it tell us?
    • How well does the subtree make use of shouldComponentUpdate for memoization?
    • The more this time decreases for update renders, the better the memoization.

“Base” render time (new)

Duration of the most recent render time for each individual component within the Profiler tree.

  • Opt in mechanism: Wrap a component with <Profiler>
  • Scope: Measured for descendants of Profiler only
  • How is it measured?
    • Measured for each fiber below a Profiler component.
    • Recorded during “begin” phase.
      • Times are not updated/recorded if a component skips render because of shouldComponentUpdate
      • (Descendant times are also not updated in that case)
    • Bubble up (summed) for the Profiler during “complete” phase
    • Total times logged for Profiler (not for individual fibers)
  • When is it recorded?
    • A new snapshot is recorded each time a Profiler is re-rendered
  • What does it tell us?
    • How expensive our render functions are in the worst case (no memoization).
    • Lower this number by reducing the work done in render.

2: Until "resume" behavior is implemented, interruptions will not accumulate time.

TODO

  • Guard new functionality behind a feature flag so it isn't included in e.g. production bundle
  • Add tests for new functionality
  • getComponentName (so flame graph labels will appear correctly)
  • ReactIs
  • Test renderer toJSON and toTree methods
  • Shallow renderer
  • DevTools (will be done with a follow up PR)

@gaearon
Copy link
Collaborator

gaearon commented May 4, 2018

A new snapshot is recorded each time a ProfileRoot is re-rendered

Does this include deep setStates inside of it?

@pull-bot
Copy link

pull-bot commented May 4, 2018

React: size: 🔺+0.9%, gzip: 🔺+0.6%

ReactDOM: size: 🔺+0.8%, gzip: 🔺+1.0%

Details of bundled changes.

Comparing: a9abd27...e3a2562

react

File Filesize Diff Gzip Diff Prev Size Current Size Prev Gzip Current Gzip ENV
react.development.js +0.6% +0.5% 55.43 KB 55.78 KB 15.23 KB 15.31 KB UMD_DEV
react.production.min.js 🔺+0.9% 🔺+0.6% 6.96 KB 7.03 KB 2.96 KB 2.98 KB UMD_PROD
react.development.js +0.8% +0.6% 46.07 KB 46.42 KB 12.87 KB 12.95 KB NODE_DEV
react.production.min.js 🔺+1.1% 🔺+0.7% 5.5 KB 5.56 KB 2.4 KB 2.42 KB NODE_PROD
React-dev.js +0.8% +0.6% 46.07 KB 46.42 KB 12.55 KB 12.63 KB FB_WWW_DEV
React-prod.js 🔺+0.9% 🔺+0.6% 13.38 KB 13.5 KB 3.71 KB 3.74 KB FB_WWW_PROD

react-dom

File Filesize Diff Gzip Diff Prev Size Current Size Prev Gzip Current Gzip ENV
react-dom.development.js +1.6% +1.5% 614.9 KB 624.98 KB 142.2 KB 144.29 KB UMD_DEV
react-dom.production.min.js 🔺+0.8% 🔺+1.0% 100.43 KB 101.28 KB 31.98 KB 32.3 KB UMD_PROD
react-dom.development.js +1.7% +1.6% 599.28 KB 609.35 KB 138.05 KB 140.2 KB NODE_DEV
react-dom.production.min.js 🔺+0.8% 🔺+0.8% 98.87 KB 99.71 KB 31.21 KB 31.46 KB NODE_PROD
react-dom-server.browser.development.js +0.2% +0.2% 101.34 KB 101.51 KB 26.45 KB 26.5 KB UMD_DEV
react-dom-server.browser.production.min.js 🔺+0.3% 🔺+0.3% 15.18 KB 15.23 KB 5.8 KB 5.82 KB UMD_PROD
react-dom-server.browser.development.js +0.2% +0.2% 90.64 KB 90.81 KB 24.19 KB 24.24 KB NODE_DEV
react-dom-server.browser.production.min.js 🔺+0.3% 🔺+0.3% 14.54 KB 14.59 KB 5.54 KB 5.56 KB NODE_PROD
react-dom-server.node.development.js +0.2% +0.2% 92.56 KB 92.73 KB 24.74 KB 24.79 KB NODE_DEV
react-dom-server.node.production.min.js 🔺+0.3% 🔺+0.3% 15.34 KB 15.39 KB 5.84 KB 5.86 KB NODE_PROD
ReactDOM-dev.js +1.7% +1.5% 623.75 KB 634.06 KB 140.84 KB 142.96 KB FB_WWW_DEV
ReactDOM-prod.js 🔺+2.5% 🔺+2.2% 285.74 KB 292.94 KB 52.25 KB 53.4 KB FB_WWW_PROD
ReactDOMServer-dev.js +0.2% +0.2% 94.11 KB 94.28 KB 24.03 KB 24.06 KB FB_WWW_DEV
ReactDOMServer-prod.js 🔺+0.3% 🔺+0.2% 31.6 KB 31.71 KB 7.76 KB 7.78 KB FB_WWW_PROD

react-art

File Filesize Diff Gzip Diff Prev Size Current Size Prev Gzip Current Gzip ENV
react-art.development.js +2.4% +2.3% 417.84 KB 427.92 KB 91.16 KB 93.23 KB UMD_DEV
react-art.production.min.js 🔺+0.9% 🔺+0.9% 90.76 KB 91.61 KB 27.63 KB 27.87 KB UMD_PROD
react-art.development.js +2.9% +2.9% 343.67 KB 353.75 KB 72.49 KB 74.6 KB NODE_DEV
react-art.production.min.js 🔺+1.5% 🔺+1.4% 55.28 KB 56.12 KB 16.92 KB 17.16 KB NODE_PROD
ReactART-dev.js +2.9% +2.9% 351.97 KB 362.28 KB 72.08 KB 74.2 KB FB_WWW_DEV
ReactART-prod.js 🔺+4.3% 🔺+4.2% 168.5 KB 175.71 KB 27.74 KB 28.91 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 +3.0% +2.9% 348.71 KB 359.17 KB 73.38 KB 75.52 KB UMD_DEV
react-test-renderer.production.min.js 🔺+1.8% 🔺+1.6% 54.91 KB 55.88 KB 16.72 KB 16.99 KB UMD_PROD
react-test-renderer.development.js +3.1% +3.1% 339.54 KB 349.99 KB 70.67 KB 72.84 KB NODE_DEV
react-test-renderer.production.min.js 🔺+1.8% 🔺+1.8% 54.14 KB 55.09 KB 16.3 KB 16.6 KB NODE_PROD
react-test-renderer-shallow.development.js +1.3% +1.1% 24.04 KB 24.35 KB 6.42 KB 6.5 KB UMD_DEV
react-test-renderer-shallow.production.min.js 🔺+0.7% 🔺+0.5% 7.16 KB 7.2 KB 2.35 KB 2.36 KB UMD_PROD
react-test-renderer-shallow.development.js +3.2% +3.2% 13.82 KB 14.25 KB 3.46 KB 3.57 KB NODE_DEV
react-test-renderer-shallow.production.min.js 🔺+3.2% 🔺+3.5% 6.92 KB 7.14 KB 2.26 KB 2.34 KB NODE_PROD
ReactTestRenderer-dev.js +3.1% +3.2% 348.07 KB 358.79 KB 70.31 KB 72.55 KB FB_WWW_DEV
ReactShallowRenderer-dev.js +3.0% +3.2% 14.52 KB 14.96 KB 3.58 KB 3.69 KB FB_WWW_DEV

react-reconciler

File Filesize Diff Gzip Diff Prev Size Current Size Prev Gzip Current Gzip ENV
react-reconciler.development.js +3.1% +3.2% 319.89 KB 329.96 KB 66.12 KB 68.23 KB NODE_DEV
react-reconciler.production.min.js 🔺+1.8% 🔺+1.3% 47.01 KB 47.85 KB 14.23 KB 14.42 KB NODE_PROD
react-reconciler-persistent.development.js +3.1% +3.1% 319.22 KB 329.24 KB 65.88 KB 67.94 KB NODE_DEV
react-reconciler-persistent.production.min.js 🔺+1.8% 🔺+1.1% 45.98 KB 46.8 KB 14.09 KB 14.24 KB NODE_PROD
react-reconciler-reflection.development.js +4.0% +3.0% 10.99 KB 11.42 KB 3.41 KB 3.52 KB NODE_DEV

react-is

File Filesize Diff Gzip Diff Prev Size Current Size Prev Gzip Current Gzip ENV
react-is.development.js +7.5% +4.2% 4.25 KB 4.58 KB 1.22 KB 1.27 KB UMD_DEV
react-is.production.min.js 🔺+6.3% 🔺+4.2% 1.74 KB 1.85 KB 742 B 773 B UMD_PROD
react-is.development.js +7.9% +4.1% 4.07 KB 4.39 KB 1.17 KB 1.22 KB NODE_DEV
react-is.production.min.js 🔺+7.2% 🔺+4.0% 1.68 KB 1.8 KB 680 B 707 B NODE_PROD
ReactIs-dev.js +7.8% +4.2% 4.13 KB 4.46 KB 1.19 KB 1.24 KB FB_WWW_DEV
ReactIs-prod.js 🔺+8.4% 🔺+4.2% 3.29 KB 3.57 KB 938 B 977 B FB_WWW_PROD

react-native-renderer

File Filesize Diff Gzip Diff Prev Size Current Size Prev Gzip Current Gzip ENV
ReactNativeRenderer-dev.js +2.2% +2.2% 459.69 KB 470 KB 98.35 KB 100.5 KB RN_FB_DEV
ReactNativeRenderer-prod.js 🔺+3.3% 🔺+3.5% 217.92 KB 225.13 KB 36.4 KB 37.67 KB RN_FB_PROD
ReactNativeRenderer-dev.js +2.2% +2.2% 459.44 KB 469.73 KB 98.29 KB 100.44 KB RN_OSS_DEV
ReactNativeRenderer-prod.js 🔺+1.0% 🔺+0.9% 217.14 KB 219.24 KB 36.27 KB 36.6 KB RN_OSS_PROD
ReactFabric-dev.js +2.3% +2.3% 442.1 KB 452.39 KB 93.95 KB 96.08 KB RN_FB_DEV
ReactFabric-prod.js 🔺+1.0% 🔺+1.0% 202.81 KB 204.88 KB 33.67 KB 34 KB RN_FB_PROD
ReactFabric-dev.js +2.3% +2.3% 442.13 KB 452.42 KB 93.96 KB 96.09 KB RN_OSS_DEV
ReactFabric-prod.js 🔺+1.0% 🔺+1.0% 202.85 KB 204.92 KB 33.69 KB 34.02 KB RN_OSS_PROD

Generated by 🚫 dangerJS

@bvaughn
Copy link
Contributor Author

bvaughn commented May 4, 2018

A new snapshot is recorded each time a ProfileRoot is re-rendered

Does this include deep setStates inside of it?

Yes, anything that re-renders the root. There are a few tests that touch on this in ReactProfileRoot-test.internal. If you think I missed any cases, let me know and I'll add more.

@gaearon
Copy link
Collaborator

gaearon commented May 4, 2018

Makes sense, just wanted to note that in external communication people generally don’t consider a deep rerender to “re-render a parent/root”. The fact that it’s structured this way is more of a Fiber architecture artefact.

I agree it’s not docs but this tripped me a little 🙂

@bvaughn
Copy link
Contributor Author

bvaughn commented May 4, 2018

Understand and agree.

Without this behavior though, it would not be possible to e.g. measure the cost of a setState update in the Header component below:

<Application>
  <ProfileRoot id="Header" callback="...">
    <Header />
  </ProfileRoot>
  <Body />
</Application>

Unless I've overlooked something. 😄

switch (finishedWork.tag) {
case Profiler: {
if (enableProfileModeMetrics) {
finishedWork.pendingProps.onRender.call(
Copy link
Collaborator

Choose a reason for hiding this comment

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

let onRender = finishedWork.memoizedProps.onRender;
onRender(...);

I think we should use memoizedProps.

https://github.com/bvaughn/react/blob/08a9b10328fdb243c3421f9e100acb8e0310f555/packages/react-reconciler/src/ReactFiberCommitWork.js#L244

Copy link
Contributor Author

@bvaughn bvaughn May 4, 2018

Choose a reason for hiding this comment

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

I'm curious- why?

Lint complains about that form (no-useless-call) but I can add an ignore rule if you prefer it.

Copy link
Collaborator

Choose a reason for hiding this comment

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

I think @sebmarkbage means we need memoizedProps, not pendingProps?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Oh, haha. I misread that 😄

Copy link
Collaborator

Choose a reason for hiding this comment

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

It’s two issues. We should use memoizedProps and avoid .call

Copy link
Contributor Author

@bvaughn bvaughn May 5, 2018

Choose a reason for hiding this comment

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

Already using memoized.

I'll remove .call - but I'd like to learn more about why it's good to avoid it in this case. 😄

}

// Never bail out early for Profilers.
// We always want to re-measure the subtree.
Copy link
Collaborator

Choose a reason for hiding this comment

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

This seems wrong. You want to measure the subtree only if there is pending work in the subtree. We shouldn't reconcile the children unless there are new props.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Maybe my wording is wrong?

This is not forcing children to re-render. It's just measuring the "cost" of re-rendering. If the tree bails out b'c of e.g. sCU then the "actual" render time is small, which is good.

Copy link
Collaborator

Choose a reason for hiding this comment

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

But why are you reconciling the children? You should only do that if the props have changed. Otherwise you should skip reconciling, which is what bailoutOnAlreadyFinishedWork does.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Gotcha.

I'll take another look at this this evening, after dinner. 👍


// Reset actualTime after successful commit.
// By default, we append to this time to account for errors and pauses.
finishedWork.stateNode = 0;
Copy link
Collaborator

Choose a reason for hiding this comment

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

I think Dan ran some performance tests that showed the stateNode should always use an object or null, so the hidden class is monomorphic, for performance reasons.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Oh? cc @gaearon

Copy link
Collaborator

Choose a reason for hiding this comment

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

It's not ideal but since we're already doing this for context I guess this doesn't make it worse.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

It's easy enough to add a wrapper object if that would be better in any way. (I actually had one earlier and removed it last minute.)

@@ -404,6 +421,20 @@ export default function<T, P, I, TI, HI, PI, C, CC, CX, PL>(
renderExpirationTime: ExpirationTime,
): Fiber | null {
const newProps = workInProgress.pendingProps;

if (enableProfileModeMetrics) {
if (workInProgress.mode & ProfileMode) {
Copy link
Collaborator

Choose a reason for hiding this comment

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

Can you move this resetExpirationTime in the scheduler? That's where we "bubble up" expiration time, which is conceptually similar.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Sure. No strong preference.

@@ -451,6 +468,12 @@ export default function<T, P, I, TI, HI, PI, C, CC, CX, PL>(
commitAttachRef(nextEffect);
}

if (enableProfileModeMetrics) {
if (effectTag & CommitProfile) {
Copy link
Collaborator

Choose a reason for hiding this comment

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

Can you reuse the Update effect type? I don't think we need a new tag here.

Copy link
Collaborator

Choose a reason for hiding this comment

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

Profiler is the only type of work that might have this effect, right?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Hm. Maybe. Not obvious to me why that would be an improvement.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Our comments got crossed.

Profiler is the only type of work that might have this effect, right?

Yes.

Copy link
Collaborator

@acdlite acdlite May 4, 2018

Choose a reason for hiding this comment

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

You're adding an extra check to every single unit of work. We already check for the Update effect.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

👍

@@ -216,6 +220,12 @@ export default function<C, CX>(
}

function unwindInterruptedWork(interruptedWork: Fiber) {
if (enableProfileModeMetrics) {
Copy link
Collaborator

Choose a reason for hiding this comment

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

Same as previous comment. Can we move this into the switch case for Profilers?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

👍

@gaearon
Copy link
Collaborator

gaearon commented May 4, 2018

Without this behavior though, it would not be possible to e.g. measure the cost of a setState update in the Header component below

I agree that's how it should work, I'm just saying that if we explain it as "when ProfileRoot re-rendered" many people won't realize that's what it means. Sorry I'm bikeshedding, let's discuss later in chat if this doesn't make sense :-)

const onRender = finishedWork.memoizedProps.onRender;
onRender(
finishedWork.memoizedProps.id,
finishedWork.alternate === null ? 'mount' : 'update',
Copy link
Collaborator

Choose a reason for hiding this comment

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

Use current === null instead. We shouldn’t use alternate in most places. We tend to pass it so that we’re free to switch to a non-alternate based model in the future.

now = function() {
return Date.now();
};
}
Copy link
Collaborator

Choose a reason for hiding this comment

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

We have this in the host config. Can we reuse that?

We should ideally avoid platform specific code in shared code like this. Some renderers will have different implementations.

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 used the host config function originally but removed it because my understanding was that we planned to change that in the future in a way that would not be compatible with this use case. cc @acdlite

Copy link
Contributor Author

Choose a reason for hiding this comment

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

If this is not the case, I can change it back to using the host config function. I'll have to make a change two test renderer to support mocking that function but that should be easy.

Copy link
Collaborator

Choose a reason for hiding this comment

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

@bvaughn I miscommunicated. I thought you were talking about the scheduler’s recalculateCurrentTime function. HostConfig.now is fine to use. My bad!

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Ah! No problem. Thanks for clarifying. 😄 I'll revert that particular change then.

* If a fiber bails out (sCU false) then its "base" timer is cancelled and the fiber is not updated.
*/

let baseStartTime: number | null = null;
Copy link
Collaborator

Choose a reason for hiding this comment

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

In wasm this wouldn’t work. Some VMs may want to use a specific representation for numbers based on type info.

We shouldn’t mix null and numbers. Null is meant for missing objects, not missing numbers.

Let’s use 0 or -1 instead of null.

}

export function markActualRenderTimeStarted(fiber: Fiber): void {
fiber.stateNode -= now() - totalElapsedPauseTime;
Copy link
Collaborator

Choose a reason for hiding this comment

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

Let’s use a temp variable here so we don’t have to read the property again below.

if (enableProfileModeMetrics) {
// Stop "base" render timer again (after the re-thrown error).
stopBaseRenderTimer();
}
Copy link
Collaborator

Choose a reason for hiding this comment

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

Does this include both renders in the time spent? Similarly for the double render flag, does it include both?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

"Both renders" meaning- if the side effect flag is enabled?

Yes. The tests disable the side effects flag for this reason.

Copy link
Collaborator

Choose a reason for hiding this comment

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

In this particular case it doesn’t matter I guess because it won’t update the base time since it errored?

In the normal case of double render I suppose we have to include it in the render time because otherwise the relative time to actual time will be misleading.

DEV is already slower than prod so the absolute numbers probably isn’t actionable regardless.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Ah, in the event of an error, if the replayFailedUnitOfWorkWithInvokeGuardedCallback flag is enabled, then when replayUnitOfWork is called- it also stops (and discards) the base time. I think this is right, because that time is kind of meaningless.

@@ -645,6 +660,12 @@ export default function<T, P, I, TI, HI, PI, C, CC, CX, PL>(
}
}

if (__DEV__) {
if (enableProfileModeMetrics) {
checkActualRenderTimeStackEmpty();
Copy link
Collaborator

Choose a reason for hiding this comment

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

Does this just check that the stack is empty? Aren’t we already doing that? If we need an extra safety check, shouldn’t this just be a generic check of the stack, not specifically to the profiler?

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 is a DEV-only sanity check to make sure we don't forget to pop anything from the timing stack.

We do the same DEV-only check with the context stack in scheduler.

@@ -702,6 +723,19 @@ export default function<T, P, I, TI, HI, PI, C, CC, CX, PL>(
child = child.sibling;
}
workInProgress.expirationTime = newExpirationTime;

if (enableProfileModeMetrics) {
if (workInProgress.mode & ProfileMode) {
Copy link
Collaborator

Choose a reason for hiding this comment

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

Let’s do the expiration time bubbling in here too. You can duplicate that code.

Let’s only do the existing path if we are not on profile mode.

That lets us reuse the same iteration instead of two iterations.

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 you're saying:

if (enableProfileModeMetrics) {
  if (workInProgress.mode & ProfileMode) {
    // Bubble both times
  } else {
    // Bubble only expiration time
} else {
  // Bubble only expiration time
}

if (enableProfileModeMetrics) {
// If we didn't finish, pause the "actual" render timer.
// We'll restart it when we resume work.
if (nextUnitOfWork !== null) {
Copy link
Collaborator

Choose a reason for hiding this comment

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

If we did finish, can we always just call pause so we don’t need the check? Simplifies things a bit. pauseActualRenderTimerIfRunning is fast anyway.

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

next = beginWork(current, workInProgress, nextRenderExpirationTime);

// Update "base" time if the render wasn't bailed out on.
if (isBaseRenderTimerRunning()) {
Copy link
Collaborator

Choose a reason for hiding this comment

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

This is a clever way to model the bailout problem. Nice.


// Update "base" time if the render wasn't bailed out on.
if (isBaseRenderTimerRunning()) {
workInProgress.selfBaseTime = getElapsedBaseRenderTime();
Copy link
Collaborator

Choose a reason for hiding this comment

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

Because performance.now is throttled in browsers and many components are pretty fast, I wouldn't be surprised if this is actually zero or one most of the time. Either way, when we add them up, it'll be misleading. :(

Not sure how to solve that. Maybe eventually performance.now will be accurate again. At least it'll be better on RN.

if (enableProfileModeMetrics) {
resumeActualRenderTimerIfPaused();
}

Copy link
Collaborator

Choose a reason for hiding this comment

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

Can you move the user timing block above findHighestPriorityRoot so that it is next to this one? Since they do the same thing, it's nice to have them colocated.

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 that one up would break things, since findHighestPriorityRoot() sets nextFlushedExpirationTime. I can move this one down though.

if (enableProfileModeMetrics) {
// If we didn't finish, pause the "actual" render timer.
// We'll restart it when we resume work.
if (nextUnitOfWork !== null) {
Copy link
Collaborator

Choose a reason for hiding this comment

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

Same question as the other spot. Is this check needed or can we just always call pauseActualRenderTimerIfRunning?

* It is paused (and accumulated) in the event of an interruption or an aborted render.
*/

const {checkThatStackIsEmpty, createCursor, push, pop} = ReactFiberStack();
Copy link
Collaborator

Choose a reason for hiding this comment

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

We should never create new fiber stacks anywhere except once.

We should reuse the one from here:

const stack = ReactFiberStack();
const hostContext = ReactFiberHostContext(config, stack);
const legacyContext = ReactFiberLegacyContext(stack);
const newContext = ReactFiberNewContext(stack);

Copy link
Contributor Author

@bvaughn bvaughn May 7, 2018

Choose a reason for hiding this comment

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

Interesting!

I avoided doing this initially because:

  • The existing stack is complete context-centric, so I wasn't sure if it was appropriate to intermingle timing values. (I was also concerned about adding complexity in terms of push/pop timing when adding more hooks into the existing stack.)
  • Re-using the existing stack cursor makes the profiler functions more awkward to use (since it requires initializing the module explicitly, and passing the profiler to the begin/unwind/complete modules explicitly).
  • The stack seemed like a lightweight enough structure that I didn't think the cost of creating a new one for profiling mode (not production mode) was a big concern.

That being said, I'll make this change 👍


const {checkThatStackIsEmpty, createCursor, push, pop} = ReactFiberStack();

let stackCursor: StackCursor<Fiber> = createCursor(null);
Copy link
Collaborator

Choose a reason for hiding this comment

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

This seems like very odd types. I'm not sure how Flow lets you do this.

You're passing a default argument for null which is not compatible with the type Fiber which you're assigning to the StackCursor.

Then later you actually pass a number to it. So it's three way inconsistent.

I think it's not noticed because you never actually use the values stored in this stack.

@@ -1093,6 +1132,9 @@ export default function<T, P, I, TI, HI, PI, C, CC, CX, PL>(
case ContextProvider:
pushProvider(workInProgress);
break;
case Profiler:
markActualRenderTimeStarted(workInProgress);
Copy link
Collaborator

Choose a reason for hiding this comment

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

Should this be wrapped in if (enableProfileModeMetrics)?

// Let the "complete" phase know to stop the timer,
// And the scheduler to record the measured time.
workInProgress.effectTag |= Update;
} else if (workInProgress.memoizedProps === nextProps) {
Copy link
Collaborator

Choose a reason for hiding this comment

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

If enableProfileModeMetrics is enabled, we should still bailout on equality, right? Seems odd to disable that optimization.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Yes, good catch. This should have been two ifs rather than an if/else

@@ -911,6 +959,14 @@ export default function<T, P, I, TI, HI, PI, C, CC, CX, PL>(
while (nextUnitOfWork !== null && !shouldYield()) {
nextUnitOfWork = performUnitOfWork(nextUnitOfWork);
}
Copy link
Collaborator

Choose a reason for hiding this comment

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

Running the base timer for everything in the tree regardless of if this fiber is part of a profiled tree or not makes this a cost paid by everyone, whether you use the feature or not. This is probably fine for now since it's off by default.

If we want to turn it on my default, then we should probably move the startBaseRenderTimer here. That way we can start a work loop that doesn't have a startBaseRenderTimer call in it, unless the first fiber is already in a profiled tree. Then when we hit a Profiler fiber, we can start another work loop that has the startBaseRenderTimer call in it.

We can do that later though. No need to do it in this PR.

Copy link
Collaborator

@sebmarkbage sebmarkbage left a comment

Choose a reason for hiding this comment

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

There’s something odd about not resetting the pause time. The other issue is that you don’t use the stack.

I suspect they’re related. Nested profilers will have issues.

Let’s talk through the scenarios.

if (enableProfileModeMetrics) {
// Stop "base" render timer again (after the re-thrown error).
stopBaseRenderTimer();
}
Copy link
Collaborator

Choose a reason for hiding this comment

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

In this particular case it doesn’t matter I guess because it won’t update the base time since it errored?

In the normal case of double render I suppose we have to include it in the render time because otherwise the relative time to actual time will be misleading.

DEV is already slower than prod so the absolute numbers probably isn’t actionable regardless.

@@ -150,6 +153,10 @@ export type Fiber = {|
// memory if we need to.
alternate: Fiber | null,

// Profiling metrics
selfBaseTime: number | null,
Copy link
Collaborator

Choose a reason for hiding this comment

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

Same thing as the other thing. We should keep this as number only. Use a number like 0 or -1 if you need to indicate missing value.

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 is just bad Flow typing on my part. I actually do initialize both to 0 below. My bad.

}
}

return baseStartTime === -1 ? 0 : now() - baseStartTime;
Copy link
Collaborator

Choose a reason for hiding this comment

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

This baseStartTime === -1 is an error anyway we don’t have to do this check at runtime. If this was all inlined in the same function the compiler could maybe know that but it is broken apart so it might not.

That’s a perfect example why I prefer to avoid abstractions like these functions, and moving to other modules, because it makes it harder to see that you’re actually doing the same comparison twice.

If they were together in the same function it would be obvious.

You could refactor this to pass the fiber instead and do the condition and update in the same function. Like updateBaseTime(workInProgress).


let stackCursor: StackCursor<Fiber> = createCursor(null);
let timerPausedAt: number = 0;
let totalElapsedPauseTime: number = 0;
Copy link
Collaborator

Choose a reason for hiding this comment

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

This only increases but never gets reset. That seems odd. At some point we need to reset it right?

Copy link
Contributor Author

@bvaughn bvaughn May 7, 2018

Choose a reason for hiding this comment

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

Do we? Why? This time is accounted for in both the start and stop time methods.

I guess I can reset it in commitRoot if you think it's best.

@sebmarkbage
Copy link
Collaborator

sebmarkbage commented May 6, 2018

For nested profilers I guess the semantics are not really clear. There are two possible semantics:

a) We include the time of the nested profiler in both the base time and actual time of the nested profiler. This seems intuitive to me but is also misleading since when you add up the time of several profilers they won’t be representative of the time if the tree.

b) The parent time include only the time of the children that are not nested in other profilers. The base time that bubbles up from a profiler would be zero. I think with this strategy we won’t need a stack which is nice.

Not sure what is more useful. You can infer some data if you have tree info in the id. So I guess it’s more about when you don’t want to have tree info in the id so that they accumulate across usages in different trees.

@bvaughn
Copy link
Contributor Author

bvaughn commented May 7, 2018

I believe I have made all of the edits suggested above. Each one is a single commit, so hopefully it will be easy to review.

@bvaughn
Copy link
Contributor Author

bvaughn commented May 7, 2018

There’s something odd about not resetting the pause time. The other issue is that you don’t use the stack.

I don't think this is actually an issue, but let's talk about it.

I suspect they’re related. Nested profilers will have issues.

I have tests for nested profilers. Can you think of cases I'm not testing? I'd love to improve the tests.

For nested profilers I guess the semantics are not really clear. There are two possible semantics

WRT nested profilers, I think option A makes the most sense (and is the behavior my test cases currently verify).

Option B seems like it would be too easy for e.g. on person to mess up another person's timing metrics unintentionally by adding a profiler at a lower level in the tree.

@@ -226,7 +226,7 @@ export default function<T, P, I, TI, HI, PI, C, CC, CX, PL>(
const nextProps = workInProgress.pendingProps;
if (enableProfileModeMetrics) {
// Start render timer here and push start time onto queue
markActualRenderTimeStarted(workInProgress);
markActualRenderTimeStarted(workInProgress, now);
Copy link
Collaborator

Choose a reason for hiding this comment

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

We should pass this when we initial the module instead of an argument, so that it can be statically known which function is called. This will be a lot easier when we move to static injection instead of dynamic.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Yeah. Duh, me.

}
workInProgress.expirationTime = newExpirationTime;

// (And "base" render timers if that feature flag is enabled)
if (enableProfileModeMetrics) {
if (workInProgress.mode & ProfileMode) {
Copy link
Collaborator

Choose a reason for hiding this comment

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

If you change this to enableProfileModeMetrics && (workInProgress.mode & ProfileMode) you only need one else block.

Copy link
Contributor Author

@bvaughn bvaughn May 7, 2018

Choose a reason for hiding this comment

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

But then we won't strip the code when enableProfileModeMetrics is false. I assumed this was more important. Disregard. I'm silly.

import type {StackCursor, Stack} from './ReactFiberStack';

import warning from 'fbjs/lib/warning';

Copy link
Collaborator

Choose a reason for hiding this comment

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

This whole module needs to be wrapped in a closure and initialized because it is stateful. Otherwise these timers will be shared with other renderers that could be rendering interleaved with this one.

That will also let you get a static reference to now instead of passing it as an argument.

Doing that might however mess up closure compiler and lead everything in here to not be inlined which would be bad for file size, compile perf and possibly runtime perf. Who knows?

We need to move to static host configs.

Copy link
Contributor Author

@bvaughn bvaughn May 7, 2018

Choose a reason for hiding this comment

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

Otherwise these timers will be shared with other renderers that could be rendering interleaved with this one.

D'oh. Good point.

I always forget about this use case.

@@ -607,7 +597,12 @@ export default function<T, P, I, TI, HI, PI, C, CC, CX, PL>(
case Mode:
return null;
case Profiler:
updateProfiler(workInProgress);
if (enableProfileModeMetrics) {
((actualRenderTimer: any): ActualRenderTimer).recordElapsedActualRenderTime(
Copy link
Collaborator

Choose a reason for hiding this comment

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

Destructure these at the top like we do with everything else so that we don't have to look up this property dynamically every time. Hopefully this also lets us inline this call. (We should confirm whether it does.)

selfBaseTime: number,
treeBaseTime: number,
selfBaseTime?: number,
treeBaseTime?: number,
Copy link
Collaborator

Choose a reason for hiding this comment

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

This is wrong. We should always assign them and they should always a consistent type value. E.g. 0.

Making them optional is a huge no, no since it might break the hidden class of the fiber.

Copy link
Contributor Author

@bvaughn bvaughn May 7, 2018

Choose a reason for hiding this comment

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

I wasn't sure how to type them- given that we only assign these values if the feature flag is enabled. (We don't want to add them to every fiber if the flag isn't even enabled- right?)

Copy link
Contributor Author

@bvaughn bvaughn May 7, 2018

Choose a reason for hiding this comment

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

To be clear, they are always either on or off. It's based on the feature flag. This will not break the hidden class of a fiber, since this is a bundle-wide thing.

  if (enableProfileModeMetrics) {
    this.selfBaseTime = 0;
    this.treeBaseTime = 0;
  }

Copy link
Collaborator

Choose a reason for hiding this comment

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

Hm. I see. I suppose we do that with DEV only too. Seems odd that Flow doesn't force you to check for their existence everywhere then? We shouldn't need to check if they're undefined/null but seems like Flow would want us to.

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 agree. I expected that also.

resumeActualRenderTimerIfPaused(now: Now): void,
};

export function createActualRenderTimer(stack: Stack): ActualRenderTimer {
Copy link
Collaborator

Choose a reason for hiding this comment

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

Sorry didn't see that you wrapped this in a later commit. This needs to also include the base time to be safe.

You can pass now to this instead of each function.

@@ -88,8 +93,9 @@ export default function<T, P, I, TI, HI, PI, C, CC, CX, PL>(
hydrationContext: HydrationContext<C, CX>,
scheduleWork: (fiber: Fiber, expirationTime: ExpirationTime) => void,
computeExpirationForFiber: (fiber: Fiber) => ExpirationTime,
actualRenderTimer: ActualRenderTimer | null,
Copy link
Collaborator

Choose a reason for hiding this comment

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

Let's always pass it the module and assume that the compiler will strip it all out. We do assume that everywhere else, whether it does or not.

NMinhNguyen referenced this pull request in enzymejs/react-shallow-renderer Jan 29, 2020
Add a new component type, Profiler, that can be used to collect new render time metrics. Since this is a new, experimental API, it will be exported as React.unstable_Profiler initially.

Most of the functionality for this component has been added behind a feature flag, enableProfileModeMetrics. When the feature flag is disabled, the component will just render its children with no additional behavior. When the flag is enabled, React will also collect timing information and pass it to the onRender function (as described below).
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.

None yet

6 participants