React Native Android - Systrace from ReactMarkers

perf.js

import React from "react";

const performanceNow = require("fbjs/lib/performanceNow");

// Construct a simple trace record
const traceRecord = ({
    name,
    time: ts,
    tag = null,
    instanceKey = 0,
    tid = 0,
    pid = 0
}) => ({
    cat: "react-native",
    ph: "I",
    name,
    ts,
    pid,
    tid,
    args: {
        instanceKey,
        tag
    }
});

// Gets the logs that Java sends from ReactMarker and converts them into the format that
// chrome://tracing can understand.
// Note that we should not really do this on the device, but send the data to the server
// and the server to change the format
const logsToTrace = (logs, epochStart) => {
    const findClosingEventTime = (
        { name, args: { tag, instanceKey } },
        index,
        records
    ) => {
        if (
            name === "CREATE_MODULE_START" ||
            name === "CONVERT_CONSTANTS_START" ||
            name === "GET_CONSTANTS_START"
        ) {
            // Some events like the above do not have all the information to be associated with the
            // end event. In that case, we look for the first matching end event with the same name
            // and assume that it would be the end event.
            // This will be fixed in React Native soon
            for (let i = index; i < records.length; i++) {
                if (records[i].name === name.replace(/_START$/, "_END")) {
                    return records[i].time;
                }
            }
        } else {
            // For most events, we just look for the name, tag and instance to match, to
            // find the closing event
            const endEvents = records.filter(
                e =>
                    e.name.endsWith("_END") &&
                    e.name.replace(/_END$/, "_START") === name &&
                    // Either the tag, or the instance, or both will match for the end tag
                    (e.tag ? e.tag === tag : e.instanceKey === instanceKey)
            );
            if (endEvents.length === 1) {
                return endEvents[0].time;
            }
        }
        if (__DEV__) {
            console.log(
                "Could not find the ending event for ",
                name,
                tag,
                instanceKey
            );
        }
    };

    const traceEvents = [];
    // Iterate over each element find its closing event, and add that to the list of traceEvents
    logs.forEach((record, index) => {
        //console.log(JSON.stringify(record));
        let event = traceRecord({ ...record, time: record.time - epochStart });
        if (record.name.endsWith("_START")) {
            const endTime = findClosingEventTime(event, index, logs);
            if (typeof endTime !== "undefined") {
                event.ph = "X";
                event.dur = endTime - record.time;
            }
            event.name = record.name.replace(/_START$/, "");
            traceEvents.push(event);
        } else if (event.name.endsWith("_END")) {
            // Nothing to do for end event, we have already processed it
        } else {
            // This is an instant event - an event without a close. We just log this
            traceEvents.push(event);
        }
    });
    return traceEvents;
};

let jsStartTime = performanceNow();
// Function to convert raw logs to a format that chrome://tracing can consume.
// Ideally this should be done at the server, not on the device
const getTrace = () => {
    const trace = { traceEvents: [] };
    // Iterate over logs from Java and convert them
    if (typeof global.AXE_PERFLOGGER !== "undefined") {
        // TODO (me) We currently react logs from ReactMarker that Java sends using a global
        // variable. This should ideally be a native module
        if (typeof global.AXE_PERFLOGGER.startTime !== "undefined") {
            jsStartTime = global.AXE_PERFLOGGER.startTime;
        }
        if (typeof global.AXE_PERFLOGGER.data !== "undefined") {
            trace.traceEvents = logsToTrace(
                global.AXE_PERFLOGGER.data,
                jsStartTime
            );
        }
    }

    // Iterate over the JS components logs, and convert them.
    for (var name in jsTimeSpans) {
        let { start, end } = jsTimeSpans[name];
        const event = traceRecord({
            name,
            time: start - jsStartTime,
            tag: "JS_EVENT"
        });
        event.ph = "X";
        event.dur = end - start;
        trace.traceEvents.push(event);
    }
    return trace;
};

