Add more performance logs and improve Systrace support

Reviewed By: tadeuzagallo

Differential Revision: D3040998

fb-gh-sync-id: c5ab4e5bcc073f94a2d309bfa7698919cf7e8856
shipit-source-id: c5ab4e5bcc073f94a2d309bfa7698919cf7e8856

React/Base/RCTBatchedBridge.m

@@ -131,7 +131,9 @@ RCT_EXTERN NSArray<Class> *RCTGetModuleClasses(void);
 
     // Asynchronously initialize the JS executor
     dispatch_group_async(setupJSExecutorAndModuleConfig, bridgeQueue, ^{
+      RCTPerformanceLoggerStart(RCTPLJSCExecutorSetup);
       [weakSelf setUpExecutor];
+      RCTPerformanceLoggerEnd(RCTPLJSCExecutorSetup);
     });
 
     // Asynchronously gather the module config
@@ -171,13 +173,8 @@ RCT_EXTERN NSArray<Class> *RCTGetModuleClasses(void);
 - (void)loadSource:(RCTSourceLoadBlock)_onSourceLoad
 {
   RCTPerformanceLoggerStart(RCTPLScriptDownload);
-  NSUInteger cookie = RCTProfileBeginAsyncEvent(0, @"JavaScript download", nil);
-
-  // Suppress a warning if RCTProfileBeginAsyncEvent gets compiled out
-  (void)cookie;
 
   RCTSourceLoadBlock onSourceLoad = ^(NSError *error, NSData *source) {
-    RCTProfileEndAsyncEvent(0, @"native", cookie, @"JavaScript download", @"JS async", nil);
     RCTPerformanceLoggerEnd(RCTPLScriptDownload);
 
     _onSourceLoad(error, source);
@@ -332,7 +329,7 @@ RCT_EXTERN NSArray<Class> *RCTGetModuleClasses(void);
                     moduleClass, moduleName, moduleData.moduleClass);
       }
     }
-    
+
     // Instantiate moduleData (TODO: can we defer this until config generation?)
     moduleData = [[RCTModuleData alloc] initWithModuleClass:moduleClass
                                                      bridge:self];
@@ -366,6 +363,7 @@ RCT_EXTERN NSArray<Class> *RCTGetModuleClasses(void);
   _moduleSetupComplete = YES;
 
   // Set up modules that require main thread init or constants export
