diff --git a/lib/decorateWithMetrics.js b/lib/decorateWithMetrics.js index 26f2c12d0..a439d0eff 100644 --- a/lib/decorateWithMetrics.js +++ b/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, totalTime: number}} + * Aggregates and returns benchmark information + * @returns {{summaries: Record, 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,6 +82,7 @@ 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, @@ -81,6 +90,7 @@ function getMetrics() { max, min, avg, + lastCall, calls, }]; }) @@ -88,16 +98,26 @@ function getMetrics() { .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 */ } diff --git a/tests/unit/decorateWithMetricsTest.js b/tests/unit/decorateWithMetricsTest.js index 0e5a9b852..befbb3e94 100644 --- a/tests/unit/decorateWithMetricsTest.js +++ b/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', () => {