[ReactNative] Optimize console.profile and add markers on JS entry points

Summary:
@public

Right now the profiler shows how long the executor took on JS but doesn't show
how long each of the batched calls took, this adds a *very* high level view of JS
execution (still doesn't show properly calls dispatched with setImmediate)

Also added a global property on JS to avoid trips to Native when profiling is
disabled.

Test Plan:
Run the Profiler on any app

{F22491690}

Libraries/Utilities/BridgeProfiling.js

@@ -0,0 +1,37 @@
+/**
+ * Copyright (c) 2015-present, Facebook, Inc.
+ * All rights reserved.
+ *
+ * This source code is licensed under the BSD-style license found in the
+ * LICENSE file in the root directory of this source tree. An additional grant
+ * of patent rights can be found in the PATENTS file in the same directory.
+ *
+ * @providesModule BridgeProfiling
+ * @flow
+ */
+'use strict';
+
+var GLOBAL = GLOBAL || this;
+
+var BridgeProfiling = {
+  profile(profileName: String, args?: any) {
+    if (GLOBAL.__BridgeProfilingIsProfiling) {
+      if (args) {
+        try {
+          args = JSON.stringify(args);
+        } catch(err) {
+          args = err.message;
+        }
+      }
+      console.profile(profileName, args);
+    }
+  },
+
+  profileEnd() {
+    if (GLOBAL.__BridgeProfilingIsProfiling) {
+      console.profileEnd();
+    }
+  },
+};
+
+module.exports = BridgeProfiling;

Libraries/Utilities/MessageQueue.js

@@ -17,6 +17,7 @@ var ReactUpdates = require('ReactUpdates');
 var invariant = require('invariant');
 var warning = require('warning');
 
+var BridgeProfiling = require('BridgeProfiling');
 var JSTimersExecution = require('JSTimersExecution');
 
 var INTERNAL_ERROR = 'Error in MessageQueue implementation';
@@ -277,7 +278,9 @@ var MessageQueueMixin = {
       if (DEBUG_SPY_MODE) {
         console.log('N->JS: Callback#' + cbID + '(' + JSON.stringify(args) + ')');
       }
+      BridgeProfiling.profile('Callback#' + cbID + '(' + JSON.stringify(args) + ')');
       cb.apply(scope, args);
+      BridgeProfiling.profileEnd();
     } catch(ie_requires_catch) {
       throw ie_requires_catch;
     } finally {
@@ -311,7 +314,9 @@ var MessageQueueMixin = {
         'N->JS: ' + moduleName + '.' + methodName +
         '(' + JSON.stringify(params) + ')');
     }
+    BridgeProfiling.profile(moduleName + '.' + methodName + '(' + JSON.stringify(params) + ')');
     var ret = jsCall(this._requireFunc(moduleName), methodName, params);
+    BridgeProfiling.profileEnd();
 
     return ret;
   },
