Instrument sync and async method calls

RNTester/Podfile.lock

@@ -99,6 +99,7 @@ PODS:
     - React-cxxreact (= 1000.0.0)
     - React-jsi (= 1000.0.0)
     - React-jsiexecutor (= 1000.0.0)
+    - React-perflogger (= 1000.0.0)
     - Yoga
   - React-Core/ARTHeaders (1000.0.0):
     - Folly (= 2020.01.13.00)
@@ -107,6 +108,7 @@ PODS:
     - React-cxxreact (= 1000.0.0)
     - React-jsi (= 1000.0.0)
     - React-jsiexecutor (= 1000.0.0)
+    - React-perflogger (= 1000.0.0)
     - Yoga
   - React-Core/CoreModulesHeaders (1000.0.0):
     - Folly (= 2020.01.13.00)
@@ -115,13 +117,15 @@ PODS:
     - React-cxxreact (= 1000.0.0)
     - React-jsi (= 1000.0.0)
     - React-jsiexecutor (= 1000.0.0)
+    - React-perflogger (= 1000.0.0)
     - Yoga
   - React-Core/Default (1000.0.0):
     - Folly (= 2020.01.13.00)
     - glog
     - React-cxxreact (= 1000.0.0)
     - React-jsi (= 1000.0.0)
     - React-jsiexecutor (= 1000.0.0)
+    - React-perflogger (= 1000.0.0)
     - Yoga
   - React-Core/DevSupport (1000.0.0):
     - Folly (= 2020.01.13.00)
@@ -132,6 +136,7 @@ PODS:
     - React-jsi (= 1000.0.0)
     - React-jsiexecutor (= 1000.0.0)
     - React-jsinspector (= 1000.0.0)
+    - React-perflogger (= 1000.0.0)
     - Yoga
   - React-Core/RCTActionSheetHeaders (1000.0.0):
     - Folly (= 2020.01.13.00)
@@ -140,6 +145,7 @@ PODS:
     - React-cxxreact (= 1000.0.0)
     - React-jsi (= 1000.0.0)
     - React-jsiexecutor (= 1000.0.0)
+    - React-perflogger (= 1000.0.0)
     - Yoga
   - React-Core/RCTAnimationHeaders (1000.0.0):
     - Folly (= 2020.01.13.00)
@@ -148,6 +154,7 @@ PODS:
     - React-cxxreact (= 1000.0.0)
     - React-jsi (= 1000.0.0)
     - React-jsiexecutor (= 1000.0.0)
+    - React-perflogger (= 1000.0.0)
     - Yoga
   - React-Core/RCTBlobHeaders (1000.0.0):
     - Folly (= 2020.01.13.00)
@@ -156,6 +163,7 @@ PODS:
     - React-cxxreact (= 1000.0.0)
     - React-jsi (= 1000.0.0)
     - React-jsiexecutor (= 1000.0.0)
+    - React-perflogger (= 1000.0.0)
     - Yoga
   - React-Core/RCTImageHeaders (1000.0.0):
     - Folly (= 2020.01.13.00)
@@ -164,6 +172,7 @@ PODS:
     - React-cxxreact (= 1000.0.0)
     - React-jsi (= 1000.0.0)
     - React-jsiexecutor (= 1000.0.0)
+    - React-perflogger (= 1000.0.0)
     - Yoga
   - React-Core/RCTLinkingHeaders (1000.0.0):
     - Folly (= 2020.01.13.00)
@@ -172,6 +181,7 @@ PODS:
     - React-cxxreact (= 1000.0.0)
     - React-jsi (= 1000.0.0)
     - React-jsiexecutor (= 1000.0.0)
+    - React-perflogger (= 1000.0.0)
     - Yoga
   - React-Core/RCTNetworkHeaders (1000.0.0):
     - Folly (= 2020.01.13.00)
@@ -180,6 +190,7 @@ PODS:
     - React-cxxreact (= 1000.0.0)
     - React-jsi (= 1000.0.0)
     - React-jsiexecutor (= 1000.0.0)
+    - React-perflogger (= 1000.0.0)
     - Yoga
   - React-Core/RCTPushNotificationHeaders (1000.0.0):
     - Folly (= 2020.01.13.00)
@@ -188,6 +199,7 @@ PODS:
     - React-cxxreact (= 1000.0.0)
     - React-jsi (= 1000.0.0)
     - React-jsiexecutor (= 1000.0.0)