// A helper to record timespans that JS components send us
const jsTimeSpans = {};
const TimeSpan = {
    start(name) {
        jsTimeSpans[name] = { start: performanceNow() };
    },
    stop(name) {
        const timespan = jsTimeSpans[name];
        if (typeof timespan !== "undefined") {
            jsTimeSpans[name] = { ...timespan, end: performanceNow() };
        }
    }
};

// A simple component to record the time taken to construct and mount JS components
class ComponentLogger extends React.Component {
    _hasLoggedUpdate = false;
    constructor(props) {
        super(props);
        const { name, type } = this.props;
        TimeSpan[type](name + "_mount");
    }

    shouldComponentUpdate() {
        if (!this._hasLoggedUpdate) {
            const { name, type } = this.props;
            this._hasLoggedUpdate = true;
            TimeSpan[type](name + "_update");
        }
        return false;
    }

    render() {
        return null;
    }
}

module.exports = {
    // Use this function in your JS code to instrument load time. Usage is
    // render() { logComponentPerf('Component_NAME', <Component ...props />); }
    logComponentPerf(name, component) {
        return (
            <>
                <ComponentLogger type="start" name={name} />
                {component}
                <ComponentLogger type="stop" name={name} />
            </>
        );
    },
    getTrace
};

// TODO (me) This should not happen on a timeout, but when TTI or loading completes.
// We could do that by adding a callback on the component that marks the end
// of loading.
global.setTimeout(() => {
    // TODO (app) Change this to your app's server, that can recieve trace.json
    fetch("http://localhost:3000", {
        method: "POST",
        body: JSON.stringify(getTrace())
    });
    console.log("---- Uploaded Performance Metrics ----");
}, 10000);

PerfLogger.java

package com.nparashuram;

import android.os.Process;
import android.text.TextUtils;
import android.util.Log;
import android.view.View;
import android.view.ViewTreeObserver;
import com.facebook.react.ReactInstanceManager;
import com.facebook.react.ReactNativeHost;
import com.facebook.react.bridge.ReactContext;
import com.facebook.react.bridge.ReactMarker;
import com.facebook.react.bridge.ReactMarkerConstants;
import com.facebook.react.uimanager.util.ReactFindViewUtil;
import org.json.JSONArray;
import org.json.JSONException;
import org.json.JSONObject;

import javax.annotation.Nullable;
import java.util.ArrayList;
import java.util.List;

/**
 * A class to record the Perf metrics that are emitted by {@link ReactMarker.MarkerListener} It
 * records the metrics and sends them over to the server
 */
public class PerfLogger {
  // TODO (axe) This also used as a global JS variable. Need a better way to expose this
  private static final String TAG = "AXE_PERFLOGGER";
  private final long mStartTime;
  private final ReactNativeHost mReactNativeHost;

  /** Class holds the individual records from the performance metrics */
  private class PerfLoggerRecord {
    private final long mTime;
    private final String mName;
    private final String mTag;
    private final int mInstanceKey;
    private final int mTid;
    private final int mPid;

    PerfLoggerRecord(String name, String tag, int instanceKey) {
      mTime = System.currentTimeMillis();
      mName = name;
      mTag = tag;
      mInstanceKey = instanceKey;
      mPid = Process.myPid();
      mTid = Process.myTid();
    }

    public JSONObject toJSON() {
      JSONObject result = new JSONObject();
      try {
        result.put("time", mTime);
        result.put("name", mName);
        result.put("tag", mTag);
        result.put("instanceKey", mInstanceKey);
        result.put("pid", mPid);
        result.put("tid", mTid);
        return result;
      } catch (JSONException e) {
        return new JSONObject();
      }
    }

    public String toString() {
      return TextUtils.join(
          ",",
          new String[] {
            Long.toString(mTime),
            mName,
            mTag,
            Integer.toString(mInstanceKey),
            Integer.toString(mTid),
            Integer.toString(mPid)
          });
    }
  }

  @Nullable private List<PerfLoggerRecord> mPerfLoggerRecords;

  public PerfLogger(ReactNativeHost reactNativeHost) {
    mStartTime = System.currentTimeMillis();
    mPerfLoggerRecords = new ArrayList<>();
    mReactNativeHost = reactNativeHost;
  }

