Capture metrics using react-native-performance

lib/Onyx.js

@@ -749,7 +749,7 @@ const Onyx = {
  */
 function applyDecorators() {
     // We're requiring the script dynamically here so that it's only evaluated when decorators are used
-    const decorate = require('./decorateWithMetrics');
+    const decorate = require('./metrics');
 
     // Re-assign with decorated functions
     /* eslint-disable no-func-assign */

lib/decorateWithMetrics.js → lib/metrics.js

@@ -1,17 +1,31 @@
 import _ from 'underscore';
+import performance from 'react-native-performance';
 import MDTable from './MDTable';
 
+const decoratedAliases = new Set();
+
 /**
- * Each key is a method name and the value is an array of calls metadata
- * @type {Record<String, Array<Object>>}
+ * Capture a start mark to performance entries
+ * @param {string} alias
+ * @param {Array<*>} args
+ * @returns {{name: string, startTime:number, detail: {args: [], alias: string}}}
  */
-let stats = {};
+function addMark(alias, args) {
+    return performance.mark(alias, {detail: {args, alias}});
+}
 
-/* For some reason `performance.now()` does not start from `0` but a very large offset
-* like `508,080,000` see: https://github.com/facebook/react-native/issues/30069
-* Capturing an offset allows us to record start/ends times relative to app launch time
-* It also allows us to compare start/end times relative to the last resetMetrics */
-let PERFORMANCE_OFFSET = performance.now();
+/**
+ * Capture a measurement between the start mark and now
+ * @param {{name: string, startTime:number, detail: {args: []}}} startMark
+ * @param {*} detail
+ */
+function measureMarkToNow(startMark, detail) {
+    performance.measure(`${startMark.name} [${startMark.detail.args.toString()}]`, {
+        start: startMark.startTime,
+        end: performance.now(),
+        detail: {...startMark.detail, ...detail}
+    });
+}
 
 /**
  * Wraps a function with metrics capturing logic
@@ -20,14 +34,14 @@ let PERFORMANCE_OFFSET = performance.now();
  * @returns {function} The wrapped function
  */
 function decorateWithMetrics(func, alias = func.name) {
-    if (_.has(stats, alias)) {
+    if (decoratedAliases.has(alias)) {
         throw new Error(`"${alias}" is already decorated`);
     }
 
-    stats[alias] = [];
+    decoratedAliases.add(alias);
 
     function decorated(...args) {
-        const startTime = performance.now() - PERFORMANCE_OFFSET;
+        const mark = addMark(alias, args);
 
         const originalPromise = func.apply(this, args);
 
@@ -36,21 +50,11 @@ function decorateWithMetrics(func, alias = func.name) {
         * They create a separate chain that's not exposed (returned) to the original caller
         * */
         originalPromise
-            .finally(() => {
-                const endTime = performance.now() - PERFORMANCE_OFFSET;
-
-                if (!_.has(stats, alias)) {
-                    stats[alias] = [];
-                }
-
-                const methodStats = stats[alias];
-                methodStats.push({
-                    methodName: alias,
-                    startTime,
-                    endTime,
-                    duration: endTime - startTime,
-                    args,
-                });
+            .then((result) => {
+                measureMarkToNow(mark, {result});
+            })
+            .catch((error) => {
+                measureMarkToNow(mark, {error});
             });
 
         return originalPromise;
@@ -78,13 +82,15 @@ function sum(list, prop) {
  * - `summaries` - mapping of all captured stats: summaries.methodName -> method stats
  */
 function getMetrics() {
-    const summaries = _.chain(stats)
+    const summaries = _.chain(performance.getEntriesByType('measure'))
+        .filter(entry => entry.detail && decoratedAliases.has(entry.detail.alias))
+        .groupBy(entry => entry.detail.alias)
         .map((calls, methodName) => {
             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;
-            const lastCall = _.max(calls, 'endTime');
+            const lastCall = _.max(calls, call => call.startTime + call.duration);
 
             return [methodName, {
                 methodName,
@@ -100,7 +106,7 @@ function getMetrics() {
         .value();
 
     const totalTime = sum(_.values(summaries), 'total');
-    const lastCompleteCall = _.max(_.values(summaries), ['lastCall', 'endTime']).lastCall;
+    const lastCompleteCall = _.max(_.values(summaries), ['lastCall', 'startTime']).lastCall;
 
     return {
         totalTime,
@@ -156,6 +162,7 @@ function printMetrics({raw = false, format = 'console', methods} = {}) {
     });
 
     const methodNames = _.isArray(methods) ? methods : _.keys(summaries);
+    const timeOrigin = performance.timeOrigin;
 
     const methodCallTables = _.chain(methodNames)
         .filter(methodName => summaries[methodName] && summaries[methodName].avg > 0)
@@ -167,7 +174,7 @@ function printMetrics({raw = false, format = 'console', methods} = {}) {
                 toDuration(methodStats.max, raw),
                 toDuration(methodStats.min, raw),
                 toDuration(methodStats.avg, raw),
-                toDuration(methodStats.lastCall.endTime, raw),
+                toDuration((methodStats.lastCall.startTime + methodStats.lastCall.duration) - timeOrigin, raw),
                 calls.length,
             );
 
@@ -176,10 +183,10 @@ function printMetrics({raw = false, format = 'console', methods} = {}) {
                 heading: ['start time', 'end time', 'duration', 'args'],
                 leftAlignedCols: [3],
                 rows: calls.map(call => ([
-                    toDuration(call.startTime, raw),
-                    toDuration(call.endTime, raw),
+                    toDuration(call.startTime - performance.timeOrigin, raw),
+                    toDuration((call.startTime + call.duration) - timeOrigin, raw),
                     toDuration(call.duration, raw),
-                    call.args.map(String).join(', ').slice(0, 60), // Restrict cell width to 60 chars max
+                    call.detail.args.map(String).join(', ').slice(0, 60), // Restrict cell width to 60 chars max
                 ]))
             });
 
@@ -202,10 +209,14 @@ function printMetrics({raw = false, format = 'console', methods} = {}) {
         }).join('\n\n');
     }
 
+    const lastComplete = lastCompleteCall && toDuration(
+        (lastCompleteCall.startTime + lastCompleteCall.duration) - timeOrigin, raw
+    );
+
     const mainOutput = [
         '### Onyx Benchmark',
         `  - Total: ${toDuration(totalTime, raw)}`,
-        `  - Last call finished at: ${lastCompleteCall ? toDuration(lastCompleteCall.endTime, raw) : 'N/A'}`,
+        `  - Last call finished at: ${lastComplete || 'N/A'}`,
         '',
         tableSummary.toString()
     ];
@@ -224,8 +235,15 @@ function printMetrics({raw = false, format = 'console', methods} = {}) {
  * Clears all collected metrics.
  */
 function resetMetrics() {
-    PERFORMANCE_OFFSET = performance.now();
-    stats = {};
+    const {summaries} = getMetrics();
+
+    _.chain(summaries)
+        .map(summary => summary.calls)
+        .flatten()
+        .each((measure) => {
+            performance.clearMarks(measure.detail.alias);
+            performance.clearMeasures(measure.name);
+        });
 }
 
 export {

package.json

@@ -39,12 +39,19 @@
     "prop-types": "^15.7.2",
     "react": "^17.0.2",
     "react-native": "0.64.1",
+    "react-native-performance": "^2.0.0",
     "react-test-renderer": "16.13.1",
     "metro-react-native-babel-preset": "^0.61.0"
   },
   "peerDependencies": {
     "@react-native-async-storage/async-storage": "^1.15.5",
-    "react": "^17.0.2"
+    "react": "^17.0.2",
+    "react-native-performance": "^2.0.0"
+  },
+  "peerDependenciesMeta": {
+    "react-native-performance": {
+      "optional": true
+    }
   },
   "jest": {
     "preset": "react-native",

tests/unit/decorateWithMetricsTest.js → tests/unit/metricsTest.js

@@ -1,13 +1,16 @@
-import {
-    decorateWithMetrics,
-    getMetrics,
-    resetMetrics
-} from '../../lib/decorateWithMetrics';
+
 import waitForPromisesToResolve from '../utils/waitForPromisesToResolve';
 
 describe('decorateWithMetrics', () => {
-    beforeEach(() => waitForPromisesToResolve()
-        .then(resetMetrics));
+    let decorateWithMetrics; let getMetrics; let resetMetrics;
+
+    beforeEach(() => {
+        jest.resetModules();
+        const metrics = require('../../lib/metrics');
+        decorateWithMetrics = metrics.decorateWithMetrics;
+        getMetrics = metrics.getMetrics;
+        resetMetrics = metrics.resetMetrics;
+    });
 
     it('Should collect metrics for a single method, single call', () => {
         // GIVEN an async function that resolves with an object
@@ -32,8 +35,7 @@ describe('decorateWithMetrics', () => {
 
                 const firstCall = metrics.summaries.mockFn.calls[0];
                 expect(firstCall.startTime).toEqual(expect.any(Number));
-                expect(firstCall.endTime).toEqual(expect.any(Number));
-                expect(firstCall.args).toEqual(['mockedKey']);
+                expect(firstCall.detail.args).toEqual(['mockedKey']);
             });
     });
 
@@ -78,9 +80,15 @@ describe('decorateWithMetrics', () => {
                 const calls = getMetrics().summaries.mockFn.calls;
                 expect(calls).toHaveLength(3);
                 expect(calls).toEqual([
-                    expect.objectContaining({args: ['mockedKey']}),
-                    expect.objectContaining({args: ['mockedKey3']}),
-                    expect.objectContaining({args: ['mockedKey2']}),
+                    expect.objectContaining({
+                        detail: expect.objectContaining({args: ['mockedKey']})
+                    }),
+                    expect.objectContaining({
+                        detail: expect.objectContaining({args: ['mockedKey3']})
+                    }),
+                    expect.objectContaining({
+                        detail: expect.objectContaining({args: ['mockedKey2']})
+                    }),
                 ]);
             });
     });
@@ -102,8 +110,12 @@ describe('decorateWithMetrics', () => {
                 const calls = getMetrics().summaries.mockFn.calls;
                 expect(calls).toHaveLength(2);
                 expect(calls).toEqual([
-                    expect.objectContaining({args: ['mockedKey', {ids: [1, 2, 3]}]}),
-                    expect.objectContaining({args: ['mockedKey', {ids: [4, 5, 6]}]}),
+                    expect.objectContaining({
+                        detail: {args: ['mockedKey', {ids: [1, 2, 3]}], alias: 'mockFn'}
+                    }),
+                    expect.objectContaining({
+                        detail: {args: ['mockedKey', {ids: [4, 5, 6]}], alias: 'mockFn'}
+                    }),
                 ]);
             });
     });