Add performance counters for Fabric

Summary: This diff adds performance loggers for Fabric in Android to be able to compare current version or RN with Fabric This is the summary of Points and Annotations: - **UIManager_CommitStart**: time that React starts the commit (react tree is ready to start rendering in native) - **UIManager_LayoutTime**: this is the time it takes to calculate layout in yoga - **UIManager_FabricFinishTransactionTime**: Time it takes transform "C++ mutationInstructions" into "Java MountItems" and cross boundaries from C++ to Java (including serialization of data) (THIS IS ONLY FABRIC) - **UIManager_DispatchViewUpdates**: time right before RN moves the mount operations to the Queue that is going to be processed in the next tick UI thread - **UIManager_BatchRunStart**: time right before the mountItems are going to be process in the UI Thread - **UIManager_BatchedExecutionTime**: time it took to run batched mountItems (usually layout and prop updates on views) - **UIManager_NonBatchedExecutionTime**: time it took to run non-batched mountItems (usually creation of views) Reviewed By: fkgozali Differential Revision: D13838337 fbshipit-source-id: 0a707619829e7d95ce94d9305ff434d1224afc46
facebook · Feb 5, 2019 · 7f27888 · 7f27888
1 parent c493cfe
commit 7f27888
Show file tree

Hide file tree

Showing 13 changed files with 187 additions and 72 deletions.
diff --git a/React/Fabric/RCTScheduler.mm b/React/Fabric/RCTScheduler.mm
@@ -24,7 +24,7 @@
   SchedulerDelegateProxy(void *scheduler):
     scheduler_(scheduler) {}
 
