Granularly track perf of Fabric

Summary: Enable granular perf measurements under Fabric.

Reviewed By: mdvacca

Differential Revision: D16021797

fbshipit-source-id: c25a8f7cebf53abfcfc39c8f6d50900813214abb

ReactAndroid/src/main/java/com/facebook/react/bridge/ReactMarker.java

@@ -21,11 +21,23 @@ public class ReactMarker {
     void logMarker(ReactMarkerConstants name, @Nullable String tag, int instanceKey);
   };
 
+  // This is for verbose, Fabric-only logging
+  // In the future we can deprecate the old logMarker API and
+  public interface FabricMarkerListener {
+    void logFabricMarker(
+        ReactMarkerConstants name, @Nullable String tag, int instanceKey, long timestamp);
+  };
+
   // Use a list instead of a set here because we expect the number of listeners
   // to be very small, and we want listeners to be called in a deterministic
   // order.
   private static final List<MarkerListener> sListeners = new ArrayList<>();
 
+  // Use a list instead of a set here because we expect the number of listeners
+  // to be very small, and we want listeners to be called in a deterministic
+  // order. For Fabric-specific events.
+  private static final List<FabricMarkerListener> sFabricMarkerListeners = new ArrayList<>();
+
   @DoNotStrip
   public static void addListener(MarkerListener listener) {
     synchronized (sListeners) {
@@ -49,6 +61,50 @@ public class ReactMarker {
     }
   }
 
+  // Specific to Fabric marker listeners
+  @DoNotStrip
+  public static void addFabricListener(FabricMarkerListener listener) {
+    synchronized (sFabricMarkerListeners) {
+      if (!sFabricMarkerListeners.contains(listener)) {
+        sFabricMarkerListeners.add(listener);
+      }
+    }
+  }
+
+  // Specific to Fabric marker listeners
+  @DoNotStrip
+  public static void removeFabricListener(FabricMarkerListener listener) {
+    synchronized (sFabricMarkerListeners) {
+      sFabricMarkerListeners.remove(listener);
+    }
+  }
+
+  // Specific to Fabric marker listeners
+  @DoNotStrip
+  public static void clearFabricMarkerListeners() {
+    synchronized (sFabricMarkerListeners) {
+      sFabricMarkerListeners.clear();
+    }
+  }
+
+  // Specific to Fabric marker listeners
+  @DoNotStrip
+  public static void logFabricMarker(
+      ReactMarkerConstants name, @Nullable String tag, int instanceKey, long timestamp) {
+    synchronized (sFabricMarkerListeners) {
+      for (FabricMarkerListener listener : sFabricMarkerListeners) {
+        listener.logFabricMarker(name, tag, instanceKey, timestamp);
+      }
+    }
+  }
+
+  // Specific to Fabric marker listeners
+  @DoNotStrip
+  public static void logFabricMarker(
+      ReactMarkerConstants name, @Nullable String tag, int instanceKey) {
+    logFabricMarker(name, tag, instanceKey, -1);
+  }
+
   @DoNotStrip
   public static void logMarker(String name) {
     logMarker(name, null);
@@ -92,5 +148,6 @@ public class ReactMarker {
         listener.logMarker(name, tag, instanceKey);
       }
     }
+    logFabricMarker(name, tag, instanceKey);
   }
 }

ReactAndroid/src/main/java/com/facebook/react/bridge/ReactMarkerConstants.java

@@ -92,6 +92,19 @@ public enum ReactMarkerConstants {
   JAVASCRIPT_EXECUTOR_FACTORY_INJECT_END,
   LOAD_REACT_NATIVE_SO_FILE_START,
   LOAD_REACT_NATIVE_SO_FILE_END,
+  // Fabric-specific constants below this line
   LOAD_REACT_NATIVE_FABRIC_SO_FILE_START,
   LOAD_REACT_NATIVE_FABRIC_SO_FILE_END,
+  FABRIC_COMMIT_START,
+  FABRIC_COMMIT_END,
+  FABRIC_FINISH_TRANSACTION_START,
+  FABRIC_FINISH_TRANSACTION_END,
+  FABRIC_DIFF_START,
+  FABRIC_DIFF_END,
+  FABRIC_LAYOUT_START,
+  FABRIC_LAYOUT_END,
+  FABRIC_BATCH_EXECUTION_START,
+  FABRIC_BATCH_EXECUTION_END,
+  FABRIC_UPDATE_UI_MAIN_THREAD_START,
+  FABRIC_UPDATE_UI_MAIN_THREAD_END
 }

ReactAndroid/src/main/java/com/facebook/react/fabric/FabricUIManager.java

@@ -29,6 +29,8 @@ 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.ReactMarker;
+import com.facebook.react.bridge.ReactMarkerConstants;
 import com.facebook.react.bridge.ReadableArray;
 import com.facebook.react.bridge.ReadableMap;
 import com.facebook.react.bridge.UIManager;