+    - React-perflogger (= 1000.0.0)
     - Yoga
   - React-Core/RCTSettingsHeaders (1000.0.0):
     - Folly (= 2020.01.13.00)
@@ -196,6 +208,7 @@ PODS:
     - React-cxxreact (= 1000.0.0)
     - React-jsi (= 1000.0.0)
     - React-jsiexecutor (= 1000.0.0)
+    - React-perflogger (= 1000.0.0)
     - Yoga
   - React-Core/RCTTextHeaders (1000.0.0):
     - Folly (= 2020.01.13.00)
@@ -204,6 +217,7 @@ PODS:
     - React-cxxreact (= 1000.0.0)
     - React-jsi (= 1000.0.0)
     - React-jsiexecutor (= 1000.0.0)
+    - React-perflogger (= 1000.0.0)
     - Yoga
   - React-Core/RCTVibrationHeaders (1000.0.0):
     - Folly (= 2020.01.13.00)
@@ -212,6 +226,7 @@ PODS:
     - React-cxxreact (= 1000.0.0)
     - React-jsi (= 1000.0.0)
     - React-jsiexecutor (= 1000.0.0)
+    - React-perflogger (= 1000.0.0)
     - Yoga
   - React-Core/RCTWebSocket (1000.0.0):
     - Folly (= 2020.01.13.00)
@@ -220,6 +235,7 @@ PODS:
     - React-cxxreact (= 1000.0.0)
     - React-jsi (= 1000.0.0)
     - React-jsiexecutor (= 1000.0.0)
+    - React-perflogger (= 1000.0.0)
     - Yoga
   - React-CoreModules (1000.0.0):
     - FBReactNativeSpec (= 1000.0.0)
@@ -236,6 +252,7 @@ PODS:
     - glog
     - React-callinvoker (= 1000.0.0)
     - React-jsinspector (= 1000.0.0)
+    - React-perflogger (= 1000.0.0)
     - React-runtimeexecutor (= 1000.0.0)
   - React-jsi (1000.0.0):
     - boost-for-react-native (= 1.63.0)
@@ -254,7 +271,9 @@ PODS:
     - glog
     - React-cxxreact (= 1000.0.0)
     - React-jsi (= 1000.0.0)
+    - React-perflogger (= 1000.0.0)
   - React-jsinspector (1000.0.0)
+  - React-perflogger (1000.0.0)
   - React-RCTActionSheet (1000.0.0):
     - React-Core/RCTActionSheetHeaders (= 1000.0.0)
   - React-RCTAnimation (1000.0.0):
@@ -329,6 +348,7 @@ PODS:
     - React-Core (= 1000.0.0)
     - React-cxxreact (= 1000.0.0)
     - React-jsi (= 1000.0.0)
+    - React-perflogger (= 1000.0.0)
   - ReactCommon/turbomodule/samples (1000.0.0):
     - DoubleConversion
     - Folly (= 2020.01.13.00)
@@ -337,6 +357,7 @@ PODS:
     - React-Core (= 1000.0.0)
     - React-cxxreact (= 1000.0.0)
     - React-jsi (= 1000.0.0)
+    - React-perflogger (= 1000.0.0)
     - ReactCommon/turbomodule/core (= 1000.0.0)
   - Yoga (1.14.0)
   - YogaKit (1.18.1):
@@ -380,6 +401,7 @@ DEPENDENCIES:
   - React-jsi (from `../ReactCommon/jsi`)
   - React-jsiexecutor (from `../ReactCommon/jsiexecutor`)
   - React-jsinspector (from `../ReactCommon/jsinspector`)
+  - React-perflogger (from `../ReactCommon/perflogger`)
   - React-RCTActionSheet (from `../Libraries/ActionSheetIOS`)
   - React-RCTAnimation (from `../Libraries/NativeAnimation`)
   - React-RCTBlob (from `../Libraries/Blob`)
@@ -444,6 +466,8 @@ EXTERNAL SOURCES:
     :path: "../ReactCommon/jsiexecutor"
   React-jsinspector:
     :path: "../ReactCommon/jsinspector"
+  React-perflogger:
+    :path: "../ReactCommon/perflogger"
   React-RCTActionSheet:
     :path: "../Libraries/ActionSheetIOS"
   React-RCTAnimation:
@@ -495,12 +519,13 @@ SPEC CHECKSUMS:
   React: cafb3c2321f7df55ce90dbf29d513799a79e4418
   React-ART: df0460bdff42ef039e28ee3ffd41f50b75644788
   React-callinvoker: 0dada022d38b73e6e15b33e2a96476153f79bbf6
