Instrument JS requires

Summary:
This diff instruments two markers:
- JSRequireBeginning: From the start of the JS require to when we start creating the platform NativeModule
- JSRequireEnding: From the end of platform NativeModule create to the end of the JS require

In order to accomplish this, I had modify `ModuleRegistry::ModuleRegistry()` to accept a `std::shared_ptr<NativeModulePerfLogger>`. I also had to implement the public method `ModuleRegistry::getNativeModulePerfLogger()` so that `JSINativeModules` could start logging the JS require beginning and ending.

Changelog: [Internal]

Reviewed By: PeteTheHeat

Differential Revision: D21418803

fbshipit-source-id: 53828817ae41f23f3f04a95b1d3ac0012735da48

RNTester/Podfile.lock

@@ -252,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)
@@ -270,6 +271,7 @@ 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):
@@ -519,9 +521,9 @@ SPEC CHECKSUMS:
   React-callinvoker: 0dada022d38b73e6e15b33e2a96476153f79bbf6
   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/Base/RCTModuleData.mm

@@ -373,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);
@@ -389,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]);
   }
 }
 

ReactCommon/cxxreact/Android.mk

@@ -19,14 +19,15 @@ LOCAL_CFLAGS := \
 
 LOCAL_CFLAGS += -fexceptions -frtti -Wno-unused-lambda-capture
 
-LOCAL_STATIC_LIBRARIES := boost jsi callinvoker runtimeexecutor
+LOCAL_STATIC_LIBRARIES := boost jsi callinvoker perflogger runtimeexecutor
 LOCAL_SHARED_LIBRARIES := jsinspector libfolly_json glog
 
 include $(BUILD_STATIC_LIBRARY)
 
 $(call import-module,fb)
 $(call import-module,folly)
 $(call import-module,callinvoker)
+$(call import-module,perflogger)
 $(call import-module,jsc)
 $(call import-module,glog)
 $(call import-module,jsi)

ReactCommon/cxxreact/BUCK

@@ -156,6 +156,7 @@ rn_xplat_cxx_library(
         react_native_xplat_target("microprofiler:microprofiler"),
         react_native_xplat_target("runtimeexecutor:runtimeexecutor"),
         "//third-party/glog:glog",
+        react_native_xplat_target("perflogger:perflogger"),
         "//xplat/folly:optional",
     ],
 )

ReactCommon/cxxreact/ModuleRegistry.cpp

@@ -7,6 +7,7 @@
 
 #include "ModuleRegistry.h"
 
+#include <ReactCommon/NativeModulePerfLogger.h>
 #include <glog/logging.h>
 
 #include "NativeModule.h"