@@ -330,7 +335,8 @@ var MessageQueueMixin = {
 
   processBatch: function(batch) {
     var self = this;
-    return guardReturn(function () {
+    BridgeProfiling.profile('MessageQueue.processBatch()');
+    var flushedQueue = guardReturn(function () {
       ReactUpdates.batchedUpdates(function() {
         batch.forEach(function(call) {
           invariant(
@@ -346,8 +352,12 @@ var MessageQueueMixin = {
               'Unrecognized method called on BatchedBridge: ' + call.method);
           }
         });
+        BridgeProfiling.profile('React.batchedUpdates()');
       });
+      BridgeProfiling.profileEnd();
     }, null, this._flushedQueueUnguarded, this);
+    BridgeProfiling.profileEnd();
+    return flushedQueue;
   },
 
   setLoggingEnabled: function(enabled) {
@@ -472,10 +482,12 @@ var MessageQueueMixin = {
   },
 
   _flushedQueueUnguarded: function() {
+    BridgeProfiling.profile('JSTimersExecution.callImmediates()');
     ReactUpdates.batchedUpdates(() => {
       // Call the functions registered via setImmediate
       JSTimersExecution.callImmediates();
     });
+    BridgeProfiling.profileEnd();
 
     var currentOutgoingItems = this._outgoingItems;
     this._swapAndReinitializeBuffer();

React/Base/RCTProfile.h

@@ -20,6 +20,9 @@
  * before before using it.
  */
 
+NSString *const RCTProfileDidStartProfiling;
+NSString *const RCTProfileDidEndProfiling;
+
 #if RCT_DEV
 
 #define RCTProfileBeginFlowEvent() \

React/Base/RCTProfile.m

@@ -17,6 +17,9 @@
 #import "RCTDefines.h"
 #import "RCTUtils.h"
 
+NSString *const RCTProfileDidStartProfiling = @"RCTProfileDidStartProfiling";
+NSString *const RCTProfileDidEndProfiling = @"RCTProfileDidEndProfiling";
+
 #if RCT_DEV
 
 #pragma mark - Prototypes
@@ -113,10 +116,16 @@ void RCTProfileInit(void)
       RCTProfileSamples: [[NSMutableArray alloc] init],
     };
   );
+
+  [[NSNotificationCenter defaultCenter] postNotificationName:RCTProfileDidStartProfiling
+                                                      object:nil];
 }
 
 NSString *RCTProfileEnd(void)
 {
+  [[NSNotificationCenter defaultCenter] postNotificationName:RCTProfileDidEndProfiling
+                                                      object:nil];
+
   RCTProfileLock(
     NSString *log = RCTJSONStringify(RCTProfileInfo, NULL);
     RCTProfileEventID = 0;

React/Executors/RCTContextExecutor.m

@@ -133,22 +133,27 @@ static JSValueRef RCTConsoleProfile(JSContextRef context, JSObjectRef object, JS
     profileName = [NSString stringWithFormat:@"Profile %d", profileCounter++];
   }
 
-  [profiles addObjectsFromArray:@[profileName, profileID]];
+  id profileInfo = [NSNull null];
+  if (argumentCount > 1 && !JSValueIsUndefined(context, arguments[1])) {
+    profileInfo = @[RCTJSValueToNSString(context, arguments[1])];
+  }
+
+  [profiles addObjectsFromArray:@[profileName, profileID, profileInfo]];
 
-  RCTLog(@"Profile '%@' finished.", profileName);
   return JSValueMakeUndefined(context);
 }
 
 static JSValueRef RCTConsoleProfileEnd(JSContextRef context, JSObjectRef object, JSObjectRef thisObject, size_t argumentCount, const JSValueRef arguments[], JSValueRef *exception)
 {
+  NSString *profileInfo = [profiles lastObject];
+  [profiles removeLastObject];
   NSNumber *profileID = [profiles lastObject];
   [profiles removeLastObject];
   NSString *profileName = [profiles lastObject];
   [profiles removeLastObject];
 
-  _RCTProfileEndEvent(profileID, profileName, @"console", nil);
+  _RCTProfileEndEvent(profileID, profileName, @"console", profileInfo);
 
-  RCTLog(@"Profile '%@' started.", profileName);
   return JSValueMakeUndefined(context);
 }
 
@@ -244,6 +249,13 @@ static NSError *RCTNSErrorFromJSError(JSContextRef context, JSValueRef jsError)
 #if RCT_DEV
       [strongSelf _addNativeHook:RCTConsoleProfile withName:"consoleProfile"];
       [strongSelf _addNativeHook:RCTConsoleProfileEnd withName:"consoleProfileEnd"];
+
+      for (NSString *event in @[RCTProfileDidStartProfiling, RCTProfileDidEndProfiling]) {
+        [[NSNotificationCenter defaultCenter] addObserver:self
+                                                 selector:@selector(toggleProfilingFlag:)
+                                                     name:event
+                                                   object:nil];
+      }
 #endif
 
     }];
@@ -252,6 +264,21 @@ static NSError *RCTNSErrorFromJSError(JSContextRef context, JSValueRef jsError)
   return self;
 }
 
+- (void)toggleProfilingFlag:(NSNotification *)notification
+{
+  JSObjectRef globalObject = JSContextGetGlobalObject(_context.ctx);
+
+  bool enabled = [notification.name isEqualToString:RCTProfileDidStartProfiling];
+  JSStringRef JSName = JSStringCreateWithUTF8CString("__BridgeProfilingIsProfiling");
+  JSObjectSetProperty(_context.ctx,
+                      globalObject,
+                      JSName,
+                      JSValueMakeBoolean(_context.ctx, enabled),
+                      kJSPropertyAttributeNone,
+                      NULL);
+  JSStringRelease(JSName);
+}
+
 - (void)_addNativeHook:(JSObjectCallAsFunctionCallback)hook withName:(const char *)name
 {
   JSObjectRef globalObject = JSContextGetGlobalObject(_context.ctx);
@@ -269,6 +296,10 @@ static NSError *RCTNSErrorFromJSError(JSContextRef context, JSValueRef jsError)
 
 - (void)invalidate
 {
+#if RCT_DEV
+  [[NSNotificationCenter defaultCenter] removeObserver:self];
+#endif
+
   [_context performSelector:@selector(invalidate) onThread:_javaScriptThread withObject:nil waitUntilDone:NO];
 }
 

React/Modules/RCTUIManager.m

@@ -921,6 +921,7 @@ RCT_EXPORT_METHOD(findSubviewIn:(NSNumber *)reactTag atPoint:(CGPoint)point call
 
 - (void)batchDidComplete
 {
+  RCTProfileBeginEvent();
   // Gather blocks to be executed now that all view hierarchy manipulations have
   // been completed (note that these may still take place before layout has finished)
   for (RCTViewManager *manager in _viewManagers.allValues) {
@@ -951,6 +952,9 @@ RCT_EXPORT_METHOD(findSubviewIn:(NSNumber *)reactTag atPoint:(CGPoint)point call
     _nextLayoutAnimation = nil;
   }
 
+  RCTProfileEndEvent(@"[RCTUIManager batchDidComplete]", @"uimanager", @{
+    @"view_count": @([_viewRegistry count]),
+  });
   [self flushUIBlocks];
 }