From 0fc42fd35c577c71825f020b0fa09bee6d9ad105 Mon Sep 17 00:00:00 2001 From: Joshua Gross Date: Thu, 19 May 2022 18:55:56 -0700 Subject: [PATCH] Add detail to Fabric perf logs (median, average, max) Summary: I'm finding it useful to keep track of a few additional numbers when doing perf analysis in Fabric. Also making it easier to enable just these perf logs without all of the other verbose Fabric logs. Changelog: [Internal] Reviewed By: mdvacca Differential Revision: D36500518 fbshipit-source-id: e57e1e75131c5d59da876d1decb96d4da386f025 --- .../react/fabric/DevToolsReactPerfLogger.java | 85 +++++++++++++++++++ .../react/fabric/FabricUIManager.java | 58 +++++++++---- 2 files changed, 126 insertions(+), 17 deletions(-) diff --git a/ReactAndroid/src/main/java/com/facebook/react/fabric/DevToolsReactPerfLogger.java b/ReactAndroid/src/main/java/com/facebook/react/fabric/DevToolsReactPerfLogger.java index 1745f094c78..e6a3bf2fe0f 100644 --- a/ReactAndroid/src/main/java/com/facebook/react/fabric/DevToolsReactPerfLogger.java +++ b/ReactAndroid/src/main/java/com/facebook/react/fabric/DevToolsReactPerfLogger.java @@ -13,9 +13,67 @@ import androidx.annotation.Nullable; import com.facebook.react.bridge.ReactMarker; import com.facebook.react.bridge.ReactMarkerConstants; import java.util.ArrayList; +import java.util.Comparator; import java.util.HashMap; import java.util.List; import java.util.Map; +import java.util.PriorityQueue; +import java.util.Queue; + +class LongStreamingStats { + private Queue minHeap = new PriorityQueue<>(Comparator.naturalOrder()); + private Queue maxHeap = new PriorityQueue<>(Comparator.reverseOrder()); + private double streamingAverage = 0.0; + private int len = 0; + private long max = 0; + + LongStreamingStats() {} + + public void add(long n) { + // To make medians more useful, we discard all zero values + // This isn't perfect and certainly makes this a totally invalid median, but, alas... + if (n != 0) { + if (minHeap.size() == maxHeap.size()) { + maxHeap.offer(n); + minHeap.offer(maxHeap.poll()); + } else { + minHeap.offer(n); + maxHeap.offer(minHeap.poll()); + } + } + + len++; + if (len == 1) { + streamingAverage = n; + } else { + streamingAverage = (streamingAverage / (len / (len - 1))) + (n / len); + } + + max = (n > max ? n : max); + } + + public double getMedian() { + if (minHeap.size() == 0 && maxHeap.size() == 0) { + return 0; + } + + long median; + if (minHeap.size() > maxHeap.size()) { + median = minHeap.peek(); + } else { + median = (minHeap.peek() + maxHeap.peek()) / 2; + } + return median; + } + + public double getAverage() { + return streamingAverage; + } + + public long getMax() { + return max; + } +} public class DevToolsReactPerfLogger implements ReactMarker.FabricMarkerListener { @@ -23,6 +81,12 @@ public class DevToolsReactPerfLogger implements ReactMarker.FabricMarkerListener private final List mDevToolsReactPerfLoggerListeners = new ArrayList<>(); + public static final LongStreamingStats mStreamingCommitStats = new LongStreamingStats(); + public static final LongStreamingStats mStreamingLayoutStats = new LongStreamingStats(); + public static final LongStreamingStats mStreamingDiffStats = new LongStreamingStats(); + public static final LongStreamingStats mStreamingTransactionEndStats = new LongStreamingStats(); + public static final LongStreamingStats mStreamingBatchExecutionStats = new LongStreamingStats(); + public interface DevToolsReactPerfLoggerListener { void onFabricCommitEnd(FabricCommitPoint commitPoint); @@ -96,6 +160,27 @@ public class DevToolsReactPerfLogger implements ReactMarker.FabricMarkerListener public long getUpdateUIMainThreadEnd() { return getValue(FABRIC_UPDATE_UI_MAIN_THREAD_END); } + + // Duration calcuations + public long getCommitDuration() { + return getCommitEnd() - getCommitStart(); + } + + public long getLayoutDuration() { + return getLayoutEnd() - getLayoutStart(); + } + + public long getDiffDuration() { + return getDiffEnd() - getDiffStart(); + } + + public long getTransactionEndDuration() { + return getFinishTransactionEnd() - getFinishTransactionStart(); + } + + public long getBatchExecutionDuration() { + return getBatchExecutionEnd() - getBatchExecutionStart(); + } } public void addDevToolsReactPerfLoggerListener(DevToolsReactPerfLoggerListener listener) { 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 75d9791e823..57d669b395c 100644 --- a/ReactAndroid/src/main/java/com/facebook/react/fabric/FabricUIManager.java +++ b/ReactAndroid/src/main/java/com/facebook/react/fabric/FabricUIManager.java @@ -106,6 +106,7 @@ public class FabricUIManager implements UIManager, LifecycleEventListener { ReactFeatureFlags.enableFabricLogs || PrinterHolder.getPrinter() .shouldDisplayLogMessage(ReactDebugOverlayTags.FABRIC_UI_MANAGER); + public static final boolean ENABLE_FABRIC_PERF_LOGS = ENABLE_FABRIC_LOGS || false; public DevToolsReactPerfLogger mDevToolsReactPerfLogger; static { @@ -366,30 +367,53 @@ public class FabricUIManager implements UIManager, LifecycleEventListener { public void initialize() { mEventDispatcher.registerEventEmitter(FABRIC, new FabricEventEmitter(this)); mEventDispatcher.addBatchEventDispatchedListener(mEventBeatManager); - if (ENABLE_FABRIC_LOGS) { + if (ENABLE_FABRIC_PERF_LOGS) { mDevToolsReactPerfLogger = new DevToolsReactPerfLogger(); mDevToolsReactPerfLogger.addDevToolsReactPerfLoggerListener( new DevToolsReactPerfLogger.DevToolsReactPerfLoggerListener() { @Override public void onFabricCommitEnd(DevToolsReactPerfLogger.FabricCommitPoint commitPoint) { + long commitDuration = commitPoint.getCommitDuration(); + long layoutDuration = commitPoint.getLayoutDuration(); + long diffDuration = commitPoint.getDiffDuration(); + long transactionEndDuration = commitPoint.getTransactionEndDuration(); + long batchExecutionDuration = commitPoint.getBatchExecutionDuration(); + + DevToolsReactPerfLogger.mStreamingCommitStats.add(commitDuration); + DevToolsReactPerfLogger.mStreamingLayoutStats.add(layoutDuration); + DevToolsReactPerfLogger.mStreamingDiffStats.add(diffDuration); + DevToolsReactPerfLogger.mStreamingTransactionEndStats.add(transactionEndDuration); + DevToolsReactPerfLogger.mStreamingBatchExecutionStats.add(batchExecutionDuration); + FLog.i( TAG, - "Statistic of Fabric commit #: " - + commitPoint.getCommitNumber() - + "\n - Total commit time: " - + (commitPoint.getFinishTransactionEnd() - commitPoint.getCommitStart()) - + " ms.\n - Layout: " - + (commitPoint.getLayoutEnd() - commitPoint.getLayoutStart()) - + " ms.\n - Diffing: " - + (commitPoint.getDiffEnd() - commitPoint.getDiffStart()) - + " ms.\n" - + " - FinishTransaction (Diffing + JNI serialization): " - + (commitPoint.getFinishTransactionEnd() - - commitPoint.getFinishTransactionStart()) - + " ms.\n" - + " - Mounting: " - + (commitPoint.getBatchExecutionEnd() - commitPoint.getBatchExecutionStart()) - + " ms."); + "Statistics of Fabric commit #%d:\n" + + " - Total commit time: %d ms. Avg: %.2f. Median: %.2f ms. Max: %d ms.\n" + + " - Layout time: %d ms. Avg: %.2f. Median: %.2f ms. Max: %d ms.\n" + + " - Diffing time: %d ms. Avg: %.2f. Median: %.2f ms. Max: %d ms.\n" + + " - FinishTransaction (Diffing + JNI serialization): %d ms. Avg: %.2f. Median: %.2f ms. Max: %d ms.\n" + + " - Mounting: %d ms. Avg: %.2f. Median: %.2f ms. Max: %d ms.\n", + commitPoint.getCommitNumber(), + commitDuration, + DevToolsReactPerfLogger.mStreamingCommitStats.getAverage(), + DevToolsReactPerfLogger.mStreamingCommitStats.getMedian(), + DevToolsReactPerfLogger.mStreamingCommitStats.getMax(), + layoutDuration, + DevToolsReactPerfLogger.mStreamingLayoutStats.getAverage(), + DevToolsReactPerfLogger.mStreamingLayoutStats.getMedian(), + DevToolsReactPerfLogger.mStreamingLayoutStats.getMax(), + diffDuration, + DevToolsReactPerfLogger.mStreamingDiffStats.getAverage(), + DevToolsReactPerfLogger.mStreamingDiffStats.getMedian(), + DevToolsReactPerfLogger.mStreamingDiffStats.getMax(), + transactionEndDuration, + DevToolsReactPerfLogger.mStreamingTransactionEndStats.getAverage(), + DevToolsReactPerfLogger.mStreamingTransactionEndStats.getMedian(), + DevToolsReactPerfLogger.mStreamingTransactionEndStats.getMax(), + batchExecutionDuration, + DevToolsReactPerfLogger.mStreamingBatchExecutionStats.getAverage(), + DevToolsReactPerfLogger.mStreamingBatchExecutionStats.getMedian(), + DevToolsReactPerfLogger.mStreamingBatchExecutionStats.getMax()); } }); ReactMarker.addFabricListener(mDevToolsReactPerfLogger);