  public void initialize() {
    addReactMarkerListener();
    addTTIEndListener();
    setVariableForJS(null);
  }

  /**
   * Currently, we set a global JS variable to send the data from {@link ReactMarker.MarkerListener}
   * to JS This should ideally be a native module. The global variable is {@link PerfLogger#TAG}
   *
   * <p>Currently, we call it on start and when the initial loading is complete, but it can
   * technically be called at the end of any scenario that needs to be profiled
   *
   * @param records
   */
  private void setVariableForJS(List<PerfLoggerRecord> records) {
    final ReactInstanceManager reactInstanceManager = mReactNativeHost.getReactInstanceManager();
    ReactContext context = reactInstanceManager.getCurrentReactContext();
    if (context != null) {
      // Called when React Native is ready. In this file, its when TTI is complete
      context.getCatalystInstance().setGlobalVariable(TAG, getPerfRecordsJSON(mStartTime, records));
    } else {
      // Called when React Native is not readt, in this file during {@link PerfLogger#initialize}
      // In this case, we wait for React Native, and then set the global JS
      reactInstanceManager.addReactInstanceEventListener(
          new ReactInstanceManager.ReactInstanceEventListener() {
            @Override
            public void onReactContextInitialized(ReactContext context) {
              reactInstanceManager.removeReactInstanceEventListener(this);
              context
                  .getCatalystInstance()
                  // TODO (axe) Use a native module instead of setting a global JS
                  .setGlobalVariable(TAG, getPerfRecordsJSON(mStartTime, null));
            }
          });
    }
  }

  private static String getPerfRecordsJSON(
      long startTime, @Nullable List<PerfLoggerRecord> records) {
    JSONObject result = new JSONObject();
    try {
      result.put("startTime", startTime);
      if (records != null) {
        JSONArray jsonRecords = new JSONArray();
        for (PerfLoggerRecord record : records) {
          // Log.d(TAG, record.toString());
          jsonRecords.put(record.toJSON());
        }
        result.put("data", jsonRecords);
      }
      return result.toString();
    } catch (JSONException e) {
      Log.w(TAG, "Could not convert perf records to JSON", e);
      return "{}";
    }
  }

  /**
   * This is the main functionality of this file. It basically listens to all the events and stores
   * them
   */
  private void addReactMarkerListener() {
    ReactMarker.addListener(
        new ReactMarker.MarkerListener() {
          @Override
          public void logMarker(ReactMarkerConstants name, @Nullable String tag, int instanceKey) {
            mPerfLoggerRecords.add(new PerfLoggerRecord(name.toString(), tag, instanceKey));
          }
        });
  }

  /**
   * Waits for Loading to complete, also called a Time-To-Interaction (TTI) event. To indicate TTI
   * completion, add a prop nativeID="tti_complete" to the component whose appearance indicates that
   * the initial TTI or loading is complete
   */
  private void addTTIEndListener() {
    ReactFindViewUtil.addViewListener(
        new ReactFindViewUtil.OnViewFoundListener() {
          @Override
          public String getNativeId() {
            // This is the value of the nativeID property
            return "tti_complete";
          }

          @Override
          public void onViewFound(final View view) {
            // Once we find the view, we also need to wait for it to be drawn
            view.getViewTreeObserver()
                // TODO (axe) Should be OnDrawListener instead of this
                .addOnPreDrawListener(
                    new ViewTreeObserver.OnPreDrawListener() {
                      @Override
                      public boolean onPreDraw() {
                        view.getViewTreeObserver().removeOnPreDrawListener(this);
                        mPerfLoggerRecords.add(new PerfLoggerRecord("TTI_COMPLETE", null, 0));
                        setVariableForJS(mPerfLoggerRecords);
                        return true;
                      }
                    });
          }
        });
  }
}

Any chance of making this a module? I tried copy-pasting this but for some reason the traces are coming out as []. Not sure if something changed since the time of writing this gist.

I don't have the bandwidth to make this a module, but if you would like to, I can help