[No QA] Performance tracking with flipper-plugin-performance

babel.config.js

@@ -34,6 +34,26 @@ const metro = {
     ],
 };
 
+const {CAPTURE_METRICS} = require('dotenv').config().parsed;
+
+/* When the CAPTURE_METRICS env var is set we add these aliases to also capture
+ * React.Profiler metrics for release builds */
+if (CAPTURE_METRICS) {
+    const path = require('path');
+    const profilingRenderer = path.resolve(
+        __dirname,
+        './node_modules/react-native/Libraries/Renderer/implementations/ReactNativeRenderer-profiling',
+    );
+
+    metro.plugins.push(['module-resolver', {
+        root: ['./'],
+        alias: {
+            'ReactNativeRenderer-prod': profilingRenderer,
+            'scheduler/tracing': 'scheduler/tracing-profiling',
+        },
+    }]);
+}
+
 module.exports = ({caller}) => {
     // For `react-native` (iOS/Android) caller will be "metro"
     // For `webpack` (Web) caller will be "@babel-loader"

package.json

@@ -84,7 +84,7 @@
     "react-native-image-picker": "^4.0.3",
     "react-native-keyboard-spacer": "^0.4.1",
     "react-native-modal": "^11.10.0",
-    "react-native-onyx": "git+https://github.com/Expensify/react-native-onyx.git#f3b24dd2c947bb4b9b60dc3718dc170f93f751f0",
+    "react-native-onyx": "git+https://github.com/kidroca/react-native-onyx.git#4c17f3d305b26792a252b14b959d112b8d524081",
     "react-native-pdf": "^6.2.2",
     "react-native-performance": "^2.0.0",
     "react-native-permissions": "^3.0.1",
@@ -150,6 +150,7 @@
     "eslint-plugin-detox": "^1.0.0",
     "eslint-plugin-jest": "^24.1.0",
     "flipper-plugin-bridgespy-client": "^0.1.9",
+    "flipper-plugin-react-native-performance": "^0.6.0",
     "html-webpack-plugin": "^4.3.0",
     "jest": "^26.5.2",
     "jest-circus": "^26.5.2",
@@ -159,7 +160,8 @@
     "portfinder": "^1.0.28",
     "pusher-js-mock": "^0.3.3",
     "react-hot-loader": "^4.12.21",
-    "react-native-flipper": "^0.100.0",
+    "react-native-flipper": "^0.103.0",
+    "react-native-performance-flipper-reporter": "^2.0.0",
     "react-native-svg-transformer": "^0.14.3",
     "react-test-renderer": "16.13.1",
     "rn-async-storage-flipper": "0.0.10",

src/components/OnyxProvider.js

@@ -7,11 +7,13 @@ import ComposeProviders from './ComposeProviders';
 import CONST from '../CONST';
 import Log from '../libs/Log';
 import listenToStorageEvents from '../libs/listenToStorageEvents';
+import canCapturePerformanceMetrics from '../libs/canCapturePerformanceMetrics';
 
 // Initialize the store when the app loads for the first time
 Onyx.init({
     keys: ONYXKEYS,
     safeEvictionKeys: [ONYXKEYS.COLLECTION.REPORT_ACTIONS],
+    captureMetrics: canCapturePerformanceMetrics(),
     initialKeyStates: {
 
         // Clear any loading and error messages so they do not appear on app startup

src/libs/Performance.js

@@ -1,6 +1,14 @@
 import _ from 'underscore';
 import lodashTransform from 'lodash/transform';
+import React, {Profiler, forwardRef} from 'react';
+import {Alert} from 'react-native';
+
 import canCapturePerformanceMetrics from './canCapturePerformanceMetrics';
+import getComponentDisplayName from './getComponentDisplayName';
+import CONST from '../CONST';
+
+/** @type {import('react-native-performance').Performance} */
+let performance;
 
 /**
  * Deep diff between two objects. Useful for figuring out what changed about an object from one render to the next so
@@ -25,43 +33,155 @@ function diffObject(object, base) {
     return changes(object, base);
 }
 
-/**
- * Sets up an observer to capture events recorded in the native layer before the app fully initializes.
- */
-function setupPerformanceObserver() {
-    if (!canCapturePerformanceMetrics()) {
-        return;
-    }
+// When performance monitoring is disabled the implementations are blank
+/* eslint-disable import/no-mutable-exports */
+let setupPerformanceObserver = () => {};
+let printPerformanceMetrics = () => {};
+let markStart = () => {};
+let markEnd = () => {};
+let traceRender = () => {};
+let withRenderTrace = () => Component => Component;
+/* eslint-enable import/no-mutable-exports */
 
-    const performance = require('react-native-performance').default;
-    const PerformanceObserver = require('react-native-performance').PerformanceObserver;
-    new PerformanceObserver((list) => {
-        if (list.getEntries().find(entry => entry.name === 'nativeLaunchEnd')) {
-            performance.measure('nativeLaunch', 'nativeLaunchStart', 'nativeLaunchEnd');
-
-            // eslint-disable-next-line no-undef
-            if (__DEV__) {
-                performance.measure('jsBundleDownload', 'downloadStart', 'downloadEnd');
-            } else {
-                performance.measure('runJsBundle', 'runJsBundleStart', 'runJsBundleEnd');
-            }
-        }
-    }).observe({type: 'react-native-mark', buffered: true});
-}
+if (canCapturePerformanceMetrics()) {
+    /**
+     * Sets up an observer to capture events recorded in the native layer before the app fully initializes.
+     */
+    setupPerformanceObserver = () => {
+        const performanceReported = require('react-native-performance-flipper-reporter');
+        performanceReported.setupDefaultFlipperReporter();
 
-/**
- * Outputs performance stats. We alert these so that they are easy to access in release builds.
- */
-function printPerformanceMetrics() {
-    const performance = require('react-native-performance').default;
-    const entries = _.map(performance.getEntriesByType('measure'), entry => ({
-        name: entry.name, duration: Math.floor(entry.duration),
-    }));
-    alert(JSON.stringify(entries, null, 4));
+        const perfModule = require('react-native-performance');
+        perfModule.setResourceLoggingEnabled(true);
+        performance = perfModule.default;
+
+        // Monitor some native marks that we want to put on the timeline
+        new perfModule.PerformanceObserver((list, observer) => {
+            list.getEntries()
+                .forEach((entry) => {
+                    if (entry.name === 'nativeLaunchEnd') {
+                        performance.measure('nativeLaunch', 'nativeLaunchStart', 'nativeLaunchEnd');
+                    }
+                    if (entry.name === 'downloadEnd') {
+                        performance.measure('jsBundleDownload', 'downloadStart', 'downloadEnd');
+                    }
+                    if (entry.name === 'runJsBundleEnd') {
+                        performance.measure('runJsBundle', 'runJsBundleStart', 'runJsBundleEnd');
+                    }
+
+                    // We don't need to keep the observer past this point
+                    if (entry.name === 'runJsBundleEnd' || entry.name === 'downloadEnd') {
+                        observer.disconnect();
+                    }
+                });
+        }).observe({type: 'react-native-mark', buffered: true});
+
+        new perfModule.PerformanceObserver((list) => {
+            list.getEntriesByType('mark')
+                .forEach((mark) => {
+                    if (mark.name.endsWith('_end')) {
+                        const end = mark.name;
+                        const name = end.replace(/_end$/, '');
+                        const start = `${name}_start`;
+                        performance.measure(name, start, end);
+                    }
+
+                    if (mark.name === `${CONST.TIMING.SIDEBAR_LOADED}_end`) {
+                        performance.measure('TTI', 'nativeLaunchStart', mark.name);
+                        printPerformanceMetrics();
+                    }
+                });
+        }).observe({type: 'mark', buffered: true});
+    };
+
+    /**
+     * Outputs performance stats. We alert these so that they are easy to access in release builds.
+     */
+    printPerformanceMetrics = () => {
+        const stats = [
+            ...performance.getEntriesByName('nativeLaunch'),
+            ...performance.getEntriesByName('runJsBundle'),
+            ...performance.getEntriesByName('jsBundleDownload'),
+            ...performance.getEntriesByName('TTI'),
+        ]
+            .filter(entry => entry.duration > 0)
+            .map(entry => `\u2022 ${entry.name}: ${entry.duration.toFixed(1)}ms`);
+
+        Alert.alert('Performance', stats.join('\n'));
+    };
+
+    /**
+     * Adds a start mark to the performance entries
+     * @param {string} name
+     * @param {Object} [detail]
+     * @returns {PerformanceMark}
+     */
+    markStart = (name, detail) => performance.mark(`${name}_start`, {detail});
+
+    /**
+     * Adds an end mark to the performance entries
+     * This would also automatically create a measure between start and end
+     * @param {string} name
+     * @param {Object} [detail]
+     * @returns {PerformanceMark}
+     */
+    markEnd = (name, detail) => performance.mark(`${name}_end`, {detail});
+
+    /**
+     * Put data emitted by Profiler components on the timeline
+     * @param {string} id the "id" prop of the Profiler tree that has just committed
+     * @param {'mount'|'update'} phase either "mount" (if the tree just mounted) or "update" (if it re-rendered)
+     * @param {number} actualDuration time spent rendering the committed update
+     * @param {number} baseDuration estimated time to render the entire subtree without memoization
+     * @param {number} startTime when React began rendering this update
+     * @param {number} commitTime when React committed this update
+     * @param {Set} interactions the Set of interactions belonging to this update
+     * @returns {PerformanceMeasure}
+     */
+    traceRender = (
+        id,
+        phase,
+        actualDuration,
+        baseDuration,
+        startTime,
+        commitTime,
+        interactions,
+    ) => performance.measure(id, {
+        start: startTime,
+        duration: actualDuration,
+        detail: {
+            phase,
+            baseDuration,
+            commitTime,
+            interactions,
+        },
+    });
+
+    /**
+     * A HOC that captures render timings of the Wrapped component
+     * @param {object} config
+     * @param {string} config.id
+     * @returns {function(React.Component): React.FunctionComponent}
+     */
+    withRenderTrace = ({id}) => (WrappedComponent) => {
+        const WithRenderTrace = forwardRef((props, ref) => (
+            <Profiler id={id} onRender={traceRender}>
+                {/* eslint-disable-next-line react/jsx-props-no-spreading */}
+                <WrappedComponent {...props} ref={ref} />
+            </Profiler>
+        ));
+
+        WithRenderTrace.displayName = `withRenderTrace(${getComponentDisplayName(WrappedComponent)})`;
+        return WithRenderTrace;
+    };
 }
 
 export {
     diffObject,
     printPerformanceMetrics,
     setupPerformanceObserver,
+    markStart,
+    markEnd,
+    traceRender,
+    withRenderTrace,
 };

src/libs/actions/App.js

@@ -7,8 +7,7 @@ import CONST from '../../CONST';
 import Log from '../Log';
 import CONFIG from '../../CONFIG';
 import ROUTES from '../../ROUTES';
-import {printPerformanceMetrics} from '../Performance';
-import canCapturePerformanceMetrics from '../canCapturePerformanceMetrics';
+import {markEnd, markStart} from '../Performance';
 import Timing from './Timing';
 
 let currentUserAccountID;
@@ -61,15 +60,8 @@ function setSidebarLoaded() {
 
     Onyx.set(ONYXKEYS.IS_SIDEBAR_LOADED, true);
     Timing.end(CONST.TIMING.SIDEBAR_LOADED);
-
-    if (!canCapturePerformanceMetrics()) {
-        return;
-    }
-
-    const performance = require('react-native-performance').default;
-    performance.mark('sidebarLoadEnd');
-    performance.measure('timeToInteractive', 'nativeLaunchStart', 'sidebarLoadEnd');
-    printPerformanceMetrics();
+    markEnd(CONST.TIMING.SIDEBAR_LOADED);
+    markStart(CONST.TIMING.SWITCH_REPORT);
 }
 
 let appState;

src/pages/home/report/ReportActionsView.js

@@ -36,6 +36,7 @@ import {contextMenuRef} from './ContextMenu/ReportActionContextMenu';
 import PopoverReportActionContextMenu from './ContextMenu/PopoverReportActionContextMenu';
 import variables from '../../../styles/variables';
 import MarkerBadge from './MarkerBadge';
+import {markEnd, markStart, withRenderTrace} from '../../../libs/Performance';
 
 const propTypes = {
     /** The ID of the report actions will be created for */
@@ -86,6 +87,7 @@ class ReportActionsView extends React.Component {
     constructor(props) {
         super(props);
 
+        markStart('ReportActionsView Mounting');
         this.renderItem = this.renderItem.bind(this);
         this.renderCell = this.renderCell.bind(this);
         this.scrollToListBottom = this.scrollToListBottom.bind(this);
@@ -137,6 +139,8 @@ class ReportActionsView extends React.Component {
         setNewMarkerPosition(this.props.reportID, oldestUnreadSequenceNumber);
 
         fetchActions(this.props.reportID);
+
+        markEnd('ReportActionsView Mounting');
     }
 
     shouldComponentUpdate(nextProps, nextState) {
@@ -405,6 +409,7 @@ class ReportActionsView extends React.Component {
 
         this.didLayout = true;
         Timing.end(CONST.TIMING.SWITCH_REPORT, CONST.TIMING.COLD);
+        markEnd(CONST.TIMING.SWITCH_REPORT);
     }
 
     /**
@@ -510,6 +515,7 @@ ReportActionsView.propTypes = propTypes;
 ReportActionsView.defaultProps = defaultProps;
 
 export default compose(
+    withRenderTrace({id: '<ReportActionsView> rendering'}),
     withWindowDimensions,
     withDrawerState,
     withLocalize,