-  React-Core: 08c69f013e6fd654ea8f9fd84bbd66780a54d886
+  React-Core: d85e4563acbfbb6e6be7414a813ad55d05d675df
   React-CoreModules: d13d148c851af5780f864be74bc2165140923dc7
-  React-cxxreact: b43a94e679b307660de530a3af872ab4c7d9925d
+  React-cxxreact: bb64d8c5798d75565870ff1a7a8ac57a09bd9ff8
   React-jsi: fe94132da767bfc4801968c2a12abae43e9a833e
-  React-jsiexecutor: 55eff40b2e0696e7a979016e321793ec8b28a2ac
+  React-jsiexecutor: 959bb48c75a3bfc1b1d2b991087a6d8df721cbcf
   React-jsinspector: 7fbf9b42b58b02943a0d89b0ba9fff0070f2de98
+  React-perflogger: d32d3423e466a825ef2e9934fe9d62b149e5d9f8
   React-RCTActionSheet: 51c43beeb74ef41189e87fe9823e53ebf6210359
   React-RCTAnimation: 9d09196c641c1ebfef3a4e9ae670bcda5fadb420
   React-RCTBlob: 715489626cf44d28ee51e5277a4d559167351696
@@ -513,7 +538,7 @@ SPEC CHECKSUMS:
   React-RCTText: 6c01963d3e562109f5548262b09b1b2bc260dd60
   React-RCTVibration: d42d73dafd9f63cf758656ee743aa80c566798ff
   React-runtimeexecutor: 60dd6204a13f68a1aa1118870edcc604a791df2b
-  ReactCommon: 39e00b754f5e1628804fab28f44146d06280f700
+  ReactCommon: 511b4a9ea129c129c6dbc982942007d195903a9a
   Yoga: f7fa200d8c49f97b54c9421079e781fb900b5cae
   YogaKit: f782866e155069a2cca2517aafea43200b01fd5a
 

React-Core.podspec

@@ -94,6 +94,7 @@ Pod::Spec.new do |s|
 
   s.dependency "Folly", folly_version
   s.dependency "React-cxxreact", version
+  s.dependency "React-perflogger", version
   s.dependency "React-jsi", version
   s.dependency "React-jsiexecutor", version
   s.dependency "Yoga"

React/Base/RCTModuleData.mm

@@ -8,7 +8,10 @@
 #import "RCTModuleData.h"
 
 #import <objc/runtime.h>
-#include <mutex>
+#import <atomic>
+#import <mutex>
+
+#import <ReactCommon/NativeModulePerfLogger.h>
 
 #import "RCTBridge+Private.h"
 #import "RCTBridge.h"
@@ -17,6 +20,16 @@
 #import "RCTProfile.h"
 #import "RCTUtils.h"
 
