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
This commit is contained in:
Joshua Gross
2022-05-19 18:55:56 -07:00
committed by Facebook GitHub Bot
parent 4fc0630faa
commit 0fc42fd35c
2 changed files with 126 additions and 17 deletions
@@ -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<Long> minHeap = new PriorityQueue<>(Comparator.naturalOrder());
private Queue<Long> 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<DevToolsReactPerfLoggerListener> 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) {
@@ -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);