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

Feature: Benchmark Onyx #70

Merged
merged 55 commits into from
May 25, 2021
Merged

Feature: Benchmark Onyx #70

merged 55 commits into from
May 25, 2021

Conversation

kidroca
Copy link
Contributor

@kidroca kidroca commented May 13, 2021

@marcaaron

Details

Moved some methods to Onyx.internal.js - e.g. to test private methods like get through the decorator pattern
Created decorateWithMetrics lib that serves to decorate Onyx methods similarly to how HOCs are used to enhance components
Updated some methods so they return the promises they work with so that they can be metered
Added captureMetrics flag to Onyx.init. Initially the intent was to use process.env.BENCHMARK_ONYX but process.env has only NODE_ENV so far - this can be configured after the draft is finalized

Created a sample usage that will print statistics for each navigation state change (only in Chrome dev tools - debug mode). Don't forget to set the BENCHMARK_ONYX=true in .env: https://github.com/kidroca/Expensify.cash/tree/kidroca/sample-onyx-benchmark

Some methods cannot be tested as easy like the connect method, they would need some changes to incorporate the decorator - e.g. don't measure the whole connect but move the promise based logic to a separate method and measure that method - this way connect can still return a connectionID or a removeListener callback

Related Issues

#65
Expensify/App#2762

Automated Tests

Added basic covering tests TBD

Linked PRs

@kidroca kidroca requested a review from a team as a code owner May 13, 2021 01:20
@github-actions
Copy link
Contributor

github-actions bot commented May 13, 2021

CLA Assistant Lite bot All contributors have signed the CLA ✍️ ✅

@MelvinBot MelvinBot requested review from Gonals and removed request for a team May 13, 2021 01:20
@kidroca
Copy link
Contributor Author

kidroca commented May 13, 2021

Metering xlsx sample:

https://docs.google.com/spreadsheets/d/1R4YPeG6rHbTiY3gcKINV-kLFsW37ITnfhV_MYnWmJzs/edit?usp=sharing

(index) method startTime endTime duration args result
             
