Merge pull request #89 from kidroca/kidroca/better-print-format

Update Onyx.printMetrics format

lib/decorateWithMetrics.js

@@ -6,6 +6,11 @@ import _ from 'underscore';
  */
 let stats = {};
 
+/* 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 */
+const APP_LAUNCH_TIME = performance.now();
+
 /**
  * Wraps a function with metrics capturing logic
  * @param {function} func
@@ -20,7 +25,7 @@ function decorateWithMetrics(func, alias = func.name) {
     stats[alias] = [];
 
     function decorated(...args) {
-        const startTime = performance.now();
+        const startTime = performance.now() - APP_LAUNCH_TIME;
 
         const originalPromise = func.apply(this, args);
 
@@ -30,7 +35,7 @@ function decorateWithMetrics(func, alias = func.name) {
         * */
         originalPromise
             .finally(() => {
-                const endTime = performance.now();
+                const endTime = performance.now() - APP_LAUNCH_TIME;
 
                 if (!_.has(stats, alias)) {
                     stats[alias] = [];
@@ -62,9 +67,12 @@ function sum(list, prop) {
 }
 
 /**
- * Returns total, average time and all captured stats mapped under
- * summaries.methodName -> method stats
- * @returns {{averageTime: number, summaries: Record<string, Object>, totalTime: number}}
+ * Aggregates and returns benchmark information
+ * @returns {{summaries: Record<string, Object>, totalTime: number, lastCompleteCall: *}}
+ * An object with
+ * - `totalTime` - total time spent by decorated methods
+ * - `lastCompleteCall` - millisecond since launch the last call completed at
+ * - `summaries` - mapping of all captured stats: summaries.methodName -> method stats
  */
 function getMetrics() {
     const summaries = _.chain(stats)
@@ -74,30 +82,42 @@ function getMetrics() {
             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');
 
             return [methodName, {
                 methodName,
                 total,
                 max,
                 min,
                 avg,
+                lastCall,
                 calls,
             }];
         })
         .object() // Create a map like methodName -> StatSummary
         .value();
 
     const totalTime = sum(_.values(summaries), 'total');
-    const averageTime = (totalTime / _.size(summaries)) || 0;
+    const lastCompleteCall = _.max(_.values(summaries), ['lastCall', 'endTime']).lastCall;
 
     return {
         totalTime,
-        averageTime,
         summaries,
+        lastCompleteCall,
     };
 }
 
-function toHumanReadableDuration(millis) {
+/**
+ * Convert milliseconds to human readable time
+ * @param {number} millis
+ * @param {boolean} [raw=false]
+ * @returns {string|number}
+ */
+function toDuration(millis, raw = false) {
+    if (raw) {
+        return millis;
+    }
+
     const minute = 60 * 1000;
     if (millis > minute) {
         return `${(millis / minute).toFixed(1)}min`;
@@ -115,30 +135,55 @@ function toHumanReadableDuration(millis) {
  * Print extensive information on the dev console
  * max, min, average, total time for each method
  * and a table of individual calls
+ *
+ * @param {boolean} [raw=false] setting this to true will print raw instead of human friendly times
+ * Useful when you copy the printed table to excel and let excel do the number formatting
  */
-function printMetrics() {
-    const {totalTime, averageTime, summaries} = getMetrics();
+function printMetrics(raw = false) {
+    const {totalTime, summaries, lastCompleteCall = {endTime: -1}} = getMetrics();
 
-    /* eslint-disable no-console */
-    console.group('Onyx Benchmark');
-    console.info('  Total: ', toHumanReadableDuration(totalTime));
-    console.info('  Average: ', toHumanReadableDuration(averageTime));
-
-    _.chain(summaries)
+    const prettyData = _.chain(summaries)
+        .filter(method => method.avg > 0)
         .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),
+        .map(({
+            calls, methodName, lastCall, ...summary
+        }) => {
+            const prettyTimes = _.chain(summary)
+                .map((value, key) => ([key, toDuration(value, raw)]))
+                .object()
+                .value();
+
+            const prettyCalls = calls.map(call => ({
+                startTime: toDuration(call.startTime, raw),
+                endTime: toDuration(call.endTime, raw),
+                duration: toDuration(call.duration, raw),
                 args: JSON.stringify(call.args)
-            })));
-            console.groupEnd();
-        });
+            }));
+
+            return {
+                methodName,
+                ...prettyTimes,
+                'time last call completed': toDuration(lastCall.endTime, raw),
+                calls: calls.length,
+                prettyCalls,
+            };
+        })
+        .value();
+
+    /* eslint-disable no-console */
+    console.group('Onyx Benchmark');
+    console.info('  Total: ', toDuration(totalTime, raw));
+    console.info('  Last call finished at: ', toDuration(lastCompleteCall.endTime, raw));
+
+    console.table(prettyData.map(({prettyCalls, ...summary}) => summary));
+
+    prettyData.forEach((method) => {
+        console.groupCollapsed(`[${method.methodName}] individual calls: `);
+        console.table(method.prettyCalls);
+        console.groupEnd();
+    });
+
     console.groupEnd();
     /* eslint-enable */
 }

tests/unit/decorateWithMetricsTest.js

@@ -24,7 +24,7 @@ describe('decorateWithMetrics', () => {
                 const metrics = getMetrics();
                 expect(metrics).toEqual(expect.objectContaining({
                     totalTime: expect.any(Number),
-                    averageTime: expect.any(Number),
+                    lastCompleteCall: expect.any(Object),
                     summaries: expect.objectContaining({mockFn: expect.any(Object)}),
                 }));
 
@@ -264,7 +264,7 @@ describe('decorateWithMetrics', () => {
         // THEN stats should be empty and the total time 0
         expect(result.summaries).toEqual({});
         expect(result.totalTime).toEqual(0);
-        expect(result.averageTime).toEqual(0);
+        expect(result.lastCompleteCall).not.toBeDefined();
     });
 
     it('Should calculate total and average correctly', () => {