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

Pass "start time" and "commit time" to Profiler callback #12852

Merged
merged 6 commits into from
May 21, 2018

Conversation

bvaughn
Copy link
Contributor

@bvaughn bvaughn commented May 18, 2018

Profiler component passes additional "start time" and "commit time" parameters to onRender callback.

After discussing this new component type with some teams at FB that might use it, it's become apparent that the addition of these time values would be helpful.

  • Start time provides a method of determining whether a given commit had already begun when an event took place (e.g. user interaction, Flux action).
  • Commit time could be roughly determined using e.g. performance.now() within the onRender callback, but multiple Profiler components would end up with slightly different times for a single commit. This explicit time value ensures consistency.

Tests have been updated to cover both new parameters.

Caveats

Start time is not the time when the event that triggered a render occurred (e.g. mouse click, Flux update). It is the time when the Profiler in question started rendering as a result. (This might be significantly later than the event that originated the update. State updates can be async. Other code may execute in between. etc.)

Commit time is not necessarily the exact time a user sees e.g. the updated DOM. It is the time when React commits the mutations to the DOM- but other scripts may run before the browser repaints.

@pull-bot
Copy link

pull-bot commented May 18, 2018

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

Details of bundled changes.

Comparing: 397d611...0c99c4c

react-dom

File Filesize Diff Gzip Diff Prev Size Current Size Prev Gzip Current Gzip ENV
react-dom.development.js +0.1% +0.1% 617.64 KB 618.11 KB 143.99 KB 144.11 KB UMD_DEV
react-dom.production.min.js -0.0% -0.1% 93.68 KB 93.64 KB 30.31 KB 30.3 KB UMD_PROD
react-dom.development.js +0.1% +0.1% 602.01 KB 602.48 KB 139.99 KB 140.11 KB NODE_DEV
react-dom.production.min.js -0.0% -0.0% 92.17 KB 92.14 KB 29.29 KB 29.28 KB NODE_PROD
ReactDOM-dev.js +0.1% +0.1% 623.77 KB 624.27 KB 142.63 KB 142.74 KB FB_WWW_DEV
ReactDOM-prod.js 🔺+0.1% 🔺+0.1% 273.23 KB 273.61 KB 51.48 KB 51.53 KB FB_WWW_PROD

react-art

File Filesize Diff Gzip Diff Prev Size Current Size Prev Gzip Current Gzip ENV
react-art.development.js +0.1% +0.1% 400.77 KB 401.24 KB 89.75 KB 89.86 KB UMD_DEV
react-art.production.min.js -0.0% -0.1% 80.64 KB 80.6 KB 24.87 KB 24.85 KB UMD_PROD
react-art.development.js +0.1% +0.2% 326.62 KB 327.1 KB 70.83 KB 70.94 KB NODE_DEV
react-art.production.min.js -0.1% -0.1% 45 KB 44.96 KB 13.99 KB 13.98 KB NODE_PROD
ReactART-dev.js +0.2% +0.1% 331.62 KB 332.12 KB 70.12 KB 70.22 KB FB_WWW_DEV
ReactART-prod.js 🔺+0.3% 🔺+0.2% 146.1 KB 146.48 KB 25.25 KB 25.31 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.1% +0.2% 336.61 KB 337.08 KB 72.95 KB 73.06 KB UMD_DEV
react-test-renderer.production.min.js -0.1% -0.2% 45.57 KB 45.54 KB 14.07 KB 14.05 KB UMD_PROD
react-test-renderer.development.js +0.1% +0.2% 327.45 KB 327.92 KB 70.2 KB 70.31 KB NODE_DEV
react-test-renderer.production.min.js -0.1% -0.1% 44.67 KB 44.64 KB 13.61 KB 13.59 KB NODE_PROD
ReactTestRenderer-dev.js +0.2% +0.1% 333.1 KB 333.6 KB 69.79 KB 69.9 KB FB_WWW_DEV

react-reconciler

File Filesize Diff Gzip Diff Prev Size Current Size Prev Gzip Current Gzip ENV
react-reconciler.development.js +0.1% +0.2% 321.1 KB 321.57 KB 68.18 KB 68.29 KB NODE_DEV
react-reconciler.production.min.js -0.1% -0.1% 45.16 KB 45.13 KB 13.5 KB 13.49 KB NODE_PROD
react-reconciler-persistent.development.js +0.1% +0.2% 319.69 KB 320.16 KB 67.6 KB 67.7 KB NODE_DEV
react-reconciler-persistent.production.min.js -0.1% -0.1% 45.17 KB 45.14 KB 13.51 KB 13.49 KB NODE_PROD