@@ -117,6 +119,12 @@ public class FabricUIManager implements UIManager, LifecycleEventListener {
   private long mFinishTransactionTime = 0l;
   private long mFinishTransactionCPPTime = 0l;
 
+  // C++ keeps track of commit numbers for telemetry purposes. We don't want to incur a JNI
+  // round-trip cost just for this, so commits from C++ are numbered 0+ and synchronous commits
+  // are 10k+. Since these are only used for perf tracking, it's unlikely for the number of commits
+  // from C++ to exceed 9,999 and it should be obvious what's going on when analyzing performance.
+  private int mCurrentSynchronousCommitNumber = 10000;
+
   public FabricUIManager(
       ReactApplicationContext reactContext,
       ViewManagerRegistry viewManagerRegistry,
@@ -290,8 +298,8 @@ public class FabricUIManager implements UIManager, LifecycleEventListener {
 
   @DoNotStrip
   @SuppressWarnings("unused")
-  private MountItem createBatchMountItem(MountItem[] items, int size) {
-    return new BatchMountItem(items, size);
+  private MountItem createBatchMountItem(MountItem[] items, int size, int commitNumber) {
+    return new BatchMountItem(items, size, commitNumber);
   }
 
   @DoNotStrip
@@ -321,11 +329,18 @@ public class FabricUIManager implements UIManager, LifecycleEventListener {
   @Override
   public void synchronouslyUpdateViewOnUIThread(int reactTag, ReadableMap props) {
     long time = SystemClock.uptimeMillis();
+    int commitNumber = mCurrentSynchronousCommitNumber++;
     try {
-      scheduleMountItem(updatePropsMountItem(reactTag, props), time, 0, time, time);
+      ReactMarker.logFabricMarker(
+          ReactMarkerConstants.FABRIC_UPDATE_UI_MAIN_THREAD_START, null, commitNumber);
+      scheduleMountItem(
+          updatePropsMountItem(reactTag, props), commitNumber, time, 0, 0, 0, 0, 0, 0);
     } catch (Exception ex) {
       // ignore exceptions for now
       // TODO T42943890: Fix animations in Fabric and remove this try/catch
+    } finally {
+      ReactMarker.logFabricMarker(
+          ReactMarkerConstants.FABRIC_UPDATE_UI_MAIN_THREAD_END, null, commitNumber);
     }
   }
 
@@ -337,21 +352,57 @@ public class FabricUIManager implements UIManager, LifecycleEventListener {
   @SuppressWarnings("unused")
   private void scheduleMountItem(
       final MountItem mountItem,
+      int commitNumber,
       long commitStartTime,
-      long layoutTime,
+      long diffStartTime,
+      long diffEndTime,
+      long layoutStartTime,
+      long layoutEndTime,
       long finishTransactionStartTime,
       long finishTransactionEndTime) {
-
     // TODO T31905686: support multithreading
-    mCommitStartTime = commitStartTime;
-    mLayoutTime = layoutTime;
-    mFinishTransactionCPPTime = finishTransactionEndTime - finishTransactionStartTime;
-    mFinishTransactionTime = SystemClock.uptimeMillis() - finishTransactionStartTime;
-    mDispatchViewUpdatesTime = SystemClock.uptimeMillis();
+    // When Binding.cpp calls scheduleMountItems during a commit phase, it always calls with
+    // a BatchMountItem. No other sites call into this with a BatchMountItem, and Binding.cpp only
+    // calls scheduleMountItems with a BatchMountItem.
+    boolean isBatchMountItem = mountItem instanceof BatchMountItem;
+
+    if (isBatchMountItem) {
+      mCommitStartTime = commitStartTime;
+      mLayoutTime = layoutEndTime - layoutStartTime;
+      mFinishTransactionCPPTime = finishTransactionEndTime - finishTransactionStartTime;
+      mFinishTransactionTime = SystemClock.uptimeMillis() - finishTransactionStartTime;
+      mDispatchViewUpdatesTime = SystemClock.uptimeMillis();
+    }
+
     synchronized (mMountItemsLock) {
       mMountItems.add(mountItem);
     }
 
+    // Post markers outside of lock
+    if (isBatchMountItem) {
+      ReactMarker.logFabricMarker(
+          ReactMarkerConstants.FABRIC_COMMIT_START, null, commitNumber, mCommitStartTime);
+      ReactMarker.logFabricMarker(
+          ReactMarkerConstants.FABRIC_FINISH_TRANSACTION_START,
+          null,
+          commitNumber,
+          finishTransactionStartTime);
+      ReactMarker.logFabricMarker(
+          ReactMarkerConstants.FABRIC_FINISH_TRANSACTION_END,
+          null,
+          commitNumber,
+          finishTransactionEndTime);
+      ReactMarker.logFabricMarker(
+          ReactMarkerConstants.FABRIC_DIFF_START, null, commitNumber, diffStartTime);
+      ReactMarker.logFabricMarker(
+          ReactMarkerConstants.FABRIC_DIFF_END, null, commitNumber, diffEndTime);
+      ReactMarker.logFabricMarker(
+          ReactMarkerConstants.FABRIC_LAYOUT_START, null, commitNumber, layoutStartTime);
+      ReactMarker.logFabricMarker(
+          ReactMarkerConstants.FABRIC_LAYOUT_END, null, commitNumber, layoutEndTime);
+      ReactMarker.logFabricMarker(ReactMarkerConstants.FABRIC_COMMIT_END, null, commitNumber);
+    }
+
     if (UiThreadUtil.isOnUiThread()) {
       dispatchMountItems();
     }

ReactAndroid/src/main/java/com/facebook/react/fabric/jni/Binding.cpp

@@ -476,6 +476,8 @@ void Binding::schedulerDidFinishTransaction(
   auto surfaceId = mountingTransaction->getSurfaceId();
   auto &mutations = mountingTransaction->getMutations();
 
+  int64_t commitNumber = telemetry.getCommitNumber();
+
   std::vector<local_ref<jobject>> queue;
   // Upper bound estimation of mount items to be delivered to Java side.
   int size = mutations.size() * 3 + 42;
@@ -609,24 +611,28 @@ void Binding::schedulerDidFinishTransaction(
   static auto createMountItemsBatchContainer =
       jni::findClassStatic(UIManagerJavaDescriptor)
           ->getMethod<alias_ref<JMountItem>(
-              jtypeArray<JMountItem::javaobject>, jint)>(
+              jtypeArray<JMountItem::javaobject>, jint, jint)>(
               "createBatchMountItem");
 
   auto batch = createMountItemsBatchContainer(
-      localJavaUIManager, mountItemsArray.get(), position);
+      localJavaUIManager, mountItemsArray.get(), position, commitNumber);
 
-  static auto scheduleMountItems =
+  static auto scheduleMountItem =
       jni::findClassStatic(UIManagerJavaDescriptor)
-          ->getMethod<void(JMountItem::javaobject, jlong, jlong, jlong, jlong)>(
+          ->getMethod<void(JMountItem::javaobject, jint, jlong, jlong, jlong, jlong, jlong, jlong, jlong)>(
               "scheduleMountItem");
 
   long finishTransactionEndTime = getTime();
 
-  scheduleMountItems(
+  scheduleMountItem(
       localJavaUIManager,
       batch.get(),
+      telemetry.getCommitNumber(),
       telemetry.getCommitStartTime(),
-      telemetry.getLayoutTime(),
+      telemetry.getDiffStartTime(),
+      telemetry.getDiffEndTime(),
+      telemetry.getLayoutStartTime(),
+      telemetry.getLayoutEndTime(),
       finishTransactionStartTime,
       finishTransactionEndTime);
 }

ReactAndroid/src/main/java/com/facebook/react/fabric/mounting/mountitems/BatchMountItem.java

@@ -11,6 +11,8 @@ import static com.facebook.react.fabric.FabricUIManager.TAG;
 
 import com.facebook.common.logging.FLog;
 import com.facebook.proguard.annotations.DoNotStrip;
+import com.facebook.react.bridge.ReactMarker;
+import com.facebook.react.bridge.ReactMarkerConstants;
 import com.facebook.react.fabric.mounting.MountingManager;
 import com.facebook.systrace.Systrace;
 
@@ -28,8 +30,9 @@ public class BatchMountItem implements MountItem {
 
   private final MountItem[] mMountItems;
   private final int mSize;
+  private final int mCommitNumber;
 
-  public BatchMountItem(MountItem[] items, int size) {
+  public BatchMountItem(MountItem[] items, int size, int commitNumber) {
     if (items == null) {
       throw new NullPointerException();
     }
@@ -39,6 +42,7 @@ public class BatchMountItem implements MountItem {
     }
     mMountItems = items;
     mSize = size;
+    mCommitNumber = commitNumber;
   }
 
   @Override
@@ -46,6 +50,11 @@ public class BatchMountItem implements MountItem {
     Systrace.beginSection(
         Systrace.TRACE_TAG_REACT_JAVA_BRIDGE, "FabricUIManager::mountViews - " + mSize + " items");
 
+    if (mCommitNumber > 0) {
+      ReactMarker.logFabricMarker(
+          ReactMarkerConstants.FABRIC_BATCH_EXECUTION_START, null, mCommitNumber);
+    }
+
     for (int mountItemIndex = 0; mountItemIndex < mSize; mountItemIndex++) {
       MountItem mountItem = mMountItems[mountItemIndex];
       if (DEBUG) {
@@ -54,6 +63,11 @@ public class BatchMountItem implements MountItem {
       mountItem.execute(mountingManager);
     }
 
+    if (mCommitNumber > 0) {
+      ReactMarker.logFabricMarker(
+          ReactMarkerConstants.FABRIC_BATCH_EXECUTION_END, null, mCommitNumber);
+    }
+
     Systrace.endSection(Systrace.TRACE_TAG_REACT_JAVA_BRIDGE);
   }