0 "Onyx.merge" 1350810.00ms 1350827.00ms 18.00ms "["modal",{"isVisible":false}]" undefined
1 "Onyx.merge" 1350810.00ms 1350827.00ms 17.00ms "["modal",{"isVisible":false}]" undefined
2 "Onyx.merge" 1350810.00ms 1350827.00ms 17.00ms "["modal",{"isVisible":false}]" undefined
3 "Onyx.merge" 1350810.00ms 1350827.00ms 17.00ms "["modal",{"isVisible":false}]" undefined
4 "Onyx.merge" 1350810.00ms 1350827.00ms 17.00ms "["modal",{"isVisible":false}]" undefined
5 "Onyx.merge" 1350810.00ms 1350827.00ms 17.00ms "["modal",{"isVisible":false}]" undefined
6 "Onyx.merge" 1350811.00ms 1350827.00ms 17.00ms "["modal",{"isVisible":false}]" undefined
7 "Onyx.merge" 1350811.00ms 1350827.00ms 16.00ms "["modal",{"isVisible":false}]" undefined
8 "Onyx.merge" 1350811.00ms 1350827.00ms 16.00ms "["modal",{"isVisible":false}]" undefined
9 "Onyx.merge" 1350811.00ms 1350827.00ms 16.00ms "["modal",{"isVisible":false}]" undefined
10 "Onyx.merge" 1350811.00ms 1350827.00ms 16.00ms "["modal",{"isVisible":false}]" undefined
65 "Onyx.get" 1350808.00ms 1350850.00ms 42.00ms "["modal"]" "{"isVisible":false}"
66 "Onyx.get" 1350820.00ms 1350871.00ms 50.00ms "["currentlyViewedReportID"]" ""71955477""
67 "Onyx.get" 1350859.00ms 1350884.00ms 25.00ms "["report_71402263"]" "{"reportID":71402263,"reportName":"Concierge","unr…cierge_2021.png"],"optimisticReportActionIDs":[]}"
68 "Onyx.get" 1350861.00ms 1350891.00ms 30.00ms "["personalDetails"]" "{"[email protected]":{"login":"expensify3@kid…":{"automatic":true,"selected":"Europe/Athens"}}}"
69 "Onyx.get" 1350865.00ms 1350899.00ms 34.00ms "["session"]" "{"authToken":"0DACCD10C10A007A181A76FE3D529FD286D4…m","loading":false,"shouldShowComposeInput":true}"
70 "Onyx.get" 1350926.00ms 1350942.00ms 16.00ms "["report_71402263"]" "{"reportID":71402263,"reportName":"Concierge","unr…cierge_2021.png"],"optimisticReportActionIDs":[]}"
71 "Onyx.get" 1350928.00ms 1351045.00ms 117.00ms "["reportActions_71402263"]" "{"0":{"actionName":"CREATED","created":"Mar 19 202…true,"clientID":"","reportActionID":"755784774"}}"
72 "Onyx.get" 1350931.00ms 1351056.00ms 125.00ms "["session"]" "{"authToken":"0DACCD10C10A007A181A76FE3D529FD286D4…m","loading":false,"shouldShowComposeInput":true}"
73 "Onyx.get" 1350935.00ms 1351062.00ms 126.00ms "["modal"]" "{"isVisible":false}"
74 "Onyx.get" 1350937.00ms 1351065.00ms 128.00ms "["network"]" "{"isOffline":false}"
75 "Onyx.get" 1350939.00ms 1351074.00ms 135.00ms "["report_71402263"]" "{"reportID":71402263,"reportName":"Concierge","unr…cierge_2021.png"],"optimisticReportActionIDs":[]}"
76 "Onyx.get" 1351055.00ms 1351270.00ms 215.00ms "["report_71402263"]" "{"reportID":71402263,"reportName":"Concierge","unr…cierge_2021.png"],"optimisticReportActionIDs":[]}"
77 "Onyx.get" 1351273.00ms 1351510.00ms 237.00ms "["session"]" "{"authToken":"0DACCD10C10A007A181A76FE3D529FD286D4…m","loading":false,"shouldShowComposeInput":true}"
78 "Onyx.get" 1351283.00ms 1351522.00ms 238.00ms "["personalDetails"]" "{"[email protected]":{"login":"expensify3@kid…":{"automatic":true,"selected":"Europe/Athens"}}}"
79 "Onyx.get" 1351293.00ms 1351535.00ms 243.00ms "["personalDetails"]" "{"[email protected]":{"login":"expensify3@kid…":{"automatic":true,"selected":"Europe/Athens"}}}"
80 "Onyx.get" 1351346.00ms 1351595.00ms 249.00ms "["personalDetails"]" "{"[email protected]":{"login":"expensify3@kid…":{"automatic":true,"selected":"Europe/Athens"}}}"
425 "Onyx.getAllKeys" 1353100.00ms 1353521.00ms 421.00ms "[]" "["account","betas","countryCode","credentials","cu…ort_73013597","report_73164379","session","user"]"
426 "Onyx.getAllKeys" 1353113.00ms 1353535.00ms 421.00ms "[]" "["account","betas","countryCode","credentials","cu…ort_73013597","report_73164379","session","user"]"
427 "Onyx.getAllKeys" 1353126.00ms 1353551.00ms 425.00ms "[]" "["account","betas","countryCode","credentials","cu…ort_73013597","report_73164379","session","user"]"
428 "Onyx.getAllKeys" 1353136.00ms 1353566.00ms 429.00ms "[]" "["account","betas","countryCode","credentials","cu…ort_73013597","report_73164379","session","user"]"
429 "Onyx.getAllKeys" 1353148.00ms 1353578.00ms 430.00ms "[]" "["account","betas","countryCode","credentials","cu…ort_73013597","report_73164379","session","user"]"
430 "Onyx.getAllKeys" 1353209.00ms 1353605.00ms 396.00ms "[]" "["account","betas","countryCode","credentials","cu…ort_73013597","report_73164379","session","user"]"
431 "Onyx.getAllKeys" 1353228.00ms 1353618.00ms 390.00ms "[]" "["account","betas","countryCode","credentials","cu…ort_73013597","report_73164379","session","user"]"
432 "Onyx.getAllKeys" 1353365.00ms 1353740.00ms 375.00ms "[]" "["account","betas","countryCode","credentials","cu…ort_73013597","report_73164379","session","user"]"
433 "Onyx.getAllKeys" 1353379.00ms 1353743.00ms 364.00ms "[]" "["account","betas","countryCode","credentials","cu…ort_73013597","report_73164379","session","user"]"
434 "Onyx.getAllKeys" 1353500.00ms 1353810.00ms 310.00ms "[]" "["account","betas","countryCode","credentials","cu…ort_73013597","report_73164379","session","user"]"
435 "Onyx.getAllKeys" 1353551.00ms 1353837.00ms 286.00ms "[]" "["account","betas","countryCode","credentials","cu…ort_73013597","report_73164379","session","user"]"
436 "Onyx.getAllKeys" 1353763.00ms 1353971.00ms 208.00ms "[]" "["account","betas","countryCode","credentials","cu…ort_73013597","report_73164379","session","user"]"
437 "Onyx.getAllKeys" 1353774.00ms 1353974.00ms 201.00ms "[]" "["account","betas","countryCode","credentials","cu…ort_73013597","report_73164379","session","user"]"

