From 2dfa3b34a15039ded46d8e67776228c8c87670f6 Mon Sep 17 00:00:00 2001
From: Tadeu Zagallo <tadeuzagallo@fb.com>
Date: Tue, 2 Jun 2015 06:13:41 -0700
Subject: [PATCH] [ReactNative] Track bridge events' flow

Summary:
@public

Use trace-viewer's flow events to link the bridge calls

Test Plan: {F22498582}
---
 React/Base/RCTBridge.m  | 60 +++++++++++++++++++++++++++--------------
 React/Base/RCTDefines.h |  6 +++++
 React/Base/RCTProfile.h | 18 +++++++++++++
 React/Base/RCTProfile.m | 28 +++++++++++++++++++
 4 files changed, 92 insertions(+), 20 deletions(-)

diff --git a/React/Base/RCTBridge.m b/React/Base/RCTBridge.m
index f122611cd..5047c0cd5 100644
--- a/React/Base/RCTBridge.m
+++ b/React/Base/RCTBridge.m
@@ -1339,8 +1339,11 @@ RCT_INNER_BRIDGE_ONLY(_invokeAndProcessModule:(NSString *)module method:(NSStrin
    * AnyThread
    */
 
+  RCTProfileBeginFlowEvent();
+
   __weak RCTBatchedBridge *weakSelf = self;
   [_javaScriptExecutor executeBlockOnJavaScriptQueue:^{
+    RCTProfileEndFlowEvent();
     RCTProfileBeginEvent();
 
     RCTBatchedBridge *strongSelf = weakSelf;
@@ -1348,13 +1351,17 @@ RCT_INNER_BRIDGE_ONLY(_invokeAndProcessModule:(NSString *)module method:(NSStrin
       return;
     }
 
-    id call = @{
-      @"module": module,
-      @"method": method,
-      @"args": args,
-      @"context": context ?: @0,
-    };
 
+    RCT_IF_DEV(NSNumber *callID = _RCTProfileBeginFlowEvent();)
+    id call = @{
+      @"js_args": @{
+        @"module": module,
+        @"method": method,
+        @"args": args,
+      },
+      @"context": context ?: @0,
+      RCT_IF_DEV(@"call_id": callID,)
+    };
     if ([method isEqualToString:@"invokeCallbackAndReturnFlushedQueue"]) {
       strongSelf->_scheduledCallbacks[args[0]] = call;
     } else {
@@ -1490,8 +1497,10 @@ RCT_INNER_BRIDGE_ONLY(_invokeAndProcessModule:(NSString *)module method:(NSStrin
     return NO;
   }
 
+  RCTProfileBeginFlowEvent();
   __weak RCTBatchedBridge *weakSelf = self;
   [self dispatchBlock:^{
+    RCTProfileEndFlowEvent();
     RCTProfileBeginEvent();
     RCTBatchedBridge *strongSelf = weakSelf;
 
@@ -1526,30 +1535,41 @@ RCT_INNER_BRIDGE_ONLY(_invokeAndProcessModule:(NSString *)module method:(NSStrin
 {
   RCTAssertJSThread();
 
-  RCTProfileImmediateEvent(@"JS Thread Tick", displayLink.timestamp, @"g");
-
-  RCTProfileBeginEvent();
-
-  RCTFrameUpdate *frameUpdate = [[RCTFrameUpdate alloc] initWithDisplayLink:displayLink];
-  for (id<RCTFrameUpdateObserver> observer in _frameUpdateObservers) {
-    if (![observer respondsToSelector:@selector(isPaused)] || ![observer isPaused]) {
-      [self dispatchBlock:^{
-        [observer didUpdateFrame:frameUpdate];
-      } forModule:RCTModuleIDsByName[RCTBridgeModuleNameForClass([observer class])]];
-    }
-  }
-
   NSArray *calls = [_scheduledCallbacks.allObjects arrayByAddingObjectsFromArray:_scheduledCalls];
   NSNumber *currentExecutorID = RCTGetExecutorID(_javaScriptExecutor);
   calls = [calls filteredArrayUsingPredicate:[NSPredicate predicateWithBlock:^BOOL(NSDictionary *call, NSDictionary *bindings) {
     return [call[@"context"] isEqualToNumber:currentExecutorID];
   }]];
+
+  RCT_IF_DEV(
+    RCTProfileImmediateEvent(@"JS Thread Tick", displayLink.timestamp, @"g");
+
+    for (NSDictionary *call in calls) {
+      _RCTProfileEndFlowEvent(call[@"call_id"]);
+    }
+  )
+  RCTProfileBeginEvent();
+
+  RCTFrameUpdate *frameUpdate = [[RCTFrameUpdate alloc] initWithDisplayLink:displayLink];
+  for (id<RCTFrameUpdateObserver> observer in _frameUpdateObservers) {
+    if (![observer respondsToSelector:@selector(isPaused)] || ![observer isPaused]) {
+      RCT_IF_DEV(NSString *name = [NSString stringWithFormat:@"[%@ didUpdateFrame:%f]", observer, displayLink.timestamp];)
+      RCTProfileBeginFlowEvent();
+      [self dispatchBlock:^{
+        RCTProfileEndFlowEvent();
+        RCTProfileBeginEvent();
+        [observer didUpdateFrame:frameUpdate];
+        RCTProfileEndEvent(name, @"objc_call,fps", nil);
+      } forModule:RCTModuleIDsByName[RCTBridgeModuleNameForClass([observer class])]];
+    }
+  }
+
   if (calls.count > 0) {
     _scheduledCalls = [[NSMutableArray alloc] init];
     _scheduledCallbacks = [[RCTSparseArray alloc] init];
     [self _actuallyInvokeAndProcessModule:@"BatchedBridge"
                                    method:@"processBatch"
-                                arguments:@[calls]
+                                arguments:@[[calls valueForKey:@"js_args"]]
                                   context:RCTGetExecutorID(_javaScriptExecutor)];
   }
 
diff --git a/React/Base/RCTDefines.h b/React/Base/RCTDefines.h
index 71550a30d..0d985db8a 100644
--- a/React/Base/RCTDefines.h
+++ b/React/Base/RCTDefines.h
@@ -42,6 +42,12 @@
 #endif
 #endif
 
+#if RCT_DEV
+#define RCT_IF_DEV(...) __VA_ARGS__
+#else
+#define RCT_IF_DEV(...)
+#endif
+
 /**
  * By default, only raise an NSAssertion in debug mode
  * (custom assert functions will still be called).
diff --git a/React/Base/RCTProfile.h b/React/Base/RCTProfile.h
index 0c254c80a..e70217f20 100644
--- a/React/Base/RCTProfile.h
+++ b/React/Base/RCTProfile.h
@@ -22,6 +22,18 @@
 
 #if RCT_DEV
 
+#define RCTProfileBeginFlowEvent() \
+_Pragma("clang diagnostic push") \
+_Pragma("clang diagnostic ignored \"-Wshadow\"") \
+NSNumber *__rct_profile_flow_id = _RCTProfileBeginFlowEvent(); \
+_Pragma("clang diagnostic pop")
+
+#define RCTProfileEndFlowEvent() \
+_RCTProfileEndFlowEvent(__rct_profile_flow_id)
+
+RCT_EXTERN NSNumber *_RCTProfileBeginFlowEvent(void);
+RCT_EXTERN void _RCTProfileEndFlowEvent(NSNumber *);
+
 /**
  * Returns YES if the profiling information is currently being collected
  */
@@ -88,6 +100,12 @@ RCT_EXTERN void RCTProfileImmediateEvent(NSString *, NSTimeInterval , NSString *
 
 #else
 
+#define RCTProfileBeginFlowEvent()
+#define _RCTProfileBeginFlowEvent() @0
+
+#define RCTProfileEndFlowEvent()
+#define _RCTProfileEndFlowEvent()
+
 #define RCTProfileIsProfiling(...) NO
 #define RCTProfileInit(...)
 #define RCTProfileEnd(...) @""
diff --git a/React/Base/RCTProfile.m b/React/Base/RCTProfile.m
index 29e606e86..5be545995 100644
--- a/React/Base/RCTProfile.m
+++ b/React/Base/RCTProfile.m
@@ -171,4 +171,32 @@ void RCTProfileImmediateEvent(NSString *name, NSTimeInterval timestamp, NSString
   );
 }
 
+NSNumber *_RCTProfileBeginFlowEvent(void)
+{
+  static NSUInteger flowID = 0;
+
+  CHECK(@0);
+  RCTProfileAddEvent(RCTProfileTraceEvents,
+    @"name": @"flow",
+    @"id": @(++flowID),
+    @"cat": @"flow",
+    @"ph": @"s",
+    @"ts": RCTProfileTimestamp(CACurrentMediaTime()),
+  );
+
+  return @(flowID);
+}
+
+void _RCTProfileEndFlowEvent(NSNumber *flowID)
+{
+  CHECK();
+  RCTProfileAddEvent(RCTProfileTraceEvents,
+    @"name": @"flow",
+    @"id": flowID,
+    @"cat": @"flow",
+    @"ph": @"f",
+    @"ts": RCTProfileTimestamp(CACurrentMediaTime()),
+  );
+}
+
 #endif