@@ -99,14 +100,44 @@ folly::Optional<ModuleConfig> ModuleRegistry::getConfig(
 
   if (it == modulesByName_.end()) {
     if (unknownModules_.find(name) != unknownModules_.end()) {
+      NativeModulePerfLogger::getInstance().moduleJSRequireBeginningFail(
+          name.c_str());
+      NativeModulePerfLogger::getInstance().moduleJSRequireEndingStart(
+          name.c_str());
       return folly::none;
     }
-    if (!moduleNotFoundCallback_ || !moduleNotFoundCallback_(name) ||
-        (it = modulesByName_.find(name)) == modulesByName_.end()) {
+
+    if (!moduleNotFoundCallback_) {
       unknownModules_.insert(name);
+      NativeModulePerfLogger::getInstance().moduleJSRequireBeginningFail(
+          name.c_str());
+      NativeModulePerfLogger::getInstance().moduleJSRequireEndingStart(
+          name.c_str());
       return folly::none;
     }
+
+    NativeModulePerfLogger::getInstance().moduleJSRequireBeginningEnd(
+        name.c_str());
+
+    bool wasModuleLazilyLoaded = moduleNotFoundCallback_(name);
+    it = modulesByName_.find(name);
+
+    bool wasModuleRegisteredWithRegistry =
+        wasModuleLazilyLoaded && it != modulesByName_.end();
+
+    if (!wasModuleRegisteredWithRegistry) {
+      NativeModulePerfLogger::getInstance().moduleJSRequireEndingStart(
+          name.c_str());
+      unknownModules_.insert(name);
+      return folly::none;
+    }
+  } else {
+    NativeModulePerfLogger::getInstance().moduleJSRequireBeginningEnd(
+        name.c_str());
   }
+
+  // If we've gotten this far, then we've signaled moduleJSRequireBeginningEnd
+
   size_t index = it->second;
 
   CHECK(index < modules_.size());
@@ -118,6 +149,12 @@ folly::Optional<ModuleConfig> ModuleRegistry::getConfig(
 
   {
     SystraceSection s_("ModuleRegistry::getConstants", "module", name);
+    /**
+     * In the case that there are constants, we'll initialize the NativeModule,
+     * and signal moduleJSRequireEndingStart. Otherwise, we'll simply signal the
+     * event. The Module will be initialized when we invoke one of its
+     * NativeModule methods.
+     */
     config.push_back(module->getConstants());
   }
 

ReactCommon/cxxreact/React-cxxreact.podspec

@@ -1,3 +1,4 @@
+# coding: utf-8
 # Copyright (c) Facebook, Inc. and its affiliates.
 #
 # This source code is licensed under the MIT license found in the
@@ -42,4 +43,5 @@ Pod::Spec.new do |s|
   s.dependency "React-jsinspector", version
   s.dependency "React-callinvoker", version
   s.dependency "React-runtimeexecutor", version
+  s.dependency "React-perflogger", version
 end

ReactCommon/jsiexecutor/Android.mk

@@ -16,7 +16,7 @@ LOCAL_EXPORT_C_INCLUDES := $(LOCAL_C_INCLUDES)
 
 LOCAL_CFLAGS := -fexceptions -frtti -O3
 
-LOCAL_STATIC_LIBRARIES := libjsi reactnative
+LOCAL_STATIC_LIBRARIES := libjsi reactnative perflogger
 LOCAL_SHARED_LIBRARIES := libfolly_json glog
 
 include $(BUILD_STATIC_LIBRARY)

ReactCommon/jsiexecutor/BUCK

@@ -39,5 +39,6 @@ cxx_library(
         react_native_xplat_dep("jsi:JSIDynamic"),
         react_native_xplat_target("cxxreact:bridge"),
         react_native_xplat_target("cxxreact:jsbigstring"),
+        react_native_xplat_target("perflogger:perflogger"),
     ],
 )

ReactCommon/jsiexecutor/React-jsiexecutor.podspec

@@ -36,6 +36,7 @@ Pod::Spec.new do |s|
 
   s.dependency "React-cxxreact", version
   s.dependency "React-jsi", version
+  s.dependency "React-perflogger", version
   s.dependency "Folly", folly_version
   s.dependency "DoubleConversion"
   s.dependency "glog"

ReactCommon/jsiexecutor/jsireact/JSINativeModules.cpp

@@ -6,6 +6,7 @@
  */
 
 #include "jsireact/JSINativeModules.h"
+#include <ReactCommon/NativeModulePerfLogger.h>
 
 #include <glog/logging.h>
 
@@ -31,21 +32,34 @@ Value JSINativeModules::getModule(Runtime &rt, const PropNameID &name) {
 
   std::string moduleName = name.utf8(rt);
 
+  NativeModulePerfLogger::getInstance().moduleJSRequireBeginningStart(
+      moduleName.c_str());
+
   const auto it = m_objects.find(moduleName);
   if (it != m_objects.end()) {
+    NativeModulePerfLogger::getInstance().moduleJSRequireBeginningCacheHit(
+        moduleName.c_str());
+    NativeModulePerfLogger::getInstance().moduleJSRequireBeginningEnd(
+        moduleName.c_str());
     return Value(rt, it->second);
   }
 
   auto module = createModule(rt, moduleName);
   if (!module.hasValue()) {
+    NativeModulePerfLogger::getInstance().moduleJSRequireEndingFail(
+        moduleName.c_str());
     // Allow lookup to continue in the objects own properties, which allows for
     // overrides of NativeModules
     return nullptr;
   }
 
   auto result =
       m_objects.emplace(std::move(moduleName), std::move(*module)).first;
-  return Value(rt, result->second);
+
+  Value ret = Value(rt, result->second);
+  NativeModulePerfLogger::getInstance().moduleJSRequireEndingEnd(
+      moduleName.c_str());
+  return ret;
 }
 
 void JSINativeModules::reset() {