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

Projects
None yet
4 participants
@bvaughn
Copy link
Contributor

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

This comment has been minimized.

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

@sebmarkbage
Copy link
Member

sebmarkbage left a comment

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

This comment has been minimized.

@sebmarkbage

sebmarkbage May 18, 2018

Member

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.

This comment has been minimized.

@bvaughn

bvaughn May 18, 2018

Author Contributor

Ah, yeah. This was pretty dumb. Thanks for the pointer.

@bvaughn

This comment has been minimized.

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 bvaughn force-pushed the bvaughn:profile-mode-part-3 branch from 7f02760 to 974ee00 May 18, 2018

@bvaughn

This comment has been minimized.

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

This comment has been minimized.

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

This comment has been minimized.

@bvaughn

bvaughn May 19, 2018

Author Contributor

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

1 check passed

ci/circleci Your tests passed on CircleCI!
Details

@bvaughn bvaughn deleted the bvaughn:profile-mode-part-3 branch May 21, 2018

@bvaughn bvaughn referenced this pull request May 22, 2018

Open

Profiler RFC #51

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

Pass "start time" and "commit time" to Profiler callback (facebook#12852
)

* Added start time parameter to Profiler onRender callback
* Profiler also captures commit time
* Only init Profiler stateNode if enableProfilerTimer feature flag enabled
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.