react-native-renderer

File Filesize Diff Gzip Diff Prev Size Current Size Prev Gzip Current Gzip ENV
ReactNativeRenderer-dev.js +0.1% +0.1% 454.47 KB 454.97 KB 99.59 KB 99.71 KB RN_FB_DEV
ReactNativeRenderer-prod.js 🔺+0.2% 🔺+0.1% 205.47 KB 205.84 KB 35.92 KB 35.98 KB RN_FB_PROD
ReactNativeRenderer-dev.js +0.1% +0.1% 454.13 KB 454.63 KB 99.52 KB 99.63 KB RN_OSS_DEV
ReactNativeRenderer-prod.js -0.0% -0.1% 193.74 KB 193.68 KB 33.94 KB 33.92 KB RN_OSS_PROD
ReactFabric-dev.js +0.1% +0.1% 445.28 KB 445.78 KB 97.29 KB 97.4 KB RN_FB_DEV
ReactFabric-prod.js -0.0% -0.1% 185.92 KB 185.86 KB 32.57 KB 32.55 KB RN_FB_PROD
ReactFabric-dev.js +0.1% +0.1% 445.32 KB 445.82 KB 97.31 KB 97.42 KB RN_OSS_DEV
ReactFabric-prod.js -0.0% -0.1% 185.96 KB 185.9 KB 32.58 KB 32.56 KB RN_OSS_PROD

Generated by 🚫 dangerJS

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.

Will @gaearon's changes fix the byte size issue? That's a lot of bytes for something that is turned off.

@@ -420,6 +422,10 @@ export default function<T, P, I, TI, HI, PI, C, CC, CX, PL>(
}
}

if (enableProfilerTimer) {
recordCommitTime();
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 not the place for it. This is inside a hot loop and gets called thousands of time. This would be a better place: https://github.com/bvaughn/react/blob/7f027607b516d3cb3d58feeb07074813f6f8bfb4/packages/react-reconciler/src/ReactFiberScheduler.js#L632 That way we also ensure that the render time doesn't overlap with the commit time frame.

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, yeah. This was pretty dumb. Thanks for the pointer.

@bvaughn
Copy link
Contributor Author

bvaughn commented May 18, 2018

Will @gaearon's changes fix the byte size issue? That's a lot of bytes for something that is turned off.

I built mater locally, then rebased and built this branch. Ran react-dom.production.min.js through Prettier and diffed them:

14c14
< var aa = require("fbjs/lib/invariant"),
---
> var ba = require("fbjs/lib/invariant"),
32c32
<   aa(
---
>   ba(
1998c1998,2002
<           (d.stateNode = { duration: 0, startTime: 0 }),
---
>           (d.stateNode = {
>             elapsedPauseTimeAtStart: 0,
>             duration: 0,
>             startTime: 0
>           }),
2079a2084,2087
>     getCommitTime: function() {
>       return 0;
>     },
>     recordCommitTime: function() {},
2945c2953
<     ba = e.enterHydrationState,
---
>     aa = e.enterHydrationState,
3045c3053
<                     (null === a || null === a.child) && d.hydrate && ba(b)
---
>                     (null === a || null === a.child) && d.hydrate && aa(b)
4130c4138
<             ? aa(
---
>             ? ba(
4486,4493c4494,4501
<     ba = Cf(),
<     D = yf(a, ba),
<     y = Af(ba);
<   ba = Bf(ba, a.isPrimaryRenderer);
<   var gb = We(Y),
<     Pb = zf(a),
<     Qb = rf(a, D, y, ba, Pb, l, k, gb, r).beginWork,
<     Nc = sf(a, D, y, ba, Pb, gb).completeWork;
---
>     aa = Cf(),
>     D = yf(a, aa),
>     y = Af(aa),
>     gb = Bf(aa, a.isPrimaryRenderer);
>   aa = We(Y);
>   var Pb = zf(a),
>     Qb = rf(a, D, y, gb, Pb, l, k, aa, r).beginWork,
>     Nc = sf(a, D, y, gb, Pb, aa).completeWork;
4498c4506
<     ba,
---
>     gb,
4505c4513
<     gb,
---
>     aa,
4516c4524
<   a = vf(a, g, l, k, d, r);
---
>   a = vf(a, g, l, k, d, r, aa);

@bvaughn
Copy link
Contributor Author

bvaughn commented May 18, 2018

Looking at this, I realize that I could wrap the entire stateNode object init for Profiler with a feature flag too, since the stateNode is only ever used when timing is enabled.

After adding this wrapper, the build size is better:
screen shot 2018-05-18 at 7 20 16 am

And the diff:

14c14
< var aa = require("fbjs/lib/invariant"),
---
> var ba = require("fbjs/lib/invariant"),
32c32
<   aa(
---
>   ba(
1998d1997
<           (d.stateNode = { duration: 0, startTime: 0 }),
2079a2079,2082
>     getCommitTime: function() {
>       return 0;
>     },
>     recordCommitTime: function() {},
2945c2948
<     ba = e.enterHydrationState,
---
>     aa = e.enterHydrationState,
3045c3048
<                     (null === a || null === a.child) && d.hydrate && ba(b)
---
>                     (null === a || null === a.child) && d.hydrate && aa(b)
4130c4133
<             ? aa(
---
>             ? ba(
4486,4493c4489,4496
<     ba = Cf(),
<     D = yf(a, ba),
<     y = Af(ba);
<   ba = Bf(ba, a.isPrimaryRenderer);
<   var gb = We(Y),
<     Pb = zf(a),
<     Qb = rf(a, D, y, ba, Pb, l, k, gb, r).beginWork,
<     Nc = sf(a, D, y, ba, Pb, gb).completeWork;
---
>     aa = Cf(),
>     D = yf(a, aa),
>     y = Af(aa),
>     gb = Bf(aa, a.isPrimaryRenderer);
>   aa = We(Y);
>   var Pb = zf(a),
>     Qb = rf(a, D, y, gb, Pb, l, k, aa, r).beginWork,
>     Nc = sf(a, D, y, gb, Pb, aa).completeWork;
4498c4501
<     ba,
---
>     gb,
4505c4508
<     gb,
---
>     aa,
4516c4519
<   a = vf(a, g, l, k, d, r);
---
>   a = vf(a, g, l, k, d, r, aa);

@bvaughn
Copy link
Contributor Author

bvaughn commented May 19, 2018

Merged in Dan's Flow refactor from master and did another master vs branch build comparison.

Relevant results:
screen shot 2018-05-19 at 8 37 53 am

DOM renderer production diff:

2826d2825
<           (d.stateNode = { duration: 0, startTime: 0 }),

DOM renderer development diff:

11822,11825c11822,11828
<       fiber.stateNode = {
<         duration: 0,
<         startTime: 0
<       };
---
>       if (enableProfilerTimer) {
>         fiber.stateNode = {
>           elapsedPauseTimeAtStart: 0,
>           duration: 0,
>           startTime: 0
>         };
>       }
13280a13284,13296
>     var commitTime = 0;
> 
>     function getCommitTime() {
>       return commitTime;
>     }
> 
>     function recordCommitTime() {
>       if (!enableProfilerTimer) {
>         return;
>       }
>       commitTime = now();
>     }
> 
13318c13334,13336
<       fiber.stateNode.startTime = now() - totalElapsedPauseTime;
---
>       var stateNode = fiber.stateNode;
>       stateNode.elapsedPauseTimeAtStart = totalElapsedPauseTime;
>       stateNode.startTime = now();
13339,13340c13357,13361
<       fiber.stateNode.duration +=
<         now() - totalElapsedPauseTime - fiber.stateNode.startTime;
---
>       var stateNode = fiber.stateNode;
>       stateNode.duration +=
>         now() -
>         (totalElapsedPauseTime - stateNode.elapsedPauseTimeAtStart) -
>         stateNode.startTime;
18373c18394,18396
<               finishedWork.treeBaseTime
---
>               finishedWork.treeBaseTime,
>               finishedWork.stateNode.startTime,
>               getCommitTime()
19122a19146,19149
>       if (enableProfilerTimer) {
>         recordCommitTime();
>       }
> 

duration: 0,
startTime: 0,
};
if (enableProfilerTimer) {
Copy link
Contributor Author

Choose a reason for hiding this comment

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

We can shave off a bit by not even initializing stateNode for Profiler unless we're actually going to use it for timing.

@bvaughn bvaughn merged commit 1300365 into facebook:master May 21, 2018
@bvaughn bvaughn deleted the profile-mode-part-3 branch May 21, 2018 16:49
@bvaughn bvaughn mentioned this pull request May 22, 2018
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

4 participants