Instrument sync and async method calls (#28893)

Summary:
Pull Request resolved: https://github.com/facebook/react-native/pull/28893

`JSIExecutor::callSerializableNativeHook` converts the arguments from `JSI::Value` to `folly::dynamic`. Then, `RCTNativeModule` converts the arguments from `folly::dynamic` to ObjC data structures in its `static invokeInner` function.

Therefore, I decided to start the sync markers inside `JSIExecutor::callSerializableNativeHook`, which required me to expose these two methode `ModuleRegistry::getModuleName` and `ModuleRegistry::getModuleSyncMethodName`. This shouldn't modify performance because we eagerly generate a NativeModule's methods when it's first required. So, at worst, this is doing a cache lookup.

Changelog: [Internal]

Reviewed By: PeteTheHeat

Differential Revision: D21443610

fbshipit-source-id: 67cf563b0b06153e56e63ba7e186eea31eafc853

React/CxxModule/RCTNativeModule.mm

@@ -15,16 +15,26 @@
 #import <React/RCTLog.h>
 #import <React/RCTProfile.h>
 #import <React/RCTUtils.h>
+#import <ReactCommon/NativeModulePerfLogger.h>
 
 #ifdef WITH_FBSYSTRACE
 #include <fbsystrace.h>
 #endif
 
+namespace {
+enum SchedulingContext { Sync, Async };
+}
+
 namespace facebook {
 namespace react {
 
-static MethodCallResult
-invokeInner(RCTBridge *bridge, RCTModuleData *moduleData, unsigned int methodId, const folly::dynamic &params);
+static MethodCallResult invokeInner(
+    RCTBridge *bridge,
+    RCTModuleData *moduleData,
+    unsigned int methodId,
+    const folly::dynamic &params,
+    int callId,
+    SchedulingContext context);
 
 RCTNativeModule::RCTNativeModule(RCTBridge *bridge, RCTModuleData *moduleData)
     : m_bridge(bridge), m_moduleData(moduleData)
@@ -36,6 +46,11 @@ std::string RCTNativeModule::getName()
   return [m_moduleData.name UTF8String];
 }
 
+std::string RCTNativeModule::getSyncMethodName(unsigned int methodId)
+{
+  return m_moduleData.methods[methodId].JSMethodName;
+}
+
 std::vector<MethodDescriptor> RCTNativeModule::getMethods()
 {
   std::vector<MethodDescriptor> descs;
@@ -58,13 +73,26 @@ folly::dynamic RCTNativeModule::getConstants()
 
 void RCTNativeModule::invoke(unsigned int methodId, folly::dynamic &&params, int callId)
 {
+  const char *moduleName = [m_moduleData.name UTF8String];
+  const char *methodName = m_moduleData.methods[methodId].JSMethodName;
+
+  dispatch_queue_t queue = m_moduleData.methodQueue;
+  const bool isSyncModule = queue == RCTJSThread;
+
+  if (isSyncModule) {
+    NativeModulePerfLogger::getInstance().syncMethodCallStart(moduleName, methodName);
+    NativeModulePerfLogger::getInstance().syncMethodCallArgConversionStart(moduleName, methodName);
+  } else {
+    NativeModulePerfLogger::getInstance().asyncMethodCallStart(moduleName, methodName);
+  }
+
   // capture by weak pointer so that we can safely use these variables in a callback
   __weak RCTBridge *weakBridge = m_bridge;
   __weak RCTModuleData *weakModuleData = m_moduleData;
   // The BatchedBridge version of this buckets all the callbacks by thread, and
   // queues one block on each.  This is much simpler; we'll see how it goes and
   // iterate.
-  dispatch_block_t block = [weakBridge, weakModuleData, methodId, params = std::move(params), callId] {
+  dispatch_block_t block = [weakBridge, weakModuleData, methodId, params = std::move(params), callId, isSyncModule] {
 #ifdef WITH_FBSYSTRACE
     if (callId != -1) {
       fbsystrace_end_async_flow(TRACE_TAG_REACT_APPS, "native", callId);
@@ -72,13 +100,14 @@ void RCTNativeModule::invoke(unsigned int methodId, folly::dynamic &&params, int
 #else
     (void)(callId);
 #endif
-    invokeInner(weakBridge, weakModuleData, methodId, std::move(params));
+    invokeInner(weakBridge, weakModuleData, methodId, std::move(params), callId, isSyncModule ? Sync : Async);
   };
 
-  dispatch_queue_t queue = m_moduleData.methodQueue;
-  if (queue == RCTJSThread) {
+  if (isSyncModule) {
     block();
+    NativeModulePerfLogger::getInstance().syncMethodCallReturnConversionEnd(moduleName, methodName);
   } else if (queue) {
+    NativeModulePerfLogger::getInstance().asyncMethodCallDispatch(moduleName, methodName);
     dispatch_async(queue, block);
   }
 
@@ -90,17 +119,36 @@ void RCTNativeModule::invoke(unsigned int methodId, folly::dynamic &&params, int
         m_moduleData.name);
   }
 #endif
+
+  if (isSyncModule) {
+    NativeModulePerfLogger::getInstance().syncMethodCallEnd(moduleName, methodName);
+  } else {
+    NativeModulePerfLogger::getInstance().asyncMethodCallEnd(moduleName, methodName);
+  }
 }
 
 MethodCallResult RCTNativeModule::callSerializableNativeHook(unsigned int reactMethodId, folly::dynamic &&params)
 {
-  return invokeInner(m_bridge, m_moduleData, reactMethodId, params);
+  return invokeInner(m_bridge, m_moduleData, reactMethodId, params, 0, Sync);
 }
 
-static MethodCallResult
-invokeInner(RCTBridge *bridge, RCTModuleData *moduleData, unsigned int methodId, const folly::dynamic &params)
+static MethodCallResult invokeInner(
+    RCTBridge *bridge,
+    RCTModuleData *moduleData,
+    unsigned int methodId,
+    const folly::dynamic &params,
+    int callId,
+    SchedulingContext context)
 {
   if (!bridge || !bridge.valid || !moduleData) {
+    if (context == Sync) {
+      /**
+       * NOTE: moduleName and methodName are "". This shouldn't be an issue because there can only be one ongoing sync
+       * call at a time, and when we call syncMethodCallFail, that one call should terminate. This is also an
+       * exceptional scenario, so it shouldn't occur often.
+       */
+      NativeModulePerfLogger::getInstance().syncMethodCallFail("N/A", "N/A");
+    }
     return folly::none;
   }
 
@@ -109,11 +157,46 @@ invokeInner(RCTBridge *bridge, RCTModuleData *moduleData, unsigned int methodId,
     RCTLogError(@"Unknown methodID: %ud for module: %@", methodId, moduleData.name);
   }
 
+  const char *moduleName = [moduleData.name UTF8String];
+  const char *methodName = moduleData.methods[methodId].JSMethodName;
+
+  if (context == Async) {
+    NativeModulePerfLogger::getInstance().asyncMethodCallExecutionStart(moduleName, methodName, (int32_t)callId);
+    NativeModulePerfLogger::getInstance().asyncMethodCallExecutionArgConversionStart(
+        moduleName, methodName, (int32_t)callId);
+  }
+
   NSArray *objcParams = convertFollyDynamicToId(params);
+
+  if (context == Sync) {
+    NativeModulePerfLogger::getInstance().syncMethodCallArgConversionEnd(moduleName, methodName);
+  }
+
   @try {
+    if (context == Sync) {
+      NativeModulePerfLogger::getInstance().syncMethodCallExecutionStart(moduleName, methodName);
+    } else {
+      NativeModulePerfLogger::getInstance().asyncMethodCallExecutionArgConversionEnd(
+          moduleName, methodName, (int32_t)callId);
+    }
+
     id result = [method invokeWithBridge:bridge module:moduleData.instance arguments:objcParams];
+
+    if (context == Sync) {
+      NativeModulePerfLogger::getInstance().syncMethodCallExecutionEnd(moduleName, methodName);
+      NativeModulePerfLogger::getInstance().syncMethodCallReturnConversionStart(moduleName, methodName);
+    } else {
+      NativeModulePerfLogger::getInstance().asyncMethodCallExecutionEnd(moduleName, methodName, (int32_t)callId);
+    }
+
     return convertIdToFollyDynamic(result);
   } @catch (NSException *exception) {
+    if (context == Sync) {
+      NativeModulePerfLogger::getInstance().syncMethodCallFail(moduleName, methodName);
+    } else {
+      NativeModulePerfLogger::getInstance().asyncMethodCallExecutionFail(moduleName, methodName, (int32_t)callId);
+    }
+
     // Pass on JS exceptions
     if ([exception.name hasPrefix:RCTFatalExceptionName]) {
       @throw exception;