Merge pull request #70 from kidroca/kidroca/benchmark

Feature: Benchmark Onyx

Author: Gonals

.gitignore

@@ -6,3 +6,6 @@
 #
 node_modules/
 npm-debug.log
+
+# IDEs
+.idea

README.md

@@ -39,3 +39,51 @@ export default withOnyx({
     },
 })(ReportActionsView);
 ```
+
+### Benchmarks
+
+Provide the `captureMetrics` boolean flag to `Onyx.init` to capture call statistics
+
+```js
+Onyx.init({
+    keys: ONYXKEYS,
+    safeEvictionKeys: [ONYXKEYS.COLLECTION.REPORT_ACTIONS],
+    captureMetrics: Config.BENCHMARK_ONYX,
+});
+```
+
+At any point you can get the collected statistics using `Onyx.getMetrics()`.
+This will return an object containing `totalTime`, `averageTime` and `summaries`.
+`summaries` is a collection of statistics for each method it contains data about:
+  - method name
+  - total, max, min, average times for this method calls
+  - calls - a list of individual calls with each having: start time; end time; call duration; call arguments
+    - start/end times are relative to application launch time - 0.00 being exactly at launch
+
+If you wish to reset the metrics and start over use `Onyx.resetMetrics()`
+
+Finally, there's a `Onyx.printMetrics()` method which prints human friendly statistics information on the dev console
+You can use this method during debugging e.g. add an `Onyx.printMetrics()` line somewhere in code or call it
+through the dev console. 
+
+Sample output of `Onyx.printMetrics()`
+
+```
+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
+```

lib/Onyx.js

@@ -28,7 +28,6 @@ const evictionBlocklist = {};
 let defaultKeyStates = {};
 
 /**
- * When a key change happens, search for any callbacks matching the regex pattern and trigger those callbacks
  * Get some data from the store
  *
  * @param {string} key
@@ -40,6 +39,14 @@ function get(key) {
         .catch(err => logInfo(`Unable to get item from persistent storage. Key: ${key} Error: ${err}`));
 }
 
+/**
+ * Returns current key names stored in persisted storage
+ * @returns {Promise<string[]>}
+ */
+function getAllKeys() {
+    return AsyncStorage.getAllKeys();
+}
+
 /**
  * Checks to see if the a subscriber's supplied key
  * is associated with a collection of keys.
@@ -141,7 +148,7 @@ function addToEvictionBlockList(key, connectionID) {
  * removed.
  */
 function addAllSafeEvictionKeysToRecentlyAccessedList() {
-    AsyncStorage.getAllKeys()
+    getAllKeys()
         .then((keys) => {
             _.each(evictionAllowList, (safeEvictionKey) => {
                 _.each(keys, (key) => {
@@ -310,7 +317,7 @@ function connect(mapping) {
         addLastAccessedKey(mapping.key);
     }
 
-    AsyncStorage.getAllKeys()
+    getAllKeys()
         .then((keys) => {
             // Find all the keys matched by the config key
             const matchingKeys = _.filter(keys, key => isKeyMatch(mapping.key, key));
@@ -482,22 +489,23 @@ function applyMerge(key, data) {
  *
  * @param {string} key
  * @param {*} val
+ * @returns {Promise}
  */
 function merge(key, val) {
     if (mergeQueue[key]) {
         mergeQueue[key].push(val);
-        return;
+        return Promise.resolve();
     }
 
     mergeQueue[key] = [val];
-    get(key)
+    return get(key)
         .then((data) => {
             const modifiedData = applyMerge(key, data);
 
             // Clean up the write queue so we
             // don't apply these changes again
             delete mergeQueue[key];
-            set(key, modifiedData);
+            return set(key, modifiedData);
         });
 }
 
@@ -515,7 +523,7 @@ function initializeWithDefaultKeyStates() {
  */
 function clear() {
     let allKeys;
-    return AsyncStorage.getAllKeys()
+    return getAllKeys()
         .then(keys => allKeys = keys)
         .then(() => AsyncStorage.clear())
         .then(() => {
@@ -545,7 +553,7 @@ function mergeCollection(collectionKey, collection) {
 
     const existingKeyCollection = {};
     const newCollection = {};
-    return AsyncStorage.getAllKeys()
+    return getAllKeys()
         .then((keys) => {
             _.each(collection, (data, dataKey) => {
                 if (keys.includes(dataKey)) {
@@ -586,13 +594,21 @@ function mergeCollection(collectionKey, collection) {
  * @param {function} registerStorageEventListener a callback when a storage event happens.
  * This applies to web platforms where the local storage emits storage events
  * across all open tabs and allows Onyx to stay in sync across all open tabs.
+ * @param {Boolean} [options.captureMetrics]
  */
 function init({
     keys,
     initialKeyStates,
     safeEvictionKeys,
-    registerStorageEventListener
+    registerStorageEventListener,
+    captureMetrics = false,
 }) {
+    if (captureMetrics) {
+        // The code here is only bundled and applied when the captureMetrics is set
+        // eslint-disable-next-line no-use-before-define
+        applyDecorators();
+    }
+
     // Let Onyx know about all of our keys
     onyxKeys = keys;
 
@@ -625,4 +641,35 @@ const Onyx = {
     isSafeEvictionKey,
 };
 
+/**
+ * Apply calls statistic decorators to benchmark Onyx
+ */
+function applyDecorators() {
+    // We're requiring the script dynamically here so that it's only evaluated when decorators are used
+    const decorate = require('./decorateWithMetrics');
+
+    // Re-assign with decorated functions
+    /* eslint-disable no-func-assign */
+    get = decorate.decorateWithMetrics(get, 'Onyx:get');
+    set = decorate.decorateWithMetrics(set, 'Onyx:set');
+    multiSet = decorate.decorateWithMetrics(multiSet, 'Onyx:multiSet');
+    clear = decorate.decorateWithMetrics(clear, 'Onyx:clear');
+    merge = decorate.decorateWithMetrics(merge, 'Onyx:merge');
+    mergeCollection = decorate.decorateWithMetrics(mergeCollection, 'Onyx:mergeCollection');
+    getAllKeys = decorate.decorateWithMetrics(getAllKeys, 'Onyx:getAllKeys');
+    /* eslint-enable */
+
+    // Re-expose decorated methods
+    Onyx.set = set;
+    Onyx.multiSet = multiSet;
+    Onyx.clear = clear;
+    Onyx.merge = merge;
+    Onyx.mergeCollection = mergeCollection;
+
+    // Expose stats methods on Onyx
+    Onyx.getMetrics = decorate.getMetrics;
+    Onyx.resetMetrics = decorate.resetMetrics;
+    Onyx.printMetrics = decorate.printMetrics;
+}
+
 export default Onyx;

lib/decorateWithMetrics.js

@@ -0,0 +1,158 @@
+import _ from 'underscore';
+
+/**
+ * Each key is a method name and the value is an array of calls metadata
+ * @type {Record<String, Array<Object>>}
+ */
+let stats = {};
+
+/**
+ * Wraps a function with metrics capturing logic
+ * @param {function} func
+ * @param {String} [alias]
+ * @returns {function} The wrapped function
+ */
+function decorateWithMetrics(func, alias = func.name) {
+    if (_.has(stats, alias)) {
+        throw new Error(`"${alias}" is already decorated`);
+    }
+
+    stats[alias] = [];
+
+    function decorated(...args) {
+        const startTime = performance.now();
+
+        const originalPromise = func.apply(this, args);
+
+        /*
+        * Then handlers added here are not affecting the original promise
+        * They crate a separate chain that's not exposed (returned) to the original caller
+        * */
+        originalPromise
+            .finally(() => {
+                const endTime = performance.now();
+
+                if (!_.has(stats, alias)) {
+                    stats[alias] = [];
+                }
+
+                const methodStats = stats[alias];
+                methodStats.push({
+                    methodName: alias,
+                    startTime,
+                    endTime,
+                    args,
+                });
+            });
+
+        return originalPromise;
+    }
+
+    return decorated;
+}
+
+/**
+ * Calculate the total sum of a given key in a list
+ * @param {Array<Record<prop, Number>>} list
+ * @param {string} prop
+ * @returns {number}
+ */
+function sum(list, prop) {
+    return _.reduce(list, (memo, next) => memo + next[prop], 0);
+}
+
+/**
+ * Returns total, average time and all captured stats mapped under
+ * summaries.methodName -> method stats
+ * @returns {{averageTime: number, summaries: Record<string, Object>, totalTime: number}}
+ */
+function getMetrics() {
+    const summaries = _.chain(stats)
+        .map((data, methodName) => {
+            const calls = _.map(data, call => ({...call, duration: call.endTime - call.startTime}));
+            const total = sum(calls, 'duration');
+            const avg = (total / calls.length) || 0;
+            const max = _.max(calls, 'duration').duration || 0;
+            const min = _.min(calls, 'duration').duration || 0;
+
+            return [methodName, {
+                methodName,
+                total,
+                max,
+                min,
+                avg,
+                calls,
+            }];
+        })
+        .object() // Create a map like methodName -> StatSummary
+        .value();
+
+    const totalTime = sum(_.values(summaries), 'total');
+    const averageTime = (totalTime / _.size(summaries)) || 0;
+
+    return {
+        totalTime,
+        averageTime,
+        summaries,
+    };
+}
+
+function toHumanReadableDuration(millis) {
+    const minute = 60 * 1000;
+    if (millis > minute) {
+        return `${(millis / minute).toFixed(1)}min`;
+    }
+
+    const second = 1000;
+    if (millis > second) {
+        return `${(millis / second).toFixed(2)}sec`;
+    }
+
+    return `${millis.toFixed(3)}ms`;
+}
+
+/**
+ * Print extensive information on the dev console
+ * max, min, average, total time for each method
+ * and a table of individual calls
+ */
+function printMetrics() {
+    const {totalTime, averageTime, summaries} = getMetrics();
+
+    /* eslint-disable no-console */
+    console.group('Onyx Benchmark');
+    console.info('  Total: ', toHumanReadableDuration(totalTime));
+    console.info('  Average: ', toHumanReadableDuration(averageTime));
+
+    _.chain(summaries)
+        .sortBy('avg')
+        .reverse()
+        .forEach(({calls, methodName, ...summary}) => {
+            const times = _.map(summary, (value, key) => `${key}: ${toHumanReadableDuration(value)}`);
+
+            console.groupCollapsed(`${methodName}\n  ${times.join('\n  ')} \n  calls: ${calls.length}`);
+            console.table(calls.map(call => ({
+                startTime: toHumanReadableDuration(call.startTime),
+                endTime: toHumanReadableDuration(call.endTime),
+                duration: toHumanReadableDuration(call.duration),
+                args: JSON.stringify(call.args)
+            })));
+            console.groupEnd();
+        });
+    console.groupEnd();
+    /* eslint-enable */
+}
+
+/**
+ * Clears all collected metrics.
+ */
+function resetMetrics() {
+    stats = {};
+}
+
+export {
+    decorateWithMetrics,
+    getMetrics,
+    resetMetrics,
+    printMetrics,
+};