diff --git a/ReactAndroid/src/main/java/com/facebook/react/bridge/ReactMarker.java b/ReactAndroid/src/main/java/com/facebook/react/bridge/ReactMarker.java index 27ec9cdb30c..9444a833562 100644 --- a/ReactAndroid/src/main/java/com/facebook/react/bridge/ReactMarker.java +++ b/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 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 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); } } diff --git a/ReactAndroid/src/main/java/com/facebook/react/bridge/ReactMarkerConstants.java b/ReactAndroid/src/main/java/com/facebook/react/bridge/ReactMarkerConstants.java index 89193a392e3..8f532571d8c 100644 --- a/ReactAndroid/src/main/java/com/facebook/react/bridge/ReactMarkerConstants.java +++ b/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 } diff --git a/ReactAndroid/src/main/java/com/facebook/react/fabric/FabricUIManager.java b/ReactAndroid/src/main/java/com/facebook/react/fabric/FabricUIManager.java index 80ed2732cc9..c6a907ade9b 100644 --- a/ReactAndroid/src/main/java/com/facebook/react/fabric/FabricUIManager.java +++ b/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(); } diff --git a/ReactAndroid/src/main/java/com/facebook/react/fabric/jni/Binding.cpp b/ReactAndroid/src/main/java/com/facebook/react/fabric/jni/Binding.cpp index 0245ee22468..b4c7d31ef44 100644 --- a/ReactAndroid/src/main/java/com/facebook/react/fabric/jni/Binding.cpp +++ b/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> 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( - jtypeArray, jint)>( + jtypeArray, 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( + ->getMethod( "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); } diff --git a/ReactAndroid/src/main/java/com/facebook/react/fabric/mounting/mountitems/BatchMountItem.java b/ReactAndroid/src/main/java/com/facebook/react/fabric/mounting/mountitems/BatchMountItem.java index 21381aad8c3..72c1ea3d42f 100644 --- a/ReactAndroid/src/main/java/com/facebook/react/fabric/mounting/mountitems/BatchMountItem.java +++ b/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); } diff --git a/ReactCommon/fabric/mounting/MountingCoordinator.cpp b/ReactCommon/fabric/mounting/MountingCoordinator.cpp index e36eddcbb88..47ecf719f55 100644 --- a/ReactCommon/fabric/mounting/MountingCoordinator.cpp +++ b/ReactCommon/fabric/mounting/MountingCoordinator.cpp @@ -13,6 +13,7 @@ #include #include +#include namespace facebook { namespace react { @@ -53,9 +54,14 @@ better::optional MountingCoordinator::pullTransaction() number_++; + auto telemetry = lastRevision_->getTelemetry(); + telemetry.willDiff(); + auto mutations = calculateShadowViewMutations( baseRevision_.getRootShadowNode(), lastRevision_->getRootShadowNode()); + telemetry.didDiff(); + #ifdef RN_SHADOW_TREE_INTROSPECTION stubViewTree_.mutate(mutations); auto stubViewTree = @@ -76,7 +82,6 @@ better::optional MountingCoordinator::pullTransaction() } #endif - auto telemetry = lastRevision_->getTelemetry(); baseRevision_ = std::move(*lastRevision_); lastRevision_.reset(); diff --git a/ReactCommon/fabric/mounting/MountingTelemetry.cpp b/ReactCommon/fabric/mounting/MountingTelemetry.cpp index 121c51e4551..75985860eac 100644 --- a/ReactCommon/fabric/mounting/MountingTelemetry.cpp +++ b/ReactCommon/fabric/mounting/MountingTelemetry.cpp @@ -18,6 +18,7 @@ void MountingTelemetry::willCommit() { assert(commitStartTime_ == kUndefinedTime); assert(commitEndTime_ == kUndefinedTime); commitStartTime_ = getTime(); + commitNumber_++; } void MountingTelemetry::didCommit() { @@ -26,6 +27,18 @@ void MountingTelemetry::didCommit() { commitEndTime_ = getTime(); } +void MountingTelemetry::willDiff() { + assert(diffStartTime_ == kUndefinedTime); + assert(diffEndTime_ == kUndefinedTime); + diffStartTime_ = getTime(); +} + +void MountingTelemetry::didDiff() { + assert(diffStartTime_ != kUndefinedTime); + assert(diffEndTime_ == kUndefinedTime); + diffEndTime_ = getTime(); +} + void MountingTelemetry::willLayout() { assert(layoutStartTime_ == kUndefinedTime); assert(layoutEndTime_ == kUndefinedTime); @@ -38,16 +51,20 @@ void MountingTelemetry::didLayout() { layoutEndTime_ = getTime(); } -int64_t MountingTelemetry::getCommitTime() const { - assert(commitStartTime_ != kUndefinedTime); - assert(commitEndTime_ != kUndefinedTime); - return commitEndTime_ - commitStartTime_; +int64_t MountingTelemetry::getDiffStartTime() const { + assert(diffStartTime_ != kUndefinedTime); + assert(diffEndTime_ != kUndefinedTime); + return diffStartTime_; } -int64_t MountingTelemetry::getLayoutTime() const { - assert(layoutStartTime_ != kUndefinedTime); - assert(layoutEndTime_ != kUndefinedTime); - return layoutEndTime_ - layoutStartTime_; +int64_t MountingTelemetry::getDiffEndTime() const { + assert(diffStartTime_ != kUndefinedTime); + assert(diffEndTime_ != kUndefinedTime); + return diffEndTime_; +} + +int64_t MountingTelemetry::getCommitNumber() const { + return commitNumber_; } int64_t MountingTelemetry::getCommitStartTime() const { @@ -56,5 +73,23 @@ int64_t MountingTelemetry::getCommitStartTime() const { return commitStartTime_; } +int64_t MountingTelemetry::getCommitEndTime() const { + assert(commitStartTime_ != kUndefinedTime); + assert(commitEndTime_ != kUndefinedTime); + return commitEndTime_; +} + +int64_t MountingTelemetry::getLayoutStartTime() const { + assert(layoutStartTime_ != kUndefinedTime); + assert(layoutEndTime_ != kUndefinedTime); + return layoutStartTime_; +} + +int64_t MountingTelemetry::getLayoutEndTime() const { + assert(layoutStartTime_ != kUndefinedTime); + assert(layoutEndTime_ != kUndefinedTime); + return layoutEndTime_; +} + } // namespace react } // namespace facebook diff --git a/ReactCommon/fabric/mounting/MountingTelemetry.h b/ReactCommon/fabric/mounting/MountingTelemetry.h index 98d90db9d4b..42cffa0e575 100644 --- a/ReactCommon/fabric/mounting/MountingTelemetry.h +++ b/ReactCommon/fabric/mounting/MountingTelemetry.h @@ -22,6 +22,8 @@ class MountingTelemetry final { /* * Signaling */ + void willDiff(); + void didDiff(); void willCommit(); void didCommit(); void willLayout(); @@ -30,13 +32,20 @@ class MountingTelemetry final { /* * Reading */ - int64_t getLayoutTime() const; - int64_t getCommitTime() const; + int64_t getDiffStartTime() const; + int64_t getDiffEndTime() const; + int64_t getLayoutStartTime() const; + int64_t getLayoutEndTime() const; int64_t getCommitStartTime() const; + int64_t getCommitEndTime() const; + int64_t getCommitNumber() const; private: constexpr static int64_t kUndefinedTime = std::numeric_limits::max(); + int64_t diffStartTime_{kUndefinedTime}; + int64_t diffEndTime_{kUndefinedTime}; + int64_t commitNumber_{0}; int64_t commitStartTime_{kUndefinedTime}; int64_t commitEndTime_{kUndefinedTime}; int64_t layoutStartTime_{kUndefinedTime};