From 1aabbf5dce29cc29eb133c21bc07c72cda690633 Mon Sep 17 00:00:00 2001 From: Alexey Lang Date: Thu, 28 Feb 2019 03:35:59 -0800 Subject: [PATCH] Allow to create local performance loggers Reviewed By: bestander Differential Revision: D14159631 fbshipit-source-id: 62830f67060e575841cbc864dde30c7bee7e7c4c --- Libraries/Core/InitializeCore.js | 2 +- Libraries/Core/setUpBatchedBridge.js | 2 +- Libraries/Inspector/PerformanceOverlay.js | 2 +- Libraries/ReactNative/renderApplication.js | 2 +- .../Utilities/GlobalPerformanceLogger.js | 15 ++ Libraries/Utilities/PerformanceLogger.js | 220 ---------------- .../__mocks__/GlobalPerformanceLogger.js | 16 ++ .../__tests__/PerformanceLogger-test.js | 142 ++++++++++ .../Utilities/createPerformanceLogger.js | 249 ++++++++++++++++++ 9 files changed, 426 insertions(+), 224 deletions(-) create mode 100644 Libraries/Utilities/GlobalPerformanceLogger.js delete mode 100644 Libraries/Utilities/PerformanceLogger.js create mode 100644 Libraries/Utilities/__mocks__/GlobalPerformanceLogger.js create mode 100644 Libraries/Utilities/__tests__/PerformanceLogger-test.js create mode 100644 Libraries/Utilities/createPerformanceLogger.js diff --git a/Libraries/Core/InitializeCore.js b/Libraries/Core/InitializeCore.js index 2a2ca6479..69fa9c870 100644 --- a/Libraries/Core/InitializeCore.js +++ b/Libraries/Core/InitializeCore.js @@ -44,7 +44,7 @@ if (__DEV__) { require('setUpDeveloperTools'); } -const PerformanceLogger = require('PerformanceLogger'); +const PerformanceLogger = require('GlobalPerformanceLogger'); // We could just call PerformanceLogger.markPoint at the top of the file, // but then we'd be excluding the time it took to require PerformanceLogger. // Instead, we just use Date.now and backdate the timestamp. diff --git a/Libraries/Core/setUpBatchedBridge.js b/Libraries/Core/setUpBatchedBridge.js index fd936bf50..be0335629 100644 --- a/Libraries/Core/setUpBatchedBridge.js +++ b/Libraries/Core/setUpBatchedBridge.js @@ -31,7 +31,7 @@ BatchedBridge.registerLazyCallableModule('RCTNativeAppEventEmitter', () => require('RCTNativeAppEventEmitter'), ); BatchedBridge.registerLazyCallableModule('PerformanceLogger', () => - require('PerformanceLogger'), + require('GlobalPerformanceLogger'), ); BatchedBridge.registerLazyCallableModule('JSDevSupportModule', () => require('JSDevSupportModule'), diff --git a/Libraries/Inspector/PerformanceOverlay.js b/Libraries/Inspector/PerformanceOverlay.js index 2384769bc..c87b46820 100644 --- a/Libraries/Inspector/PerformanceOverlay.js +++ b/Libraries/Inspector/PerformanceOverlay.js @@ -10,7 +10,7 @@ 'use strict'; -const PerformanceLogger = require('PerformanceLogger'); +const PerformanceLogger = require('GlobalPerformanceLogger'); const React = require('React'); const StyleSheet = require('StyleSheet'); const Text = require('Text'); diff --git a/Libraries/ReactNative/renderApplication.js b/Libraries/ReactNative/renderApplication.js index 694567726..ad3ec9944 100644 --- a/Libraries/ReactNative/renderApplication.js +++ b/Libraries/ReactNative/renderApplication.js @@ -11,7 +11,7 @@ 'use strict'; const AppContainer = require('AppContainer'); -import PerformanceLogger from 'PerformanceLogger'; +import PerformanceLogger from 'GlobalPerformanceLogger'; const React = require('React'); const ReactFabricIndicator = require('ReactFabricIndicator'); diff --git a/Libraries/Utilities/GlobalPerformanceLogger.js b/Libraries/Utilities/GlobalPerformanceLogger.js new file mode 100644 index 000000000..abbd9e434 --- /dev/null +++ b/Libraries/Utilities/GlobalPerformanceLogger.js @@ -0,0 +1,15 @@ +/** + * Copyright (c) Facebook, Inc. and its affiliates. + * + * This source code is licensed under the MIT license found in the + * LICENSE file in the root directory of this source tree. + * + * @flow + * @format + */ +'use strict'; + +const createPerformanceLogger = require('createPerformanceLogger'); + +const GlobalPerformanceLogger = createPerformanceLogger(); +module.exports = GlobalPerformanceLogger; diff --git a/Libraries/Utilities/PerformanceLogger.js b/Libraries/Utilities/PerformanceLogger.js deleted file mode 100644 index 0054b2464..000000000 --- a/Libraries/Utilities/PerformanceLogger.js +++ /dev/null @@ -1,220 +0,0 @@ -/** - * Copyright (c) Facebook, Inc. and its affiliates. - * - * This source code is licensed under the MIT license found in the - * LICENSE file in the root directory of this source tree. - * - * @flow - * @format - */ -'use strict'; - -const Systrace = require('Systrace'); - -const infoLog = require('infoLog'); -const performanceNow = - global.nativeQPLTimestamp || - global.nativePerformanceNow || - require('fbjs/lib/performanceNow'); - -type Timespan = { - description?: string, - totalTime?: number, - startTime?: number, - endTime?: number, -}; - -let timespans: {[key: string]: Timespan} = {}; -let extras: {[key: string]: any} = {}; -let points: {[key: string]: number} = {}; -const cookies: {[key: string]: number} = {}; - -const PRINT_TO_CONSOLE: false = false; // Type as false to prevent accidentally committing `true`; - -/** - * This is meant to collect and log performance data in production, which means - * it needs to have minimal overhead. - */ -const PerformanceLogger = { - addTimespan(key: string, lengthInMs: number, description?: string) { - if (timespans[key]) { - if (__DEV__) { - infoLog( - 'PerformanceLogger: Attempting to add a timespan that already exists ', - key, - ); - } - return; - } - - timespans[key] = { - description: description, - totalTime: lengthInMs, - }; - }, - - startTimespan(key: string, description?: string) { - if (timespans[key]) { - if (__DEV__) { - infoLog( - 'PerformanceLogger: Attempting to start a timespan that already exists ', - key, - ); - } - return; - } - - timespans[key] = { - description: description, - startTime: performanceNow(), - }; - cookies[key] = Systrace.beginAsyncEvent(key); - if (PRINT_TO_CONSOLE) { - infoLog('PerformanceLogger.js', 'start: ' + key); - } - }, - - stopTimespan(key: string) { - const timespan = timespans[key]; - if (!timespan || !timespan.startTime) { - if (__DEV__) { - infoLog( - 'PerformanceLogger: Attempting to end a timespan that has not started ', - key, - ); - } - return; - } - if (timespan.endTime) { - if (__DEV__) { - infoLog( - 'PerformanceLogger: Attempting to end a timespan that has already ended ', - key, - ); - } - return; - } - - timespan.endTime = performanceNow(); - timespan.totalTime = timespan.endTime - (timespan.startTime || 0); - if (PRINT_TO_CONSOLE) { - infoLog('PerformanceLogger.js', 'end: ' + key); - } - - Systrace.endAsyncEvent(key, cookies[key]); - delete cookies[key]; - }, - - clear() { - timespans = {}; - extras = {}; - points = {}; - if (PRINT_TO_CONSOLE) { - infoLog('PerformanceLogger.js', 'clear'); - } - }, - - clearCompleted() { - for (const key in timespans) { - if (timespans[key].totalTime) { - delete timespans[key]; - } - } - extras = {}; - points = {}; - if (PRINT_TO_CONSOLE) { - infoLog('PerformanceLogger.js', 'clearCompleted'); - } - }, - - clearExceptTimespans(keys: Array) { - timespans = Object.keys(timespans).reduce(function(previous, key) { - if (keys.indexOf(key) !== -1) { - previous[key] = timespans[key]; - } - return previous; - }, {}); - extras = {}; - points = {}; - if (PRINT_TO_CONSOLE) { - infoLog('PerformanceLogger.js', 'clearExceptTimespans', keys); - } - }, - - currentTimestamp() { - return performanceNow(); - }, - - getTimespans() { - return timespans; - }, - - hasTimespan(key: string) { - return !!timespans[key]; - }, - - logTimespans() { - for (const key in timespans) { - if (timespans[key].totalTime) { - infoLog(key + ': ' + timespans[key].totalTime + 'ms'); - } - } - }, - - addTimespans(newTimespans: Array, labels: Array) { - for (let ii = 0, l = newTimespans.length; ii < l; ii += 2) { - const label = labels[ii / 2]; - PerformanceLogger.addTimespan( - label, - newTimespans[ii + 1] - newTimespans[ii], - label, - ); - } - }, - - setExtra(key: string, value: any) { - if (extras[key]) { - if (__DEV__) { - infoLog( - 'PerformanceLogger: Attempting to set an extra that already exists ', - {key, currentValue: extras[key], attemptedValue: value}, - ); - } - return; - } - extras[key] = value; - }, - - getExtras() { - return extras; - }, - - logExtras() { - infoLog(extras); - }, - - markPoint(key: string, timestamp?: number) { - if (points[key]) { - if (__DEV__) { - infoLog( - 'PerformanceLogger: Attempting to mark a point that has been already logged ', - key, - ); - } - return; - } - points[key] = timestamp ?? performanceNow(); - }, - - getPoints() { - return points; - }, - - logPoints() { - for (const key in points) { - infoLog(key + ': ' + points[key] + 'ms'); - } - }, -}; - -module.exports = PerformanceLogger; diff --git a/Libraries/Utilities/__mocks__/GlobalPerformanceLogger.js b/Libraries/Utilities/__mocks__/GlobalPerformanceLogger.js new file mode 100644 index 000000000..b47df421a --- /dev/null +++ b/Libraries/Utilities/__mocks__/GlobalPerformanceLogger.js @@ -0,0 +1,16 @@ +/** + * Copyright (c) Facebook, Inc. and its affiliates. + * + * This source code is licensed under the MIT license found in the + * LICENSE file in the root directory of this source tree. + * + * @format + */ + +'use strict'; + +const GlobalPerformanceLogger = jest + .unmock('createPerformanceLogger') + .genMockFromModule('GlobalPerformanceLogger'); + +module.exports = GlobalPerformanceLogger; diff --git a/Libraries/Utilities/__tests__/PerformanceLogger-test.js b/Libraries/Utilities/__tests__/PerformanceLogger-test.js new file mode 100644 index 000000000..b72fd9ebc --- /dev/null +++ b/Libraries/Utilities/__tests__/PerformanceLogger-test.js @@ -0,0 +1,142 @@ +/** + * Copyright (c) Facebook, Inc. and its affiliates. + * + * This source code is licensed under the MIT license found in the + * LICENSE file in the root directory of this source tree. + * + * @format + */ + +'use strict'; + +import GlobalPerformanceLogger from 'GlobalPerformanceLogger'; +import createPerformanceLogger from 'createPerformanceLogger'; +import type {IPerformanceLogger} from 'createPerformanceLogger'; + +const TIMESPAN_1 = ''; +const TIMESPAN_2 = ''; +const TIMESPAN_2_DURATION = 123; +const EXTRA_KEY = ''; +const EXTRA_VALUE = ''; +const EXTRA_VALUE_2 = ''; +const POINT = ''; +const POINT_TIMESTAMP = 99; +const POINT_TIMESTAMP_2 = 999; + +describe('PerformanceLogger', () => { + beforeEach(() => { + GlobalPerformanceLogger.clear(); + }); + + it('starts & stops and adds a timespan', () => { + let perfLogger = createPerformanceLogger(); + perfLogger.startTimespan(TIMESPAN_1); + perfLogger.stopTimespan(TIMESPAN_1); + perfLogger.addTimespan(TIMESPAN_2, TIMESPAN_2_DURATION); + expect(perfLogger.hasTimespan(TIMESPAN_1)).toBe(true); + expect(perfLogger.hasTimespan(TIMESPAN_2)).toBe(true); + expect(perfLogger.getTimespans()[TIMESPAN_2].totalTime).toBe( + TIMESPAN_2_DURATION, + ); + }); + + it('does not override a timespan', () => { + let perfLogger = createPerformanceLogger(); + perfLogger.startTimespan(TIMESPAN_1); + let old = perfLogger.getTimespans()[TIMESPAN_1]; + perfLogger.startTimespan(TIMESPAN_1); + expect(perfLogger.getTimespans()[TIMESPAN_1]).toBe(old); + perfLogger.addTimespan(TIMESPAN_1, 1); + expect(perfLogger.getTimespans()[TIMESPAN_1]).toBe(old); + }); + + it('logs an extra', () => { + let perfLogger = createPerformanceLogger(); + perfLogger.setExtra(EXTRA_KEY, EXTRA_VALUE); + expect(perfLogger.getExtras()).toEqual({ + [EXTRA_KEY]: EXTRA_VALUE, + }); + }); + + it('does not override a extra', () => { + let perfLogger = createPerformanceLogger(); + perfLogger.setExtra(EXTRA_KEY, EXTRA_VALUE); + expect(perfLogger.getExtras()).toEqual({ + [EXTRA_KEY]: EXTRA_VALUE, + }); + perfLogger.setExtra(EXTRA_KEY, EXTRA_VALUE_2); + expect(perfLogger.getExtras()).toEqual({ + [EXTRA_KEY]: EXTRA_VALUE, + }); + }); + + it('logs a point', () => { + let perfLogger = createPerformanceLogger(); + perfLogger.markPoint(POINT, POINT_TIMESTAMP); + expect(perfLogger.getPoints()).toEqual({ + [POINT]: POINT_TIMESTAMP, + }); + }); + + it('does not override a point', () => { + let perfLogger = createPerformanceLogger(); + perfLogger.markPoint(POINT, POINT_TIMESTAMP); + expect(perfLogger.getPoints()).toEqual({ + [POINT]: POINT_TIMESTAMP, + }); + perfLogger.markPoint(POINT, POINT_TIMESTAMP_2); + expect(perfLogger.getPoints()).toEqual({ + [POINT]: POINT_TIMESTAMP, + }); + }); + + it('global and local loggers do not conflict', () => { + let checkLogger = (logger: IPerformanceLogger, shouldBeEmpty: boolean) => { + expect(Object.keys(logger.getTimespans())).toEqual( + shouldBeEmpty ? [] : [TIMESPAN_1], + ); + expect(logger.getExtras()).toEqual( + shouldBeEmpty + ? {} + : { + [EXTRA_KEY]: EXTRA_VALUE, + }, + ); + expect(Object.keys(logger.getPoints())).toEqual( + shouldBeEmpty ? [] : [POINT], + ); + }; + let localPerformanceLogger1 = createPerformanceLogger(); + let localPerformanceLogger2 = createPerformanceLogger(); + localPerformanceLogger1.startTimespan(TIMESPAN_1); + localPerformanceLogger1.stopTimespan(TIMESPAN_1); + localPerformanceLogger1.setExtra(EXTRA_KEY, EXTRA_VALUE); + localPerformanceLogger1.markPoint(POINT); + checkLogger(localPerformanceLogger1, false); + checkLogger(localPerformanceLogger2, true); + checkLogger(GlobalPerformanceLogger, true); + localPerformanceLogger2.startTimespan(TIMESPAN_1); + localPerformanceLogger2.stopTimespan(TIMESPAN_1); + localPerformanceLogger2.setExtra(EXTRA_KEY, EXTRA_VALUE); + localPerformanceLogger2.markPoint(POINT, undefined); + checkLogger(localPerformanceLogger2, false); + checkLogger(GlobalPerformanceLogger, true); + GlobalPerformanceLogger.startTimespan(TIMESPAN_1); + GlobalPerformanceLogger.stopTimespan(TIMESPAN_1); + GlobalPerformanceLogger.setExtra(EXTRA_KEY, EXTRA_VALUE); + GlobalPerformanceLogger.markPoint(POINT); + checkLogger(GlobalPerformanceLogger, false); + localPerformanceLogger1.clear(); + checkLogger(localPerformanceLogger1, true); + checkLogger(localPerformanceLogger2, false); + checkLogger(GlobalPerformanceLogger, false); + GlobalPerformanceLogger.clear(); + checkLogger(localPerformanceLogger1, true); + checkLogger(localPerformanceLogger2, false); + checkLogger(GlobalPerformanceLogger, true); + localPerformanceLogger2.clear(); + checkLogger(localPerformanceLogger1, true); + checkLogger(localPerformanceLogger2, true); + checkLogger(GlobalPerformanceLogger, true); + }); +}); diff --git a/Libraries/Utilities/createPerformanceLogger.js b/Libraries/Utilities/createPerformanceLogger.js new file mode 100644 index 000000000..b432f19c6 --- /dev/null +++ b/Libraries/Utilities/createPerformanceLogger.js @@ -0,0 +1,249 @@ +/** + * Copyright (c) Facebook, Inc. and its affiliates. + * + * This source code is licensed under the MIT license found in the + * LICENSE file in the root directory of this source tree. + * + * @flow + * @format + */ +'use strict'; + +const Systrace = require('Systrace'); + +const infoLog = require('infoLog'); +const performanceNow = + global.nativeQPLTimestamp || + global.nativePerformanceNow || + require('fbjs/lib/performanceNow'); + +type Timespan = { + description?: string, + totalTime?: number, + startTime?: number, + endTime?: number, +}; + +export type IPerformanceLogger = { + addTimespan(string, number, string | void): void, + startTimespan(string, string | void): void, + stopTimespan(string): void, + clear(): void, + clearCompleted(): void, + clearExceptTimespans(Array): void, + currentTimestamp(): number, + getTimespans(): {[key: string]: Timespan}, + hasTimespan(string): boolean, + logTimespans(): void, + addTimespans(Array, Array): void, + setExtra(string, any): void, + getExtras(): {[key: string]: any}, + logExtras(): void, + markPoint(string, number | void): void, + getPoints(): {[key: string]: number}, + logPoints(): void, +}; + +const _cookies: {[key: string]: number} = {}; + +const PRINT_TO_CONSOLE: false = false; // Type as false to prevent accidentally committing `true`; + +/** + * This function creates peformance loggers that can be used to collect and log + * various performance data such as timespans, points and extras. + * The loggers need to have minimal overhead since they're used in production. + */ +function createPerformanceLogger(): IPerformanceLogger { + const result: IPerformanceLogger & { + _timespans: {[key: string]: Timespan}, + _extras: {[key: string]: any}, + _points: {[key: string]: number}, + } = { + _timespans: {}, + _extras: {}, + _points: {}, + + addTimespan(key: string, lengthInMs: number, description?: string) { + if (this._timespans[key]) { + if (__DEV__) { + infoLog( + 'PerformanceLogger: Attempting to add a timespan that already exists ', + key, + ); + } + return; + } + + this._timespans[key] = { + description: description, + totalTime: lengthInMs, + }; + }, + + startTimespan(key: string, description?: string) { + if (this._timespans[key]) { + if (__DEV__) { + infoLog( + 'PerformanceLogger: Attempting to start a timespan that already exists ', + key, + ); + } + return; + } + + this._timespans[key] = { + description: description, + startTime: performanceNow(), + }; + _cookies[key] = Systrace.beginAsyncEvent(key); + if (PRINT_TO_CONSOLE) { + infoLog('PerformanceLogger.js', 'start: ' + key); + } + }, + + stopTimespan(key: string) { + const timespan = this._timespans[key]; + if (!timespan || !timespan.startTime) { + if (__DEV__) { + infoLog( + 'PerformanceLogger: Attempting to end a timespan that has not started ', + key, + ); + } + return; + } + if (timespan.endTime) { + if (__DEV__) { + infoLog( + 'PerformanceLogger: Attempting to end a timespan that has already ended ', + key, + ); + } + return; + } + + timespan.endTime = performanceNow(); + timespan.totalTime = timespan.endTime - (timespan.startTime || 0); + if (PRINT_TO_CONSOLE) { + infoLog('PerformanceLogger.js', 'end: ' + key); + } + + Systrace.endAsyncEvent(key, _cookies[key]); + delete _cookies[key]; + }, + + clear() { + this._timespans = {}; + this._extras = {}; + this._points = {}; + if (PRINT_TO_CONSOLE) { + infoLog('PerformanceLogger.js', 'clear'); + } + }, + + clearCompleted() { + for (const key in this._timespans) { + if (this._timespans[key].totalTime) { + delete this._timespans[key]; + } + } + this._extras = {}; + this._points = {}; + if (PRINT_TO_CONSOLE) { + infoLog('PerformanceLogger.js', 'clearCompleted'); + } + }, + + clearExceptTimespans(keys: Array) { + this._timespans = Object.keys(this._timespans).reduce(function( + previous, + key, + ) { + if (keys.indexOf(key) !== -1) { + previous[key] = this._timespans[key]; + } + return previous; + }, + {}); + this._extras = {}; + this._points = {}; + if (PRINT_TO_CONSOLE) { + infoLog('PerformanceLogger.js', 'clearExceptTimespans', keys); + } + }, + + currentTimestamp() { + return performanceNow(); + }, + + getTimespans() { + return this._timespans; + }, + + hasTimespan(key: string) { + return !!this._timespans[key]; + }, + + logTimespans() { + for (const key in this._timespans) { + if (this._timespans[key].totalTime) { + infoLog(key + ': ' + this._timespans[key].totalTime + 'ms'); + } + } + }, + + addTimespans(newTimespans: Array, labels: Array) { + for (let ii = 0, l = newTimespans.length; ii < l; ii += 2) { + const label = labels[ii / 2]; + this.addTimespan(label, newTimespans[ii + 1] - newTimespans[ii], label); + } + }, + + setExtra(key: string, value: any) { + if (this._extras[key]) { + if (__DEV__) { + infoLog( + 'PerformanceLogger: Attempting to set an extra that already exists ', + {key, currentValue: this._extras[key], attemptedValue: value}, + ); + } + return; + } + this._extras[key] = value; + }, + + getExtras() { + return this._extras; + }, + + logExtras() { + infoLog(this._extras); + }, + + markPoint(key: string, timestamp?: number) { + if (this._points[key]) { + if (__DEV__) { + infoLog( + 'PerformanceLogger: Attempting to mark a point that has been already logged ', + key, + ); + } + return; + } + this._points[key] = timestamp ?? performanceNow(); + }, + + getPoints() { + return this._points; + }, + + logPoints() { + for (const key in this._points) { + infoLog(key + ': ' + this._points[key] + 'ms'); + } + }, + }; + return result; +} + +module.exports = createPerformanceLogger;