Allow to create local performance loggers

Reviewed By: bestander

Differential Revision: D14159631

fbshipit-source-id: 62830f67060e575841cbc864dde30c7bee7e7c4c

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.

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'),

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');

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');
 

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;

Libraries/Utilities/PerformanceLogger.js

@@ -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<string>) {
-    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<number>, labels: Array<string>) {
-    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;

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;

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 = '<timespan_1>';
+const TIMESPAN_2 = '<timespan_2>';
+const TIMESPAN_2_DURATION = 123;
+const EXTRA_KEY = '<extra_key>';
+const EXTRA_VALUE = '<extra_value>';
+const EXTRA_VALUE_2 = '<extra_value_2>';
+const POINT = '<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);
+  });
+});

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<string>): void,
+  currentTimestamp(): number,
+  getTimespans(): {[key: string]: Timespan},
+  hasTimespan(string): boolean,
+  logTimespans(): void,
+  addTimespans(Array<number>, Array<string>): 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<string>) {
+      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<number>, labels: Array<string>) {
+      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;