+using namespace facebook::react;
+
+namespace {
+int32_t getUniqueId()
+{
+  static std::atomic<int32_t> counter{0};
+  return counter++;
+}
+}
+
 @implementation RCTModuleData {
   NSDictionary<NSString *, id> *_constantsToExport;
   NSString *_queueName;
@@ -110,22 +123,29 @@ - (instancetype)initWithModuleInstance:(id<RCTBridgeModule>)instance bridge:(RCT
 
 #pragma mark - private setup methods
 
-- (void)setUpInstanceAndBridge
+- (void)setUpInstanceAndBridge:(int32_t)requestId
 {
+  NSString *moduleName = [self name];
+
   RCT_PROFILE_BEGIN_EVENT(
       RCTProfileTagAlways,
       @"[RCTModuleData setUpInstanceAndBridge]",
       @{@"moduleClass" : NSStringFromClass(_moduleClass)});
   {
     std::unique_lock<std::mutex> lock(_instanceLock);
+    BOOL shouldSetup = !_setupComplete && _bridge.valid;
 
-    if (!_setupComplete && _bridge.valid) {
+    if (shouldSetup) {
       if (!_instance) {
         if (RCT_DEBUG && _requiresMainQueueSetup) {
           RCTAssertMainQueue();
         }
         RCT_PROFILE_BEGIN_EVENT(RCTProfileTagAlways, @"[RCTModuleData setUpInstanceAndBridge] Create module", nil);
+
+        NativeModulePerfLogger::getInstance().moduleCreateConstructStart([moduleName UTF8String], requestId);
         _instance = _moduleProvider ? _moduleProvider() : nil;
+        NativeModulePerfLogger::getInstance().moduleCreateConstructEnd([moduleName UTF8String], requestId);
+
         RCT_PROFILE_END_EVENT(RCTProfileTagAlways, @"");
         if (!_instance) {
           // Module init returned nil, probably because automatic instantiation
@@ -143,7 +163,13 @@ - (void)setUpInstanceAndBridge
       if (_instance && RCTProfileIsProfiling()) {
         RCTProfileHookInstance(_instance);
       }
+    }
+
+    if (_instance) {
+      NativeModulePerfLogger::getInstance().moduleCreateSetUpStart([moduleName UTF8String], requestId);
+    }
 
+    if (shouldSetup) {
       // Bridge must be set before methodQueue is set up, as methodQueue
       // initialization requires it (View Managers get their queue by calling
       // self.bridge.uiManager.methodQueue)
@@ -171,6 +197,10 @@ - (void)setUpInstanceAndBridge
     // thread.
     _requiresMainQueueSetup = NO;
   }
+
+  if (_instance) {
+    NativeModulePerfLogger::getInstance().moduleCreateSetUpEnd([moduleName UTF8String], requestId);
+  }
 }
 
 - (void)setBridgeForInstance
@@ -286,6 +316,10 @@ - (BOOL)hasInstance
 
 - (id<RCTBridgeModule>)instance
 {
+  NSString *moduleName = [self name];
+  int32_t requestId = getUniqueId();
+  NativeModulePerfLogger::getInstance().moduleCreateStart([moduleName UTF8String], requestId);
+
   if (!_setupComplete) {
     RCT_PROFILE_BEGIN_EVENT(
         RCTProfileTagAlways, ([NSString stringWithFormat:@"[RCTModuleData instanceForClass:%@]", _moduleClass]), nil);
@@ -301,13 +335,21 @@ - (BOOL)hasInstance
       }
 
       RCTUnsafeExecuteOnMainQueueSync(^{
-        [self setUpInstanceAndBridge];
+        [self setUpInstanceAndBridge:requestId];
       });
       RCT_PROFILE_END_EVENT(RCTProfileTagAlways, @"");
     } else {
-      [self setUpInstanceAndBridge];
+      [self setUpInstanceAndBridge:requestId];
     }
     RCT_PROFILE_END_EVENT(RCTProfileTagAlways, @"");
+  } else {
+    NativeModulePerfLogger::getInstance().moduleCreateCacheHit([moduleName UTF8String], requestId);
+  }
+
+  if (_instance) {
+    NativeModulePerfLogger::getInstance().moduleCreateEnd([moduleName UTF8String], requestId);
+  } else {
+    NativeModulePerfLogger::getInstance().moduleCreateFail([moduleName UTF8String], requestId);
   }
   return _instance;
 }
@@ -331,10 +373,22 @@ - (NSString *)name
 
 - (void)gatherConstants
 {
+  NSString *moduleName = [self name];
+
   if (_hasConstantsToExport && !_constantsToExport) {
     RCT_PROFILE_BEGIN_EVENT(
         RCTProfileTagAlways, ([NSString stringWithFormat:@"[RCTModuleData gatherConstants] %@", _moduleClass]), nil);
     (void)[self instance];
+
+    /**
+     * Why do we instrument moduleJSRequireEndingStart here?
+     *  - NativeModule requires from JS go through ModuleRegistry::getConfig().
+     *  - ModuleRegistry::getConfig() calls NativeModule::getConstants() first.
+     *  - This delegates to RCTNativeModule::getConstants(), which calls RCTModuleData gatherConstants().
+     *  - Therefore, this is the first statement that executes after the NativeModule is created/initialized in a JS
+     *    require.
+     */
+    NativeModulePerfLogger::getInstance().moduleJSRequireEndingStart([moduleName UTF8String]);
     if (_requiresMainQueueSetup) {
       if (!RCTIsMainQueue()) {
         RCTLogWarn(@"Required dispatch_sync to load constants for %@. This may lead to deadlocks", _moduleClass);
@@ -347,6 +401,12 @@ - (void)gatherConstants
       _constantsToExport = [_instance constantsToExport] ?: @{};
     }
     RCT_PROFILE_END_EVENT(RCTProfileTagAlways, @"");
+  } else {
+    /**
+     * If a NativeModule doesn't have constants, it isn't eagerly loaded until its methods are first invoked.
+     * Therefore, we should immediately start JSRequireEnding
+     */
+    NativeModulePerfLogger::getInstance().moduleJSRequireEndingStart([moduleName UTF8String]);
   }
 }