-  void schedulerDidFinishTransaction(Tag rootTag, const ShadowViewMutationList &mutations) override {
+  void schedulerDidFinishTransaction(Tag rootTag, const ShadowViewMutationList &mutations, const long commitStartTime, const long layoutTime) override {
     RCTScheduler *scheduler = (__bridge RCTScheduler *)scheduler_;
     [scheduler.delegate schedulerDidFinishTransaction:mutations rootTag:rootTag];
   }

diff --git a/ReactAndroid/src/main/java/com/facebook/react/fabric/FabricUIManager.java b/ReactAndroid/src/main/java/com/facebook/react/fabric/FabricUIManager.java
@@ -6,18 +6,33 @@
  */
 package com.facebook.react.fabric;
 
+import static com.facebook.infer.annotation.ThreadConfined.UI;
 import static com.facebook.react.fabric.mounting.LayoutMetricsConversions.getMaxSize;
 import static com.facebook.react.fabric.mounting.LayoutMetricsConversions.getMinSize;
 import static com.facebook.react.fabric.mounting.LayoutMetricsConversions.getYogaMeasureMode;
 import static com.facebook.react.fabric.mounting.LayoutMetricsConversions.getYogaSize;
-import static com.facebook.infer.annotation.ThreadConfined.UI;
 import static com.facebook.react.uimanager.common.UIManagerType.FABRIC;
 
 import android.annotation.SuppressLint;
+import android.os.SystemClock;
 import android.support.annotation.GuardedBy;
 import android.support.annotation.Nullable;
 import android.support.annotation.UiThread;
 import com.facebook.common.logging.FLog;
+import com.facebook.infer.annotation.Assertions;
+import com.facebook.infer.annotation.ThreadConfined;
+import com.facebook.proguard.annotations.DoNotStrip;
+import com.facebook.react.bridge.GuardedRunnable;
+import com.facebook.react.bridge.LifecycleEventListener;
+import com.facebook.react.bridge.NativeMap;
+import com.facebook.react.bridge.ReactApplicationContext;
+import com.facebook.react.bridge.ReactContext;
+import com.facebook.react.bridge.ReadableArray;
+import com.facebook.react.bridge.ReadableNativeMap;
+import com.facebook.react.bridge.UIManager;
+import com.facebook.react.bridge.UiThreadUtil;
+import com.facebook.react.bridge.WritableMap;
+import com.facebook.react.common.ReactConstants;
 import com.facebook.react.fabric.jsi.Binding;
 import com.facebook.react.fabric.jsi.EventBeatManager;
 import com.facebook.react.fabric.jsi.EventEmitterWrapper;
@@ -35,20 +50,6 @@
 import com.facebook.react.fabric.mounting.mountitems.UpdateLayoutMountItem;
 import com.facebook.react.fabric.mounting.mountitems.UpdateLocalDataMountItem;
 import com.facebook.react.fabric.mounting.mountitems.UpdatePropsMountItem;
-import com.facebook.infer.annotation.Assertions;
-import com.facebook.infer.annotation.ThreadConfined;
-import com.facebook.proguard.annotations.DoNotStrip;
-import com.facebook.react.bridge.GuardedRunnable;
-import com.facebook.react.bridge.LifecycleEventListener;
-import com.facebook.react.bridge.NativeMap;
-import com.facebook.react.bridge.ReactApplicationContext;
-import com.facebook.react.bridge.ReactContext;
-import com.facebook.react.bridge.ReadableArray;
-import com.facebook.react.bridge.ReadableNativeMap;
-import com.facebook.react.bridge.UIManager;
-import com.facebook.react.bridge.UiThreadUtil;
-import com.facebook.react.bridge.WritableMap;
-import com.facebook.react.common.ReactConstants;
 import com.facebook.react.modules.core.ReactChoreographer;
 import com.facebook.react.uimanager.IllegalViewOperationException;
 import com.facebook.react.uimanager.ReactRootViewTagGenerator;
@@ -109,6 +110,13 @@ public class FabricUIManager implements UIManager, LifecycleEventListener {
 
   @ThreadConfined(UI)
   private boolean mIsMountingEnabled = true;
+  private long mRunStartTime = 0l;
+  private long mBatchedExecutionTime = 0l;
+  private long mNonBatchedExecutionTime = 0l;
+  private long mDispatchViewUpdatesTime = 0l;
+  private long mCommitStartTime = 0l;
+  private long mLayoutTime = 0l;
+  private long mFinishTransactionTime = 0l;
 
   public FabricUIManager(
       ReactApplicationContext reactContext,
@@ -268,7 +276,17 @@ private long measure(
    */
   @DoNotStrip
   @SuppressWarnings("unused")
-  private void scheduleMountItems(final MountItem mountItems) {
+  private void scheduleMountItems(
+      final MountItem mountItems,
+      long commitStartTime,
+      long layoutTime,
+      long finishTransactionStartTime) {
+
+    // TODO T31905686: support multithreading
+    mCommitStartTime = commitStartTime;
+    mLayoutTime = layoutTime;
+    mFinishTransactionTime = SystemClock.uptimeMillis() - finishTransactionStartTime;
+    mDispatchViewUpdatesTime = SystemClock.uptimeMillis();
     synchronized (mMountItemsLock) {
       mMountItems.add(mountItems);
     }
@@ -294,26 +312,32 @@ private void flushMountItems() {
         mPreMountItems = new ArrayList<>();
       }
 
+      mRunStartTime = SystemClock.uptimeMillis();
       List<MountItem> mountItemsToDispatch;
       synchronized (mMountItemsLock) {
         mountItemsToDispatch = mMountItems;
         mMountItems = new ArrayList<>();
       }
 
+      long nonBatchedExecutionStartTime = SystemClock.uptimeMillis();
       Systrace.beginSection(
         Systrace.TRACE_TAG_REACT_JAVA_BRIDGE,
         "FabricUIManager::premountViews (" + preMountItemsToDispatch.size() + " batches)");
       for (MountItem mountItem : preMountItemsToDispatch) {
         mountItem.execute(mMountingManager);
       }
+      mNonBatchedExecutionTime = SystemClock.uptimeMillis() - nonBatchedExecutionStartTime;
       Systrace.endSection(Systrace.TRACE_TAG_REACT_JAVA_BRIDGE);
 
       Systrace.beginSection(
           Systrace.TRACE_TAG_REACT_JAVA_BRIDGE,
           "FabricUIManager::mountViews (" + mountItemsToDispatch.size() + " batches)");
+
+      long batchedExecutionStartTime = SystemClock.uptimeMillis();
       for (MountItem mountItem : mountItemsToDispatch) {
         mountItem.execute(mMountingManager);
       }
+      mBatchedExecutionTime = SystemClock.uptimeMillis() - batchedExecutionStartTime;
       Systrace.endSection(Systrace.TRACE_TAG_REACT_JAVA_BRIDGE);
     } catch (Exception ex) {
       FLog.e(ReactConstants.TAG, "Exception thrown when executing UIFrameGuarded", ex);
@@ -379,7 +403,9 @@ public void onHostDestroy() {}
   @Override
   public void dispatchCommand(
       final int reactTag, final int commandId, final ReadableArray commandArgs) {
-    scheduleMountItems(new DispatchCommandMountItem(reactTag, commandId, commandArgs));
+    synchronized (mMountItemsLock) {
+      mMountItems.add(new DispatchCommandMountItem(reactTag, commandId, commandArgs));
+    }
   }
 
   @Override
@@ -394,12 +420,20 @@ public void clearJSResponder() {
 
   @Override
   public void profileNextBatch() {
-    // do nothing for now.
+    // TODO T31905686: Remove this method and add support for multi-threading performance counters
   }
 
   @Override
   public Map<String, Long> getPerformanceCounters() {
-    return new HashMap<>();
+    HashMap<String, Long> performanceCounters = new HashMap<>();
+    performanceCounters.put("CommitStartTime", mCommitStartTime);
+    performanceCounters.put("LayoutTime", mLayoutTime);
+    performanceCounters.put("DispatchViewUpdatesTime", mDispatchViewUpdatesTime);
+    performanceCounters.put("RunStartTime", mRunStartTime);
+    performanceCounters.put("BatchedExecutionTime", mBatchedExecutionTime);
+    performanceCounters.put("NonBatchedExecutionTime", mNonBatchedExecutionTime);
+    performanceCounters.put("FinishFabricTransactionTime", mFinishTransactionTime);
+    return performanceCounters;
   }
 
   private class DispatchUIFrameCallback extends GuardedFrameCallback {

diff --git a/ReactAndroid/src/main/java/com/facebook/react/fabric/jsi/jni/Binding.cpp b/ReactAndroid/src/main/java/com/facebook/react/fabric/jsi/jni/Binding.cpp
@@ -20,6 +20,7 @@
 #include <react/uimanager/primitives.h>
 #include <react/uimanager/Scheduler.h>
 #include <react/uimanager/SchedulerDelegate.h>
+#include <react/uimanager/TimeUtils.h>
 
 using namespace facebook::jni;
 using namespace facebook::jsi;
@@ -249,12 +250,15 @@ local_ref<JMountItem::javaobject> createDeleteMountItem(const jni::global_ref<jo
   return deleteInstruction(javaUIManager, mutation.oldChildShadowView.tag);
 }
 
-void Binding::schedulerDidFinishTransaction(const Tag rootTag, const ShadowViewMutationList &mutations) {
+void Binding::schedulerDidFinishTransaction(const Tag rootTag, const ShadowViewMutationList &mutations, const long commitStartTime, const long layoutTime) {
   SystraceSection s("FabricUIManager::schedulerDidFinishTransaction");
   std::vector<local_ref<jobject>> queue;
   // Upper bound estimation of mount items to be delivered to Java side.
   int size = mutations.size() * 3 + 42;
 
+  long finishTransactionStartTime = getTime();
+
+
   local_ref<JArrayClass<JMountItem::javaobject>> mountItemsArray = JArrayClass<JMountItem::javaobject>::newArray(size);
 
   auto mountItems = *(mountItemsArray);
@@ -341,9 +345,9 @@ void Binding::schedulerDidFinishTransaction(const Tag rootTag, const ShadowViewM
 
   static auto scheduleMountItems =
           jni::findClassStatic(UIManagerJavaDescriptor)
-              ->getMethod<void(JMountItem::javaobject)>("scheduleMountItems");
+              ->getMethod<void(JMountItem::javaobject,jlong,jlong,jlong)>("scheduleMountItems");
 
-  scheduleMountItems(javaUIManager_, batch.get());
+  scheduleMountItems(javaUIManager_, batch.get(), commitStartTime, layoutTime, finishTransactionStartTime);
 }
 
 void Binding::setPixelDensity(float pointScaleFactor) {

diff --git a/ReactAndroid/src/main/java/com/facebook/react/fabric/jsi/jni/Binding.h b/ReactAndroid/src/main/java/com/facebook/react/fabric/jsi/jni/Binding.h
@@ -46,7 +46,7 @@ class Binding : public jni::HybridClass<Binding>, public SchedulerDelegate {
 
   void stopSurface(jint surfaceId);
 
-  void schedulerDidFinishTransaction(const Tag rootTag, const ShadowViewMutationList &mutations);
+  void schedulerDidFinishTransaction(const Tag rootTag, const ShadowViewMutationList &mutations, const long commitStartTime, const long layoutTime);
 
   void schedulerDidRequestPreliminaryViewAllocation(const SurfaceId surfaceId, const ComponentName componentName, bool isLayoutable, const ComponentHandle componentHandle);
 

diff --git a/ReactCommon/fabric/uimanager/Scheduler.cpp b/ReactCommon/fabric/uimanager/Scheduler.cpp
@@ -9,6 +9,7 @@
 
 #include <react/core/LayoutContext.h>
 #include <react/uimanager/ComponentDescriptorRegistry.h>
+#include <react/uimanager/TimeUtils.h>
 #include <react/uimanager/UIManager.h>
 #include <react/uimanager/UIManagerBinding.h>
 #include <react/uimanager/UITemplateProcessor.h>
@@ -85,6 +86,7 @@ void Scheduler::startSurface(
 void Scheduler::renderTemplateToSurface(
     SurfaceId surfaceId,
     const std::string &uiTemplate) {
+  long commitStartTime = getTime();
   try {
     if (uiTemplate.size() == 0) {
       return;
@@ -106,7 +108,8 @@ void Scheduler::renderTemplateToSurface(
                 ShadowNodeFragment{.children =
                                        std::make_shared<SharedShadowNodeList>(
                                            SharedShadowNodeList{tree})});
-          });
+          },
+          commitStartTime);
     });
   } catch (const std::exception &e) {
     LOG(ERROR) << "    >>>> EXCEPTION <<<  rendering uiTemplate in "
@@ -115,16 +118,20 @@ void Scheduler::renderTemplateToSurface(
 }
 
 void Scheduler::stopSurface(SurfaceId surfaceId) const {
-  shadowTreeRegistry_.visit(surfaceId, [](const ShadowTree &shadowTree) {
-    // As part of stopping the Surface, we have to commit an empty tree.
-    return shadowTree.tryCommit(
-        [&](const SharedRootShadowNode &oldRootShadowNode) {
-          return std::make_shared<RootShadowNode>(
-              *oldRootShadowNode,
-              ShadowNodeFragment{
-                  .children = ShadowNode::emptySharedShadowNodeSharedList()});
-        });
-  });
+  long commitStartTime = getTime();
+  shadowTreeRegistry_.visit(
+      surfaceId, [commitStartTime](const ShadowTree &shadowTree) {
+        // As part of stopping the Surface, we have to commit an empty tree.
+        return shadowTree.tryCommit(
+            [&](const SharedRootShadowNode &oldRootShadowNode) {
+              return std::make_shared<RootShadowNode>(
+                  *oldRootShadowNode,
+                  ShadowNodeFragment{
+                      .children =
+                          ShadowNode::emptySharedShadowNodeSharedList()});
+            },
+            commitStartTime);
+      });
 
   auto shadowTree = shadowTreeRegistry_.remove(surfaceId);
   shadowTree->setDelegate(nullptr);
@@ -140,15 +147,19 @@ Size Scheduler::measureSurface(
     SurfaceId surfaceId,
     const LayoutConstraints &layoutConstraints,
     const LayoutContext &layoutContext) const {
+  long commitStartTime = getTime();
+
   Size size;
   shadowTreeRegistry_.visit(surfaceId, [&](const ShadowTree &shadowTree) {
-    shadowTree.tryCommit([&](const SharedRootShadowNode &oldRootShadowNode) {
-      auto rootShadowNode =
-          oldRootShadowNode->clone(layoutConstraints, layoutContext);
-      rootShadowNode->layout();
-      size = rootShadowNode->getLayoutMetrics().frame.size;
-      return nullptr;
-    });
+    shadowTree.tryCommit(
+        [&](const SharedRootShadowNode &oldRootShadowNode) {
+          auto rootShadowNode =
+              oldRootShadowNode->clone(layoutConstraints, layoutContext);
+          rootShadowNode->layout();
+          size = rootShadowNode->getLayoutMetrics().frame.size;
+          return nullptr;
+        },
+        commitStartTime);
   });
   return size;
 }
@@ -157,10 +168,14 @@ void Scheduler::constraintSurfaceLayout(
     SurfaceId surfaceId,
     const LayoutConstraints &layoutConstraints,
     const LayoutContext &layoutContext) const {
+  long commitStartTime = getTime();
+
   shadowTreeRegistry_.visit(surfaceId, [&](const ShadowTree &shadowTree) {
-    shadowTree.commit([&](const SharedRootShadowNode &oldRootShadowNode) {
-      return oldRootShadowNode->clone(layoutConstraints, layoutContext);
-    });
+    shadowTree.commit(
+        [&](const SharedRootShadowNode &oldRootShadowNode) {
+          return oldRootShadowNode->clone(layoutConstraints, layoutContext);
+        },
+        commitStartTime);
   });
 }
 
@@ -178,23 +193,29 @@ SchedulerDelegate *Scheduler::getDelegate() const {
 
 void Scheduler::shadowTreeDidCommit(
     const ShadowTree &shadowTree,
-    const ShadowViewMutationList &mutations) const {
+    const ShadowViewMutationList &mutations,
+    long commitStartTime,
+    long layoutTime) const {
   if (delegate_) {
     delegate_->schedulerDidFinishTransaction(
-        shadowTree.getSurfaceId(), mutations);
+        shadowTree.getSurfaceId(), mutations, commitStartTime, layoutTime);
   }
 }
 
 #pragma mark - UIManagerDelegate
 
 void Scheduler::uiManagerDidFinishTransaction(
     SurfaceId surfaceId,
-    const SharedShadowNodeUnsharedList &rootChildNodes) {
+    const SharedShadowNodeUnsharedList &rootChildNodes,
+    long startCommitTime) {
   shadowTreeRegistry_.visit(surfaceId, [&](const ShadowTree &shadowTree) {
-    shadowTree.commit([&](const SharedRootShadowNode &oldRootShadowNode) {
-      return std::make_shared<RootShadowNode>(
-          *oldRootShadowNode, ShadowNodeFragment{.children = rootChildNodes});
-    });
+    shadowTree.commit(
+        [&](const SharedRootShadowNode &oldRootShadowNode) {
+          return std::make_shared<RootShadowNode>(
+              *oldRootShadowNode,
+              ShadowNodeFragment{.children = rootChildNodes});
+        },
+        startCommitTime);
   });
 }
 

diff --git a/ReactCommon/fabric/uimanager/Scheduler.h b/ReactCommon/fabric/uimanager/Scheduler.h
@@ -81,15 +81,18 @@ class Scheduler final : public UIManagerDelegate, public ShadowTreeDelegate {
 
   void uiManagerDidFinishTransaction(
       SurfaceId surfaceId,
-      const SharedShadowNodeUnsharedList &rootChildNodes) override;
+      const SharedShadowNodeUnsharedList &rootChildNodes,
+      long startCommitTime) override;
   void uiManagerDidCreateShadowNode(
       const SharedShadowNode &shadowNode) override;
 
 #pragma mark - ShadowTreeDelegate
 
   void shadowTreeDidCommit(
       const ShadowTree &shadowTree,
-      const ShadowViewMutationList &mutations) const override;
+      const ShadowViewMutationList &mutations,
+      long commitStartTime,
+      long layoutTime) const override;
 
  private:
   SchedulerDelegate *delegate_;

diff --git a/ReactCommon/fabric/uimanager/SchedulerDelegate.h b/ReactCommon/fabric/uimanager/SchedulerDelegate.h
@@ -26,7 +26,9 @@ class SchedulerDelegate {
    */
   virtual void schedulerDidFinishTransaction(
       Tag rootTag,
-      const ShadowViewMutationList &mutations) = 0;
+      const ShadowViewMutationList &mutations,
+      const long commitStartTime,
+      const long layoutTime) = 0;
 
   /*
    * Called right after a new ShadowNode was created.