+  RCTPerformanceLoggerSet(RCTPLNativeModuleMainThread, 0);
   for (RCTModuleData *moduleData in _moduleDataByID) {
     __weak RCTBatchedBridge *weakSelf = self;
     if (moduleData.requiresMainThreadSetup) {
@@ -376,8 +374,10 @@ RCT_EXTERN NSArray<Class> *RCTGetModuleClasses(void);
       // they will already be available before they are ever required.
       dispatch_group_async(dispatchGroup, dispatch_get_main_queue(), ^{
         if (weakSelf.valid) {
+          RCTPerformanceLoggerAppendStart(RCTPLNativeModuleMainThread);
           (void)[moduleData instance];
           [moduleData gatherConstants];
+          RCTPerformanceLoggerAppendEnd(RCTPLNativeModuleMainThread);
         }
       });
     } else if (moduleData.hasConstantsToExport) {
@@ -386,7 +386,9 @@ RCT_EXTERN NSArray<Class> *RCTGetModuleClasses(void);
       (void)[moduleData instance];
       dispatch_group_async(dispatchGroup, dispatch_get_main_queue(), ^{
         if (weakSelf.valid) {
+          RCTPerformanceLoggerAppendStart(RCTPLNativeModuleMainThread);
           [moduleData gatherConstants];
+          RCTPerformanceLoggerAppendEnd(RCTPLNativeModuleMainThread);
         }
       });
     }

React/Base/RCTModuleData.m

@@ -13,6 +13,7 @@
 #import "RCTBridge+Private.h"
 #import "RCTModuleMethod.h"
 #import "RCTLog.h"
+#import "RCTProfile.h"
 #import "RCTUtils.h"
 
 @implementation RCTModuleData
@@ -185,6 +186,7 @@ RCT_NOT_IMPLEMENTED(- (instancetype)init);
 - (id<RCTBridgeModule>)instance
 {
   if (!_setupComplete) {
+    RCT_PROFILE_BEGIN_EVENT(0, [NSString stringWithFormat:@"[RCTModuleData instanceForClass:%@]", _moduleClass], nil);
     if (_requiresMainThreadSetup) {
       // The chances of deadlock here are low, because module init very rarely
       // calls out to other threads, however we can't control when a module might
@@ -196,6 +198,7 @@ RCT_NOT_IMPLEMENTED(- (instancetype)init);
     } else {
       [self setUpInstanceAndBridge];
     }
+    RCT_PROFILE_END_EVENT(0, @"", nil);
   }
   return _instance;
 }

React/Base/RCTPerformanceLogger.h

@@ -15,15 +15,48 @@ typedef NS_ENUM(NSUInteger, RCTPLTag) {
   RCTPLScriptDownload = 0,
   RCTPLScriptExecution,
   RCTPLNativeModuleInit,
+  RCTPLNativeModuleMainThread,
   RCTPLNativeModulePrepareConfig,
   RCTPLNativeModuleInjectConfig,
+  RCTPLJSCExecutorSetup,
   RCTPLTTI,
   RCTPLBundleSize,
   RCTPLSize
 };
 
+/**
+ * Starts measuring a metric with the given tag.
+ * Overrides previous value if the measurement has been already started.
+ * If RCTProfile is enabled it also begins appropriate async event.
+ */
 RCT_EXTERN void RCTPerformanceLoggerStart(RCTPLTag tag);
+
+/**
+ * Stops measuring a metric with given tag.
+ * Checks if RCTPerformanceLoggerStart() has been called before
+ * and doesn't do anything and log a message if it hasn't.
+ * If RCTProfile is enabled it also ends appropriate async event.
+ */
 RCT_EXTERN void RCTPerformanceLoggerEnd(RCTPLTag tag);
+
+/**
+ * Sets given value for a metric with given tag.
+ */
 RCT_EXTERN void RCTPerformanceLoggerSet(RCTPLTag tag, int64_t value);
+
+/**
+ * Starts an additional measurement for a metric with given tag.
+ * It doesn't override previous measurement, instead it'll append a new value
+ * to the old one.
+ */
+RCT_EXTERN void RCTPerformanceLoggerAppendStart(RCTPLTag tag);
+
+/**
+ * Stops measurement and appends the result to the metric with given tag.
+ * Checks if RCTPerformanceLoggerAppendStart() has been called before
+ * and doesn't do anything and log a message if it hasn't.
+ */
+RCT_EXTERN void RCTPerformanceLoggerAppendEnd(RCTPLTag tag);
+
 RCT_EXTERN NSArray<NSNumber *> *RCTPerformanceLoggerOutput(void);
 RCT_EXTERN NSArray *RCTPerformanceLoggerLabels(void);

React/Base/RCTPerformanceLogger.m

@@ -12,11 +12,18 @@
 #import "RCTPerformanceLogger.h"
 #import "RCTRootView.h"
 #import "RCTLog.h"
+#import "RCTProfile.h"
 
 static int64_t RCTPLData[RCTPLSize][2] = {};
+static int64_t RCTPLCookies[RCTPLSize] = {};
 
 void RCTPerformanceLoggerStart(RCTPLTag tag)
 {
+  if (RCTProfileIsProfiling()) {
+    NSString *label = RCTPerformanceLoggerLabels()[tag];
+    RCTPLCookies[tag] = RCTProfileBeginAsyncEvent(0, label, nil);
+  }
+
   RCTPLData[tag][0] = CACurrentMediaTime() * 1000;
   RCTPLData[tag][1] = 0;
 }
@@ -25,6 +32,11 @@ void RCTPerformanceLoggerEnd(RCTPLTag tag)
 {
   if (RCTPLData[tag][0] != 0 && RCTPLData[tag][1] == 0) {
     RCTPLData[tag][1] = CACurrentMediaTime() * 1000;
+
+    if (RCTProfileIsProfiling()) {
+      NSString *label = RCTPerformanceLoggerLabels()[tag];
+      RCTProfileEndAsyncEvent(0, @"native", RCTPLCookies[tag], label, @"RCTPerformanceLogger", nil);
+    }
   } else {
     RCTLogInfo(@"Unbalanced calls start/end for tag %li", (unsigned long)tag);
   }
@@ -36,6 +48,21 @@ void RCTPerformanceLoggerSet(RCTPLTag tag, int64_t value)
   RCTPLData[tag][1] = value;
 }
 
+void RCTPerformanceLoggerAppendStart(RCTPLTag tag)
+{
+  RCTPLData[tag][0] = CACurrentMediaTime() * 1000;
+}
+
+void RCTPerformanceLoggerAppendEnd(RCTPLTag tag)
+{
+  if (RCTPLData[tag][0] != 0) {
+    RCTPLData[tag][1] += CACurrentMediaTime() * 1000 - RCTPLData[tag][0];
+    RCTPLData[tag][0] = 0;
+  } else {
+    RCTLogInfo(@"Unbalanced calls start/end for tag %li", (unsigned long)tag);
+  }
+}
+
 NSArray<NSNumber *> *RCTPerformanceLoggerOutput(void)
 {
   return @[
@@ -45,10 +72,14 @@ NSArray<NSNumber *> *RCTPerformanceLoggerOutput(void)
     @(RCTPLData[RCTPLScriptExecution][1]),
     @(RCTPLData[RCTPLNativeModuleInit][0]),
     @(RCTPLData[RCTPLNativeModuleInit][1]),
+    @(RCTPLData[RCTPLNativeModuleMainThread][0]),
+    @(RCTPLData[RCTPLNativeModuleMainThread][1]),
     @(RCTPLData[RCTPLNativeModulePrepareConfig][0]),
     @(RCTPLData[RCTPLNativeModulePrepareConfig][1]),
     @(RCTPLData[RCTPLNativeModuleInjectConfig][0]),
     @(RCTPLData[RCTPLNativeModuleInjectConfig][1]),
+    @(RCTPLData[RCTPLJSCExecutorSetup][0]),
+    @(RCTPLData[RCTPLJSCExecutorSetup][1]),
     @(RCTPLData[RCTPLTTI][0]),
     @(RCTPLData[RCTPLTTI][1]),
     @(RCTPLData[RCTPLBundleSize][0]),
@@ -58,15 +89,22 @@ NSArray<NSNumber *> *RCTPerformanceLoggerOutput(void)
 
 NSArray *RCTPerformanceLoggerLabels(void)
 {
-  return @[
-    @"ScriptDownload",
-    @"ScriptExecution",
-    @"NativeModuleInit",
-    @"NativeModulePrepareConfig",
-    @"NativeModuleInjectConfig",
-    @"TTI",
-    @"BundleSize",
-  ];
+  static NSArray *labels;
+  static dispatch_once_t token;
+  dispatch_once(&token, ^{
+    labels = @[
+      @"ScriptDownload",
+      @"ScriptExecution",
+      @"NativeModuleInit",
+      @"NativeModuleMainThread",
+      @"NativeModulePrepareConfig",
+      @"NativeModuleInjectConfig",
+      @"JSCExecutorSetup",
+      @"RootViewTTI",
+      @"BundleSize",
+    ];
+  });
+  return labels;
 }
 
 @interface RCTPerformanceLogger : NSObject <RCTBridgeModule>