@kidroca
Copy link
Contributor Author

kidroca commented May 13, 2021

I have read the CLA Document and I hereby sign the CLA

@kidroca
Copy link
Contributor Author

kidroca commented May 13, 2021

recheck

@kidroca
Copy link
Contributor Author

kidroca commented May 13, 2021

Now that I look at the data merge does not seem to be measured very accurately

    if (mergeQueue[key]) {
        mergeQueue[key].push(val);
        return Promise.resolve();
    }

It returns early when it's filling a queue
So there are a lot of 7-10ms calls
And then one big call ranging between 100ms and 900ms

lib/Onyx.js Outdated
@@ -324,15 +314,15 @@ function connect(mapping) {
// React components are an exception since we'll want to send their
// initial data as a single object when using collection keys.
if (mapping.withOnyxInstance && isCollectionKey(mapping.key)) {
Promise.all(_.map(matchingKeys, key => get(key)))
Promise.all(_.map(matchingKeys, key => OnyxInternal.get(key)))
Copy link
Contributor Author

Choose a reason for hiding this comment

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

When this was just get we have no way to replace dynamically replace it with a decorated get that would collect statistics.
By providing get from an object - OnyxInternal.get - we can always change the method on the object to alter the implementation of get - in our case we decorate it with stats collection logic

Copy link
Contributor

@marcaaron marcaaron left a comment

Choose a reason for hiding this comment

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

This all looks pretty straightforward to me, but going to tag in @tgolen to give his thoughts.

@marcaaron
Copy link
Contributor

Now that I look at the data merge does not seem to be measured very accurately

Regarding this comment. The only calls to merge() that we are interested in measuring are the ones that write to disk. I don't have a perfect answer on how to get around that. But one complicated idea would be...

Make merge() privately and unreliably return a Promise that can be measured if one has been returned (e.g. check return value of calling _merge() to see if instanceof Promise and then have the public method always return void so .then() cannot be called on it). Not sure if the decorator pattern you are going for makes that easy or not.

A simpler alternative would be to just manually wrap all the promises we want to measure and tag them. But you'd have to unwind the decorator pattern stuff.

@marcaaron
Copy link
Contributor

Some methods cannot be tested as easy like the connect method, they would need some changes to incorporate the decorator - e.g. don't measure the whole connect but move the promise based logic to a separate method and measure that method - this way connect can still return a connectionID or a removeListener callback

Sounds like this could be another reason why benchmarking inline with a higher order function that wraps any Promise could be useful. This way we would not need to have methods that return Promise, but could track any Promise whether returned by a function or not. But I'll let you decide.

@kidroca kidroca changed the title Kidroca/benchmark Draft: Kidroca/benchmark May 13, 2021
@kidroca kidroca force-pushed the kidroca/benchmark branch from efb1e1e to eb7b109 Compare May 21, 2021 20:28
@kidroca kidroca force-pushed the kidroca/benchmark branch from 36ee6a4 to 6275a02 Compare May 21, 2021 21:47
@kidroca kidroca force-pushed the kidroca/benchmark branch from 6275a02 to 74809be Compare May 21, 2021 21:58
@kidroca
Copy link
Contributor Author

kidroca commented May 21, 2021

Updated

Addressed all the points in @marcaaron's comment
Added the snippet requested by @tgolen as Onyx.printMetrics + human friendly duration

This is an example output:

Onyx Benchmark
  Total:  135.9min
  Average:  45.3min

Onyx:get
  total: 51.5min
  max: 6.20sec
  min: 26.650ms
  avg: 4.24sec 
  calls: 728

Onyx:getAllKeys
  total: 84.3min
  max: 6.20sec
  min: 8.210ms
  avg: 3.78sec 
  calls: 1336

Onyx:set
  total: 10.09sec
  max: 5.01sec
  min: 43.125ms
  avg: 2.02sec 
  calls: 5

Total time is lot 135.9min because there are a lot of calls happening in parallel

React.Native.Debugger.-.Google.Chrome.2021-05-22.00-56-52.mp4

@tgolen

and then you had a personal code snippet that you were running from the JS console

I didn't run it through the console, I've added some code to E.cash to print statistics each time navigation state changed:

NavigationRoot.js

    parseAndStoreRoute(state) {
        if (!state) {
            return;
        }

        const path = getPathFromState(state, linkingConfig.config);
        setCurrentURL(path);

        // Added this (previously it was a method on this component)
        if (Onyx.printMetrics) {
            Onyx.printMetrics();
            Onyx.resetMetrics();
        }
    }

@marcaaron I've removed Onyx.isCapturingMetrics as you can see above, if Onyx is capturing metrics this method will be defined

@kidroca kidroca changed the title Draft: Kidroca/benchmark Feature: Benchmark Onyx May 21, 2021
@kidroca
Copy link
Contributor Author

kidroca commented May 21, 2021

Updated

Resolved merge conflicts

Copy link
Contributor

@marcaaron marcaaron left a comment

Choose a reason for hiding this comment

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

Code looking good, thanks for the changes!

Hooked this up on the web side and doesn't seem to be working with mergeCollection() any ideas why?

2021-05-21_13-03-46

@kidroca
Copy link
Contributor Author

kidroca commented May 21, 2021

Hooked this up on the web side and doesn't seem to be working with mergeCollection() any ideas why?

Yes I've just added a fix:

Because the original non decorated methods are instantly added to Onyx here:

const Onyx = {
    connect,
    disconnect,
    set,
    multiSet,
    merge,
    mergeCollection,
    clear,
    init,
    registerLogger,
    addToEvictionBlockList,
    removeFromEvictionBlockList,
    isSafeEvictionKey,
};

And this happens before init is called and the decorator applied

We need to re-expose them like so

In applyDecorators()

    // Re-expose decorated methods
    Onyx.set = set;
    Onyx.multiSet = multiSet;
    Onyx.clear = clear;
    Onyx.merge = merge;
    Onyx.mergeCollection = mergeCollection;

@kidroca kidroca requested a review from marcaaron May 21, 2021 23:55
@kidroca
Copy link
Contributor Author

kidroca commented May 24, 2021

Updated with requested changes

@kidroca kidroca requested a review from tgolen May 24, 2021 18:44
Copy link
Contributor

@marcaaron marcaaron left a comment

Choose a reason for hiding this comment

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

LGTM just had one NAB for a typo all you @Gonals

Comment on lines +27 to +30
/*
* Then handlers added here are not affecting the original promise
* They crate a separate chain that's not exposed (returned) to the original caller
* */
Copy link
Contributor

Choose a reason for hiding this comment

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

Suggested change
/*
* Then handlers added here are not affecting the original promise
* They crate a separate chain that's not exposed (returned) to the original caller
* */
// The handlers added here are not affecting the original promise
// They create a separate chain that's not exposed (returned) to the original caller

Copy link
Contributor

@Gonals Gonals left a comment

Choose a reason for hiding this comment

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

This looks good!

@Gonals Gonals merged commit 0cdf133 into Expensify:master May 25, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants