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

Projects
None yet
7 participants
@bvaughn
Contributor

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

This comment has been minimized.

Member

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

This comment has been minimized.

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

This comment has been minimized.

Contributor

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

This comment has been minimized.

Member

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

This comment has been minimized.

Contributor

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(

This comment has been minimized.

@sebmarkbage

sebmarkbage May 4, 2018

Member
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

This comment has been minimized.

@bvaughn

bvaughn May 4, 2018

Contributor

I'm curious- why?

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

This comment has been minimized.

@gaearon

gaearon May 4, 2018

Member

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

This comment has been minimized.

@bvaughn

bvaughn May 4, 2018

Contributor

Oh, haha. I misread that 😄

This comment has been minimized.

@sebmarkbage

sebmarkbage May 5, 2018

Member

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

This comment has been minimized.

@bvaughn

bvaughn May 5, 2018

Contributor

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.

This comment has been minimized.

@acdlite

acdlite May 4, 2018

Member

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.

This comment has been minimized.

@bvaughn

bvaughn May 4, 2018

Contributor

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.

This comment has been minimized.

@acdlite

acdlite May 4, 2018

Member

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.

This comment has been minimized.

@bvaughn

bvaughn May 4, 2018

Contributor

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;

This comment has been minimized.

@acdlite

acdlite May 4, 2018

Member

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.

This comment has been minimized.

@bvaughn

bvaughn May 4, 2018

Contributor

Oh? cc @gaearon

This comment has been minimized.

@gaearon

gaearon May 4, 2018

Member

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

This comment has been minimized.

@bvaughn

bvaughn May 4, 2018

Contributor

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) {

This comment has been minimized.

@acdlite

acdlite May 4, 2018

Member

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

This comment has been minimized.

@bvaughn

bvaughn May 4, 2018

Contributor

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) {

This comment has been minimized.

@acdlite

acdlite May 4, 2018

Member

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

This comment has been minimized.

@acdlite

acdlite May 4, 2018

Member

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

This comment has been minimized.

@bvaughn

bvaughn May 4, 2018

Contributor

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

This comment has been minimized.

@bvaughn

bvaughn May 4, 2018

Contributor

Our comments got crossed.

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

Yes.

This comment has been minimized.

@acdlite

acdlite May 4, 2018

Member

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

This comment has been minimized.

@bvaughn

bvaughn May 4, 2018

Contributor

👍

@@ -216,6 +220,12 @@ export default function<C, CX>(
}
function unwindInterruptedWork(interruptedWork: Fiber) {
if (enableProfileModeMetrics) {

This comment has been minimized.

@acdlite

acdlite May 4, 2018

Member

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

This comment has been minimized.

@bvaughn

bvaughn May 4, 2018

Contributor

👍

@gaearon

This comment has been minimized.

Member

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',

This comment has been minimized.

@sebmarkbage

sebmarkbage May 5, 2018

Member

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();
};
}

This comment has been minimized.

@sebmarkbage

sebmarkbage May 5, 2018

Member

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.

This comment has been minimized.

@bvaughn

bvaughn May 6, 2018

Contributor

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

This comment has been minimized.

@bvaughn

bvaughn May 6, 2018

Contributor

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.

This comment has been minimized.

@acdlite

acdlite May 6, 2018

Member

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

This comment has been minimized.

@bvaughn

bvaughn May 7, 2018

Contributor

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;

This comment has been minimized.

@sebmarkbage

sebmarkbage May 5, 2018

Member

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;

This comment has been minimized.

@sebmarkbage

sebmarkbage May 5, 2018

Member

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();
}

This comment has been minimized.

@sebmarkbage

sebmarkbage May 6, 2018

Member

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

This comment has been minimized.

@bvaughn

bvaughn May 6, 2018

Contributor

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

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

This comment has been minimized.

@WeShared

WeShared May 6, 2018

💙💛💚👍

This comment has been minimized.

@sebmarkbage

sebmarkbage May 6, 2018

Member

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.

This comment has been minimized.

@bvaughn

bvaughn May 7, 2018

Contributor

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

This comment has been minimized.

@sebmarkbage

sebmarkbage May 6, 2018

Member

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?

This comment has been minimized.

@bvaughn

bvaughn May 6, 2018

Contributor

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) {

This comment has been minimized.

@sebmarkbage

sebmarkbage May 6, 2018

Member

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.

This comment has been minimized.

@bvaughn

bvaughn May 7, 2018

Contributor

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) {

This comment has been minimized.

@sebmarkbage

sebmarkbage May 6, 2018

Member

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.

This comment has been minimized.

@bvaughn

bvaughn May 6, 2018

Contributor

I...think so.

next = beginWork(current, workInProgress, nextRenderExpirationTime);
// Update "base" time if the render wasn't bailed out on.
if (isBaseRenderTimerRunning()) {

This comment has been minimized.

@sebmarkbage

sebmarkbage May 6, 2018

Member

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

This comment has been minimized.

@sebmarkbage

sebmarkbage May 6, 2018

Member

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();
}

This comment has been minimized.

@sebmarkbage

sebmarkbage May 6, 2018

Member

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.

This comment has been minimized.

@bvaughn

bvaughn May 7, 2018

Contributor

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) {

This comment has been minimized.

@sebmarkbage

sebmarkbage May 6, 2018

Member

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

This comment has been minimized.

@sebmarkbage

sebmarkbage May 6, 2018

Member

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

This comment has been minimized.

@bvaughn

bvaughn May 7, 2018

Contributor

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

This comment has been minimized.

@sebmarkbage

sebmarkbage May 6, 2018

Member

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

This comment has been minimized.

@sebmarkbage

sebmarkbage May 6, 2018

Member

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) {

This comment has been minimized.

@sebmarkbage

sebmarkbage May 6, 2018

Member

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

This comment has been minimized.

@bvaughn

bvaughn May 7, 2018

Contributor

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

This comment has been minimized.

@sebmarkbage

sebmarkbage May 6, 2018

Member

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.

@sebmarkbage

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();
}

This comment has been minimized.

@sebmarkbage

sebmarkbage May 6, 2018

Member

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,

This comment has been minimized.

@sebmarkbage

sebmarkbage May 6, 2018

Member

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.

This comment has been minimized.

@bvaughn

bvaughn May 7, 2018

Contributor

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;

This comment has been minimized.

@sebmarkbage

sebmarkbage May 6, 2018

Member

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;

This comment has been minimized.

@sebmarkbage

sebmarkbage May 6, 2018

Member

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

This comment has been minimized.

@bvaughn

bvaughn May 7, 2018

Contributor

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

This comment has been minimized.

Member

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

This comment has been minimized.

Contributor

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

This comment has been minimized.

Contributor

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

This comment has been minimized.

@sebmarkbage

sebmarkbage May 7, 2018

Member

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.

This comment has been minimized.

@bvaughn

bvaughn May 7, 2018

Contributor

Yeah. Duh, me.

}
workInProgress.expirationTime = newExpirationTime;
// (And "base" render timers if that feature flag is enabled)
if (enableProfileModeMetrics) {
if (workInProgress.mode & ProfileMode) {

This comment has been minimized.

@sebmarkbage

sebmarkbage May 7, 2018

Member

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

This comment has been minimized.

@bvaughn

bvaughn May 7, 2018

Contributor

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';

This comment has been minimized.

@sebmarkbage

sebmarkbage May 7, 2018

Member

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.

This comment has been minimized.

@bvaughn

bvaughn May 7, 2018

Contributor

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(

This comment has been minimized.

@sebmarkbage

sebmarkbage May 7, 2018

Member

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,

This comment has been minimized.

@sebmarkbage

sebmarkbage May 7, 2018

Member

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.

This comment has been minimized.

@bvaughn

bvaughn May 7, 2018

Contributor

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?)

This comment has been minimized.

@bvaughn

bvaughn May 7, 2018

Contributor

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;
  }

This comment has been minimized.

@sebmarkbage

sebmarkbage May 7, 2018

Member

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.

This comment has been minimized.

@bvaughn

bvaughn May 7, 2018

Contributor

I agree. I expected that also.

resumeActualRenderTimerIfPaused(now: Now): void,
};
export function createActualRenderTimer(stack: Stack): ActualRenderTimer {

This comment has been minimized.

@sebmarkbage

sebmarkbage May 7, 2018

Member

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,

This comment has been minimized.

@sebmarkbage

sebmarkbage May 7, 2018

Member

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.

TejasQ added a commit to TejasQ/react that referenced this pull request Aug 26, 2018

Add Profiler component for collecting new render timing info (faceboo…
…k#12745)

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