AppDelegate.m

...

- (BOOL)application:(UIApplication *)application didFinishLaunchingWithOptions:(NSDictionary *)launchOptions
{
  int64_t startTime = CACurrentMediaTime() * 1000;
  
  // Create root view code
  ...
  
  [[rootView.bridge moduleForName:@"PerfLogger"] setStartTime:startTime];
  
  ...
 }

PerfLogger.js

// @flow

import * as React from 'react';
import { NativeModules } from 'react-native';
import DeviceInfo from 'react-native-device-info';

import { commitMutation, graphql } from 'tw/relay';

// eslint-disable-next-line import/no-extraneous-dependencies
const performanceNow = require('fbjs/lib/performanceNow');

// Construct a simple trace record
const traceRecord = ({
  name,
  time: ts,
  tag = null,
  instanceKey = 0,
  tid = 0,
  pid = 0,
}: Object): Object => ({
  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 += 1) {
        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,
      );
    }
    return null;
  };

  const traceEvents = [];
  // Iterate over each element find its closing event, and add that to the list of traceEvents
  logs.forEach((record, index) => {
    const event = traceRecord({ ...record, time: record.time - epochStart });
    if (record.name.endsWith('_START')) {
      const endTime = findClosingEventTime(event, index, logs);
      if (endTime != null) {
        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
export const getTrace = async () => {
  // start iOS support
  const trace = { traceEvents: [] };
  let nativeTrace;
  if (NativeModules.PerfLogger != null) {
    nativeTrace = await NativeModules.PerfLogger.getTrace();
  } else {
    // TODO (me) We currently react logs from ReactMarker that Java sends using a global
    // variable. This should ideally be a native module
    nativeTrace = global.AXE_PERFLOGGER;
  }
  // end iOS support

  if (nativeTrace != null) {
    jsStartTime = nativeTrace.startTime;
    if (nativeTrace.data != null) {
      trace.traceEvents = logsToTrace(nativeTrace.data, jsStartTime);
    }
  }

  // Iterate over the JS components logs, and convert them.
  for (const name of Object.keys(jsTimeSpans)) {
    const { 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<{
  type: 'start' | 'stop',
  name: string,
}> {
  _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;
  }
}

export function initialize() {
  // 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.
  setTimeout(async () => {
    const trace = await getTrace();
    const [batteryLevel] = await Promise.all([DeviceInfo.getBatteryLevel()]);
    if (__DEV__) {
      // eslint-disable-next-line no-console
      console.log(JSON.stringify(trace, null, 2));
    } else {
      await commitMutation({
        mutation: graphql`
          mutation PerfLoggerMutation($input: LogPerfTraceInput!) {
            logPerfTrace(input: $input) {
              clientMutationId
            }
          }
        `,
        variables: {
          input: {
            traceJSON: JSON.stringify(trace),
            deviceInfoJSON: JSON.stringify({
              batteryLevel,
              version: DeviceInfo.getVersion(),
              buildNumber: DeviceInfo.getBuildNumber(),
              deviceBrand: DeviceInfo.getBrand(),
              deviceModel: DeviceInfo.getModel(),
              deviceManufacturer: DeviceInfo.getManufacturer(),
              deviceId: DeviceInfo.getDeviceId(),
              systemVersion: DeviceInfo.getSystemVersion(),
              totalMemory: DeviceInfo.getTotalMemory(),
              diskFree: DeviceInfo.getFreeDiskStorage(),
              diskTotal: DeviceInfo.getTotalDiskCapacity(),
            }),
          },
        },
      });
    }
  }, 5000);
}

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

export function start(tag: string): void {
  TimeSpan.start(tag);
}

export function stop(tag: string): void {
  TimeSpan.stop(tag);
}

TWPerfLoggerModule.h

//
//  TWPerfLogger.h
//  th3rdwave
//
//  Created by Janic Duplessis on 2018-11-27.
//  Copyright © 2018 Facebook. All rights reserved.
//

#import <React/RCTBridgeModule.h>

NS_ASSUME_NONNULL_BEGIN

@interface TWPerfLoggerModule : NSObject <RCTBridgeModule>

- (void)setStartTime:(int64_t)time;

@end

NS_ASSUME_NONNULL_END

TWPerfLoggerModule.m

//
//  TWPerfLogger.m
//  th3rdwave
//
//  Created by Janic Duplessis on 2018-11-27.
//  Copyright © 2018 Facebook. All rights reserved.
//

#import "TWPerfLoggerModule.h"

#import <React/RCTUIManager.h>
#import <React/RCTUIManagerObserverCoordinator.h>
#import <React/RCTPerformanceLogger.h>

@interface TWPerfMarker : NSObject

- (instancetype)initWithName:(NSString *)name time:(int64_t)time;

- (id)json;

@end

@implementation TWPerfMarker
{
  NSString *_name;
  int64_t _time;
}

- (instancetype)initWithName:(NSString *)name time:(int64_t)time
{
  self = [super init];
  if (self) {
    _name = name;
    _time = time;
  }
  return self;
}

- (id)json
{
  return @{
    @"time": @(_time),
    @"name": _name,
    @"tag": @"0",
    @"instanceKey": @1,
    @"pid": @10,
    @"tid": @10,
  };
}

@end

@interface TWPerfLoggerModule () <RCTUIManagerObserver>

@end

@implementation TWPerfLoggerModule
{
  int64_t _startTime;
  int64_t _unixTimestampOffset;
  NSMutableArray *_markers;
}

RCT_EXPORT_MODULE(PerfLogger);

@synthesize bridge = _bridge;

+ (BOOL)requiresMainQueueSetup
{
  // Make sure the module is not lazy loaded.
  return YES;
}

- (void)invalidate
{
  [_bridge.uiManager.observerCoordinator removeObserver:self];
}

- (void)setStartTime:(int64_t)time
{
  _unixTimestampOffset = ([[NSDate date] timeIntervalSince1970] - CACurrentMediaTime()) * 1000;
  _startTime = time;
}

- (void)setBridge:(RCTBridge *)bridge
{

  _bridge = bridge;
  [_bridge.uiManager.observerCoordinator addObserver:self];
}

RCT_EXPORT_METHOD(getTrace:(RCTPromiseResolveBlock)resolve
                  rejecter:(__unused RCTPromiseRejectBlock)reject)
{
  if (_markers == nil) {
    resolve(@{});
    return;
  }
  NSMutableArray *data = [NSMutableArray new];
  for (TWPerfMarker *marker in _markers) {
    [data addObject:[marker json]];
  }
  return resolve(@{
    @"startTime": @(_startTime + _unixTimestampOffset),
    @"data": data
  });
}

- (void)uiManagerWillPerformMounting:(RCTUIManager *)uiManager
{
  [uiManager addUIBlock:^(__unused RCTUIManager *manager, NSDictionary<NSNumber *, UIView *> *viewRegistry) {
    if (_markers != nil) {
      return;
    }
    // Not sure if there is a better way to look for the view with nativeID `tti_complete`...
    for (UIView *view in [viewRegistry allValues]) {
      if ([view.nativeID isEqualToString:@"tti_complete"]) {
        [self.bridge.uiManager.observerCoordinator removeObserver:self];
        RCTPerformanceLogger *perfLogger = self.bridge.performanceLogger;
        NSArray<NSNumber *> *values = [perfLogger valuesForTags];
        NSArray<NSString *> *labels = [perfLogger labelsForTags];
        _markers = [NSMutableArray new];
        for (NSUInteger index = 0; index < RCTPLSize; index++) {
          int64_t start = [values[index * 2] longLongValue];
          int64_t stop = [values[index * 2 + 1] longLongValue];
          NSString *label = labels[index];

          if (start != 0) {
            // Stop + start markers
            [_markers addObject:[[TWPerfMarker alloc] initWithName:[label stringByAppendingString:@"_START"] time:start + _unixTimestampOffset]];
            [_markers addObject:[[TWPerfMarker alloc] initWithName:[label stringByAppendingString:@"_END"] time:stop + _unixTimestampOffset]];
          } else if (stop - _startTime > 0) {
            // Single timestamp
            [_markers addObject:[[TWPerfMarker alloc] initWithName:label time:stop + _unixTimestampOffset]];
          }
        }
        [_markers addObject:[[TWPerfMarker alloc] initWithName:@"TTI_COMPLETE" time:CACurrentMediaTime() * 1000 + _unixTimestampOffset]];
        
        break;
      }
    }
  }];
}

@end