From a06856e4c2119af1cac4cad18be95f7a4a3cebdf Mon Sep 17 00:00:00 2001 From: Peter Velkov Date: Wed, 14 Jul 2021 14:32:26 +0300 Subject: [PATCH 1/7] Updated Onyx.printMetrics functionality - easier copy to excel --- lib/decorateWithMetrics.js | 45 +++++++++++++++++++++++++++----------- 1 file changed, 32 insertions(+), 13 deletions(-) diff --git a/lib/decorateWithMetrics.js b/lib/decorateWithMetrics.js index 26f2c12d..8f42c56b 100644 --- a/lib/decorateWithMetrics.js +++ b/lib/decorateWithMetrics.js @@ -119,26 +119,45 @@ function toHumanReadableDuration(millis) { 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) + 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)}`); + .map(({calls, methodName, ...summary}) => { + const prettyTimes = _.chain(summary) + .map((value, key) => ([key, toHumanReadableDuration(value)])) + .object() + .value(); - console.groupCollapsed(`${methodName}\n ${times.join('\n ')} \n calls: ${calls.length}`); - console.table(calls.map(call => ({ + const prettyCalls = calls.map(call => ({ startTime: toHumanReadableDuration(call.startTime), endTime: toHumanReadableDuration(call.endTime), duration: toHumanReadableDuration(call.duration), args: JSON.stringify(call.args) - }))); - console.groupEnd(); - }); + })); + + return { + methodName, + ...prettyTimes, + calls: calls.length, + prettyCalls, + }; + }) + .value(); + + /* eslint-disable no-console */ + console.group('Onyx Benchmark'); + console.info(' Total: ', toHumanReadableDuration(totalTime)); + console.info(' Average: ', toHumanReadableDuration(averageTime)); + + 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 */ } From e8413b0efff8d93e9f654451e5f32f36b2680fb2 Mon Sep 17 00:00:00 2001 From: Peter Velkov Date: Fri, 16 Jul 2021 01:26:19 +0300 Subject: [PATCH 2/7] Remove top level `averageTime` This doesn't represent accurate or useful information It was just the total time divided by the count of decorated methods --- lib/decorateWithMetrics.js | 7 ++----- 1 file changed, 2 insertions(+), 5 deletions(-) diff --git a/lib/decorateWithMetrics.js b/lib/decorateWithMetrics.js index 8f42c56b..4265c0ae 100644 --- a/lib/decorateWithMetrics.js +++ b/lib/decorateWithMetrics.js @@ -64,7 +64,7 @@ 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}} + * @returns {{summaries: Record, totalTime: number}} */ function getMetrics() { const summaries = _.chain(stats) @@ -88,11 +88,9 @@ function getMetrics() { .value(); const totalTime = sum(_.values(summaries), 'total'); - const averageTime = (totalTime / _.size(summaries)) || 0; return { totalTime, - averageTime, summaries, }; } @@ -117,7 +115,7 @@ function toHumanReadableDuration(millis) { * and a table of individual calls */ function printMetrics() { - const {totalTime, averageTime, summaries} = getMetrics(); + const {totalTime, summaries} = getMetrics(); const prettyData = _.chain(summaries) .filter(method => method.avg > 0) @@ -148,7 +146,6 @@ function printMetrics() { /* eslint-disable no-console */ console.group('Onyx Benchmark'); console.info(' Total: ', toHumanReadableDuration(totalTime)); - console.info(' Average: ', toHumanReadableDuration(averageTime)); console.table(prettyData.map(({prettyCalls, ...summary}) => summary)); From 5fae00cc616637802289cc77622a219d35115727 Mon Sep 17 00:00:00 2001 From: Peter Velkov Date: Fri, 16 Jul 2021 02:02:44 +0300 Subject: [PATCH 3/7] Capture the last call of decorated methods --- lib/decorateWithMetrics.js | 14 +++++++++++--- 1 file changed, 11 insertions(+), 3 deletions(-) diff --git a/lib/decorateWithMetrics.js b/lib/decorateWithMetrics.js index 4265c0ae..71f90f42 100644 --- a/lib/decorateWithMetrics.js +++ b/lib/decorateWithMetrics.js @@ -64,7 +64,7 @@ function sum(list, prop) { /** * Returns total, average time and all captured stats mapped under * summaries.methodName -> method stats - * @returns {{summaries: Record, totalTime: number}} + * @returns {{summaries: Record, totalTime: number, lastCompleteCall: *}} */ function getMetrics() { const summaries = _.chain(stats) @@ -74,6 +74,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 +82,7 @@ function getMetrics() { max, min, avg, + lastCall, calls, }]; }) @@ -88,10 +90,12 @@ function getMetrics() { .value(); const totalTime = sum(_.values(summaries), 'total'); + const lastCompleteCall = _.max(_.values(summaries), ['lastCall', 'endTime']); return { totalTime, summaries, + lastCompleteCall, }; } @@ -115,13 +119,15 @@ function toHumanReadableDuration(millis) { * and a table of individual calls */ function printMetrics() { - const {totalTime, summaries} = getMetrics(); + const {totalTime, summaries, lastCompleteCall = {endTime: -1}} = getMetrics(); const prettyData = _.chain(summaries) .filter(method => method.avg > 0) .sortBy('avg') .reverse() - .map(({calls, methodName, ...summary}) => { + .map(({ + calls, methodName, lastCall, ...summary + }) => { const prettyTimes = _.chain(summary) .map((value, key) => ([key, toHumanReadableDuration(value)])) .object() @@ -137,6 +143,7 @@ function printMetrics() { return { methodName, ...prettyTimes, + last: toHumanReadableDuration(lastCall.endTime), calls: calls.length, prettyCalls, }; @@ -146,6 +153,7 @@ function printMetrics() { /* eslint-disable no-console */ console.group('Onyx Benchmark'); console.info(' Total: ', toHumanReadableDuration(totalTime)); + console.info(' Last call made at: ', toHumanReadableDuration(lastCompleteCall.endTime)); console.table(prettyData.map(({prettyCalls, ...summary}) => summary)); From 9a1e475ab5a64ee3bebc57eb333cf532185632cf Mon Sep 17 00:00:00 2001 From: Peter Velkov Date: Fri, 16 Jul 2021 02:20:58 +0300 Subject: [PATCH 4/7] Add an override parameter to print raw times For example copying the raw data to excel allow for easier formatting sorting and other math operations --- lib/decorateWithMetrics.js | 31 ++++++++++++++++++++++--------- 1 file changed, 22 insertions(+), 9 deletions(-) diff --git a/lib/decorateWithMetrics.js b/lib/decorateWithMetrics.js index 71f90f42..931a92e2 100644 --- a/lib/decorateWithMetrics.js +++ b/lib/decorateWithMetrics.js @@ -99,7 +99,17 @@ function getMetrics() { }; } -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`; @@ -117,8 +127,11 @@ 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() { +function printMetrics(raw = false) { const {totalTime, summaries, lastCompleteCall = {endTime: -1}} = getMetrics(); const prettyData = _.chain(summaries) @@ -129,21 +142,21 @@ function printMetrics() { calls, methodName, lastCall, ...summary }) => { const prettyTimes = _.chain(summary) - .map((value, key) => ([key, toHumanReadableDuration(value)])) + .map((value, key) => ([key, toDuration(value, raw)])) .object() .value(); const prettyCalls = calls.map(call => ({ - startTime: toHumanReadableDuration(call.startTime), - endTime: toHumanReadableDuration(call.endTime), - duration: toHumanReadableDuration(call.duration), + startTime: toDuration(call.startTime, raw), + endTime: toDuration(call.endTime, raw), + duration: toDuration(call.duration, raw), args: JSON.stringify(call.args) })); return { methodName, ...prettyTimes, - last: toHumanReadableDuration(lastCall.endTime), + last: toDuration(lastCall.endTime, raw), calls: calls.length, prettyCalls, }; @@ -152,8 +165,8 @@ function printMetrics() { /* eslint-disable no-console */ console.group('Onyx Benchmark'); - console.info(' Total: ', toHumanReadableDuration(totalTime)); - console.info(' Last call made at: ', toHumanReadableDuration(lastCompleteCall.endTime)); + console.info(' Total: ', toDuration(totalTime, raw)); + console.info(' Last call made at: ', toDuration(lastCompleteCall.endTime, raw)); console.table(prettyData.map(({prettyCalls, ...summary}) => summary)); From d15c407bb58216bd82102c0ca6f659b0200dc0bb Mon Sep 17 00:00:00 2001 From: Peter Velkov Date: Fri, 16 Jul 2021 02:34:52 +0300 Subject: [PATCH 5/7] Update decoration tests after changes --- lib/decorateWithMetrics.js | 2 +- tests/unit/decorateWithMetricsTest.js | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/lib/decorateWithMetrics.js b/lib/decorateWithMetrics.js index 931a92e2..6e7fd3ae 100644 --- a/lib/decorateWithMetrics.js +++ b/lib/decorateWithMetrics.js @@ -90,7 +90,7 @@ function getMetrics() { .value(); const totalTime = sum(_.values(summaries), 'total'); - const lastCompleteCall = _.max(_.values(summaries), ['lastCall', 'endTime']); + const lastCompleteCall = _.max(_.values(summaries), ['lastCall', 'endTime']).lastCall; return { totalTime, diff --git a/tests/unit/decorateWithMetricsTest.js b/tests/unit/decorateWithMetricsTest.js index 0e5a9b85..befbb3e9 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', () => { From 897ba8b864090045b76d9d67ad1a56d408a659f0 Mon Sep 17 00:00:00 2001 From: Peter Velkov Date: Fri, 16 Jul 2021 12:49:31 +0300 Subject: [PATCH 6/7] Fix Onyx.printMetrics descriptions and column names --- lib/decorateWithMetrics.js | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/lib/decorateWithMetrics.js b/lib/decorateWithMetrics.js index 6e7fd3ae..b83c0a7c 100644 --- a/lib/decorateWithMetrics.js +++ b/lib/decorateWithMetrics.js @@ -62,9 +62,12 @@ function sum(list, prop) { } /** - * Returns total, average time and all captured stats mapped under - * summaries.methodName -> method stats + * 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) @@ -156,7 +159,7 @@ function printMetrics(raw = false) { return { methodName, ...prettyTimes, - last: toDuration(lastCall.endTime, raw), + 'time last call completed': toDuration(lastCall.endTime, raw), calls: calls.length, prettyCalls, }; @@ -166,7 +169,7 @@ function printMetrics(raw = false) { /* eslint-disable no-console */ console.group('Onyx Benchmark'); console.info(' Total: ', toDuration(totalTime, raw)); - console.info(' Last call made at: ', toDuration(lastCompleteCall.endTime, raw)); + console.info(' Last call finished at: ', toDuration(lastCompleteCall.endTime, raw)); console.table(prettyData.map(({prettyCalls, ...summary}) => summary)); From 541279a90b5893835a62c4cd46a1050e7d2d4674 Mon Sep 17 00:00:00 2001 From: Peter Velkov Date: Fri, 16 Jul 2021 16:21:08 +0300 Subject: [PATCH 7/7] fix: method start/end are listed as `8468.7min` This does not happen while debugging with Chrome, which is what I used for the most of the time and never noticed the issue Since the update for Reanimated 2 (TurboModules/JSI) It's no longer possible to use the old (Chrome) debugging flow I've discovered the timing information was not at all relative to app launch, the duration between start/end is correct but the start/end values are otherwise useless if they display like 8468.7min To be useful they need to be relative to app launch time Since timing otherwise works correct, we can capture an offset - APP_LAUNCH_TIME and subtract this value from the timings we make to capture a correct start/end time relative to APP_LAUNCH_TIME --- lib/decorateWithMetrics.js | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/lib/decorateWithMetrics.js b/lib/decorateWithMetrics.js index b83c0a7c..a439d0ef 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] = [];