Update LeafProfiler formatting

2024-12-22 16:47:51 +01:00 · 2024-11-27 08:00:41 -08:00 · 2024-11-27 08:00:41 -08:00 · 97805cb5c9
commit 97805cb5c9
parent be8908e2b2
1 changed files with 234 additions and 146 deletions
--- a/patches/server/0017-Region-profiler.patch
+++ b/patches/server/0017-Region-profiler.patch
@ -314,14 +314,16 @@ index 0000000000000000000000000000000000000000..cf81748afe993e486ce27ae65e014807
 +}
 diff --git a/src/main/java/ca/spottedleaf/leafprofiler/LeafProfiler.java b/src/main/java/ca/spottedleaf/leafprofiler/LeafProfiler.java
 new file mode 100644
-index 0000000000000000000000000000000000000000..6c6e759fccce3b669490c09933c01705107d24ac
+index 0000000000000000000000000000000000000000..d1d259fbf6633ea38799b1519bca6deb623704a3
 --- /dev/null
 +++ b/src/main/java/ca/spottedleaf/leafprofiler/LeafProfiler.java
-@@ -0,0 +1,326 @@
+@@ -0,0 +1,413 @@
 +package ca.spottedleaf.leafprofiler;
 +
 +import com.mojang.logging.LogUtils;
 +import it.unimi.dsi.fastutil.ints.IntArrayFIFOQueue;
+import it.unimi.dsi.fastutil.ints.IntArrayList;
+import it.unimi.dsi.fastutil.ints.IntList;
 +import it.unimi.dsi.fastutil.longs.LongArrayFIFOQueue;
 +import it.unimi.dsi.fastutil.objects.Reference2ReferenceOpenHashMap;
 +import org.slf4j.Logger;
@ -330,6 +332,7 @@ index 0000000000000000000000000000000000000000..6c6e759fccce3b669490c09933c01705
 +import java.util.ArrayList;
 +import java.util.Arrays;
 +import java.util.List;
+import java.util.Objects;
 +
 +public final class LeafProfiler {
 +
@ -345,6 +348,9 @@ index 0000000000000000000000000000000000000000..6c6e759fccce3b669490c09933c01705
 +    public final LProfilerRegistry registry;
 +    private final LProfileGraph graph;
 +
+    private long[] accumulatedTimers = new long[0];
+    private long[] accumulatedCounters = new long[0];
+
 +    private long[] timers = new long[16];
 +    private long[] counters = new long[16];
 +    private final IntArrayFIFOQueue callStack = new IntArrayFIFOQueue();
@ -357,6 +363,45 @@ index 0000000000000000000000000000000000000000..6c6e759fccce3b669490c09933c01705
 +        this.graph = graph;
 +    }
 +
+    private static void add(final long[] dst, final long[] src) {
+        final int srcLen = src.length;
+        Objects.checkFromToIndex(0, srcLen, dst.length);
+        for (int i = 0; i < srcLen; ++i) {
+            dst[i] += src[i];
+        }
+    }
+
+    public ProfilingData copyCurrent() {
+        return new ProfilingData(
+                this.registry, this.graph, this.timers.clone(), this.counters.clone()
+        );
+    }
+
+    public ProfilingData copyAccumulated() {
+        return new ProfilingData(
+                this.registry, this.graph, this.accumulatedTimers.clone(), this.accumulatedCounters.clone()
+        );
+    }
+
+    public void accumulate() {
+        if (this.accumulatedTimers.length != this.timers.length) {
+            this.accumulatedTimers = Arrays.copyOf(this.accumulatedTimers, this.timers.length);
+        }
+        add(this.accumulatedTimers, this.timers);
+        Arrays.fill(this.timers, 0L);
+
+        if (this.accumulatedCounters.length != this.counters.length) {
+            this.accumulatedCounters = Arrays.copyOf(this.accumulatedCounters, this.counters.length);
+        }
+        add(this.accumulatedCounters, this.counters);
+        Arrays.fill(this.counters, 0L);
+    }
+
+    public void clearCurrent() {
+        Arrays.fill(this.timers, 0L);
+        Arrays.fill(this.counters, 0L);
+    }
+
 +    private long[] resizeTimers(final long[] old, final int least) {
 +        return this.timers = Arrays.copyOf(old, Math.max(old.length * 2, least * 2));
 +    }
@ -424,147 +469,16 @@ index 0000000000000000000000000000000000000000..6c6e759fccce3b669490c09933c01705
 +        this.incrementCountersDirect(currentNode, 1L);
 +    }
 +
-+    private static final char[][] INDENT_PATTERNS = new char[][] {
-+        "|---".toCharArray(),
-+        "|+++".toCharArray(),
-+    };
+    public void stopLastTimer(final long endTime) {
+        final long lastStart = this.lastTimerStart;
+        final int currentNode = this.topOfStack;
+        final IntArrayFIFOQueue callStack = this.callStack;
+        final LongArrayFIFOQueue timerStack = this.timerStack;
+        this.lastTimerStart = timerStack.dequeueLastLong();
+        this.topOfStack = callStack.dequeueLastInt();
 +
-+    public List<String> dumpToString() {
-+        final List<LProfileGraph.GraphNode> graphDFS = this.graph.getDFS();
-+        final Reference2ReferenceOpenHashMap<LProfileGraph.GraphNode, ProfileNode> nodeMap = new Reference2ReferenceOpenHashMap<>();
-+
-+        final ArrayDeque<ProfileNode> orderedNodes = new ArrayDeque<>();
-+
-+        for (int i = 0, len = graphDFS.size(); i < len; ++i) {
-+            final LProfileGraph.GraphNode graphNode = graphDFS.get(i);
-+            final ProfileNode parent = nodeMap.get(graphNode.parent());
-+            final int nodeId = graphNode.nodeId();
-+
-+            final long totalTime = nodeId >= this.timers.length ? 0L : this.timers[nodeId];
-+            final long totalCount = nodeId >= this.counters.length ? 0L : this.counters[nodeId];
-+            final LProfilerRegistry.ProfilerEntry profiler = this.registry.getById(graphNode.timerId());
-+
-+            final ProfileNode profileNode = new ProfileNode(parent, nodeId, profiler, totalTime, totalCount);
-+
-+            if (parent != null) {
-+                parent.childrenTimingCount += totalTime;
-+                parent.children.add(profileNode);
-+            } else if (i != 0) { // i == 0 is root
-+                throw new IllegalStateException("Node " + nodeId + " must have parent");
-+            } else {
-+                // set up
-+                orderedNodes.add(profileNode);
-+            }
-+
-+            nodeMap.put(graphNode, profileNode);
-+        }
-+
-+        final List<String> ret = new ArrayList<>();
-+
-+        long totalTime = 0L;
-+
-+        // totalTime = sum of times for root node's children
-+        for (final ProfileNode node : orderedNodes.peekFirst().children) {
-+            totalTime += node.totalTime;
-+        }
-+
-+        ProfileNode profileNode;
-+        final StringBuilder builder = new StringBuilder();
-+        while ((profileNode = orderedNodes.pollFirst()) != null) {
-+            if (profileNode.nodeId != LProfileGraph.ROOT_NODE && profileNode.totalCount == 0L) {
-+                // skip nodes not recorded
-+                continue;
-+            }
-+
-+            final int depth = profileNode.depth;
-+            profileNode.children.sort((final ProfileNode p1, final ProfileNode p2) -> {
-+                final int typeCompare = p1.profiler.type().compareTo(p2.profiler.type());
-+                if (typeCompare != 0) {
-+                    // first count, then profiler
-+                    return typeCompare;
-+                }
-+
-+                if (p1.profiler.type() == LProfilerRegistry.ProfileType.COUNTER) {
-+                    // highest count first
-+                    return Long.compare(p2.totalCount, p1.totalCount);
-+                } else {
-+                    // highest time first
-+                    return Long.compare(p2.totalTime, p1.totalTime);
-+                }
-+            });
-+
-+            for (int i = profileNode.children.size() - 1; i >= 0; --i) {
-+                final ProfileNode child = profileNode.children.get(i);
-+                child.depth = depth + 1;
-+                orderedNodes.addFirst(child);
-+            }
-+
-+            if (profileNode.nodeId == LProfileGraph.ROOT_NODE) {
-+                // don't display root
-+                continue;
-+            }
-+
-+            final boolean noParent = profileNode.parent == null || profileNode.parent.nodeId == LProfileGraph.ROOT_NODE;
-+
-+            final long parentTime = noParent ? totalTime : profileNode.parent.totalTime;
-+            final LProfilerRegistry.ProfilerEntry profilerEntry = profileNode.profiler;
-+
-+            // format:
-+            // For profiler type:
-+            // <indent><name> X% total, Y% parent, self A% total, self B% children, avg X sum Y, Dms raw sum
-+            // For counter type:
-+            // <indent>#<name> avg X sum Y
-+            builder.setLength(0);
-+            // prepare indent
-+            final char[] indent = INDENT_PATTERNS[ret.size() % INDENT_PATTERNS.length];
-+            for (int i = 0; i < depth; ++i) {
-+                builder.append(indent);
-+            }
-+
-+            switch (profilerEntry.type()) {
-+                case TIMER: {
-+                    ret.add(
-+                        builder
-+                            .append(profilerEntry.name())
-+                            .append(' ')
-+                            .append(THREE_DECIMAL_PLACES.get().format(((double)profileNode.totalTime / (double)totalTime) * 100.0))
-+                            .append("% total, ")
-+                            .append(THREE_DECIMAL_PLACES.get().format(((double)profileNode.totalTime / (double)parentTime) * 100.0))
-+                            .append("% parent, self ")
-+                            .append(THREE_DECIMAL_PLACES.get().format(((double)(profileNode.totalTime - profileNode.childrenTimingCount) / (double)totalTime) * 100.0))
-+                            .append("% total, self ")
-+                            .append(THREE_DECIMAL_PLACES.get().format(((double)(profileNode.totalTime - profileNode.childrenTimingCount) / (double)profileNode.totalTime) * 100.0))
-+                            .append("% children, avg ")
-+                            .append(THREE_DECIMAL_PLACES.get().format((double)profileNode.totalCount / (double)(noParent ? 1L : profileNode.parent.totalCount)))
-+                            .append(" sum ")
-+                            .append(NO_DECIMAL_PLACES.get().format(profileNode.totalCount))
-+                            .append(", ")
-+                            .append(THREE_DECIMAL_PLACES.get().format((double)profileNode.totalTime / 1.0E6))
-+                            .append("ms raw sum")
-+                            .toString()
-+                    );
-+                    break;
-+                }
-+                case COUNTER: {
-+                    ret.add(
-+                        builder
-+                            .append('#')
-+                            .append(profilerEntry.name())
-+                            .append(" avg ")
-+                            .append(THREE_DECIMAL_PLACES.get().format((double)profileNode.totalCount / (double)(noParent ? 1L : profileNode.parent.totalCount)))
-+                            .append(" sum ")
-+                            .append(NO_DECIMAL_PLACES.get().format(profileNode.totalCount))
-+                            .toString()
-+                    );
-+                    break;
-+                }
-+                default: {
-+                    throw new IllegalStateException("Unknown type " + profilerEntry.type());
-+                }
-+            }
-+        }
-+
-+        return ret;
+        this.incrementTimersDirect(currentNode, endTime - lastStart);
+        this.incrementCountersDirect(currentNode, 1L);
 +    }
 +
 +    private static final class ProfileNode {
@ -577,6 +491,7 @@ index 0000000000000000000000000000000000000000..6c6e759fccce3b669490c09933c01705
 +        public final List<ProfileNode> children = new ArrayList<>();
 +        public long childrenTimingCount;
 +        public int depth = -1;
+        public boolean lastChild;
 +
 +        private ProfileNode(final ProfileNode parent, final int nodeId, final LProfilerRegistry.ProfilerEntry profiler,
 +                            final long totalTime, final long totalCount) {
@ -588,6 +503,178 @@ index 0000000000000000000000000000000000000000..6c6e759fccce3b669490c09933c01705
 +        }
 +    }
 +
+
+
+    public static final record ProfilingData(
+            LProfilerRegistry registry,
+            LProfileGraph graph,
+            long[] timers,
+            long[] counters
+    ) {
+        public List<String> dumpToString() {
+            final List<LProfileGraph.GraphNode> graphDFS = this.graph.getDFS();
+            final Reference2ReferenceOpenHashMap<LProfileGraph.GraphNode, ProfileNode> nodeMap = new Reference2ReferenceOpenHashMap<>();
+
+            final ArrayDeque<ProfileNode> orderedNodes = new ArrayDeque<>();
+
+            for (int i = 0, len = graphDFS.size(); i < len; ++i) {
+                final LProfileGraph.GraphNode graphNode = graphDFS.get(i);
+                final ProfileNode parent = nodeMap.get(graphNode.parent());
+                final int nodeId = graphNode.nodeId();
+
+                final long totalTime = nodeId >= this.timers.length ? 0L : this.timers[nodeId];
+                final long totalCount = nodeId >= this.counters.length ? 0L : this.counters[nodeId];
+                final LProfilerRegistry.ProfilerEntry profiler = this.registry.getById(graphNode.timerId());
+
+                final ProfileNode profileNode = new ProfileNode(parent, nodeId, profiler, totalTime, totalCount);
+
+                if (parent != null) {
+                    parent.childrenTimingCount += totalTime;
+                    parent.children.add(profileNode);
+                } else if (i != 0) { // i == 0 is root
+                    throw new IllegalStateException("Node " + nodeId + " must have parent");
+                } else {
+                    // set up
+                    orderedNodes.add(profileNode);
+                }
+
+                nodeMap.put(graphNode, profileNode);
+            }
+
+            final List<String> ret = new ArrayList<>();
+
+            long totalTime = 0L;
+
+            // totalTime = sum of times for root node's children
+            for (final ProfileNode node : orderedNodes.peekFirst().children) {
+                totalTime += node.totalTime;
+            }
+
+            final ArrayDeque<ProfileNode> flatOrderedNodes = new ArrayDeque<>();
+
+            ProfileNode profileNode;
+            while ((profileNode = orderedNodes.pollFirst()) != null) {
+                final int depth = profileNode.depth;
+                profileNode.children.sort((final ProfileNode p1, final ProfileNode p2) -> {
+                    final int typeCompare = p1.profiler.type().compareTo(p2.profiler.type());
+                    if (typeCompare != 0) {
+                        // first count, then profiler
+                        return typeCompare;
+                    }
+
+                    if (p1.profiler.type() == LProfilerRegistry.ProfileType.COUNTER) {
+                        // highest count first
+                        return Long.compare(p2.totalCount, p1.totalCount);
+                    } else {
+                        // highest time first
+                        return Long.compare(p2.totalTime, p1.totalTime);
+                    }
+                });
+
+                boolean first = true;
+                for (int i = profileNode.children.size() - 1; i >= 0; --i) {
+                    final ProfileNode child = profileNode.children.get(i);
+                    if (child.totalCount == 0L) {
+                        // skip nodes not recorded
+                        continue;
+                    }
+                    if (first) {
+                        child.lastChild = true;
+                        first = false;
+                    }
+                    child.depth = depth + 1;
+                    orderedNodes.addFirst(child);
+                }
+
+                flatOrderedNodes.addLast(profileNode);
+            }
+
+            final StringBuilder builder = new StringBuilder();
+            final IntList closed = new IntArrayList();
+            while ((profileNode = flatOrderedNodes.pollFirst()) != null) {
+                final int depth = profileNode.depth;
+                closed.removeIf((int d) -> d >= depth);
+                if (profileNode.lastChild) {
+                    closed.add(depth);
+                }
+                if (profileNode.nodeId == LProfileGraph.ROOT_NODE) {
+                    // don't display root
+                    continue;
+                }
+
+                final boolean noParent = profileNode.parent == null || profileNode.parent.nodeId == LProfileGraph.ROOT_NODE;
+
+                final long parentTime = noParent ? totalTime : profileNode.parent.totalTime;
+                final LProfilerRegistry.ProfilerEntry profilerEntry = profileNode.profiler;
+
+                // format:
+                // For profiler type:
+                // <indent><name> X% total, Y% parent, self A% total, self B% children, avg X sum Y, Dms raw sum
+                // For counter type:
+                // <indent>#<name> avg X sum Y
+                builder.setLength(0);
+                // prepare indent
+                for (int i = 0; i < depth; ++i) {
+                    if (i == depth - 1) {
+                        if (flatOrderedNodes.peekFirst() == null || profileNode.lastChild) {
+                            builder.append("  └─");
+                        } else {
+                            builder.append("  ├─");
+                        }
+                    } else if (!closed.contains(i + 1)) {
+                        builder.append("  │ ");
+                    } else {
+                        builder.append("    ");
+                    }
+                }
+
+                switch (profilerEntry.type()) {
+                    case TIMER: {
+                        ret.add(
+                                builder
+                                        .append(profilerEntry.name())
+                                        .append(' ')
+                                        .append(THREE_DECIMAL_PLACES.get().format(((double)profileNode.totalTime / (double)totalTime) * 100.0))
+                                        .append("% total, ")
+                                        .append(THREE_DECIMAL_PLACES.get().format(((double)profileNode.totalTime / (double)parentTime) * 100.0))
+                                        .append("% parent, self ")
+                                        .append(THREE_DECIMAL_PLACES.get().format(((double)(profileNode.totalTime - profileNode.childrenTimingCount) / (double)totalTime) * 100.0))
+                                        .append("% total, self ")
+                                        .append(THREE_DECIMAL_PLACES.get().format(((double)(profileNode.totalTime - profileNode.childrenTimingCount) / (double)profileNode.totalTime) * 100.0))
+                                        .append("% children, avg ")
+                                        .append(THREE_DECIMAL_PLACES.get().format((double)profileNode.totalCount / (double)(noParent ? 1L : profileNode.parent.totalCount)))
+                                        .append(" sum ")
+                                        .append(NO_DECIMAL_PLACES.get().format(profileNode.totalCount))
+                                        .append(", ")
+                                        .append(THREE_DECIMAL_PLACES.get().format((double)profileNode.totalTime / 1.0E6))
+                                        .append("ms raw sum")
+                                        .toString()
+                        );
+                        break;
+                    }
+                    case COUNTER: {
+                        ret.add(
+                                builder
+                                        .append('#')
+                                        .append(profilerEntry.name())
+                                        .append(" avg ")
+                                        .append(THREE_DECIMAL_PLACES.get().format((double)profileNode.totalCount / (double)(noParent ? 1L : profileNode.parent.totalCount)))
+                                        .append(" sum ")
+                                        .append(NO_DECIMAL_PLACES.get().format(profileNode.totalCount))
+                                        .toString()
+                        );
+                        break;
+                    }
+                    default: {
+                        throw new IllegalStateException("Unknown type " + profilerEntry.type());
+                    }
+                }
+            }
+
+            return ret;
+        }
+    }
+
 +    /*
 +    public static void main(final String[] args) throws Throwable {
 +        final Thread timerHack = new Thread("Timer hack thread") {
@ -646,10 +733,10 @@ index 0000000000000000000000000000000000000000..6c6e759fccce3b669490c09933c01705
 +}
 diff --git a/src/main/java/ca/spottedleaf/leafprofiler/RegionizedProfiler.java b/src/main/java/ca/spottedleaf/leafprofiler/RegionizedProfiler.java
 new file mode 100644
-index 0000000000000000000000000000000000000000..95c0e6416afafbb633f0a30ae22df166055a0cbc
+index 0000000000000000000000000000000000000000..6e9b04613c5c867a74fa4f266a8ae8e60416cb6d
 --- /dev/null
 +++ b/src/main/java/ca/spottedleaf/leafprofiler/RegionizedProfiler.java
-@@ -0,0 +1,276 @@
+@@ -0,0 +1,277 @@
 +package ca.spottedleaf.leafprofiler;
 +
 +import ca.spottedleaf.concurrentutil.collection.MultiThreadedQueue;
@ -797,6 +884,7 @@ index 0000000000000000000000000000000000000000..95c0e6416afafbb633f0a30ae22df166
 +
 +
 +            this.profiler.stopTimer(LProfilerRegistry.TICK, System.nanoTime());
+            this.profiler.accumulate();
 +        }
 +
 +        public void startInBetweenTick() {
@ -1110,7 +1198,7 @@ index df15b1139e71dfe10b8f24ec6d235b99f6d5006a..b1c07e582dbf0a203cf734fdbcd8387a
         @Override
 diff --git a/src/main/java/io/papermc/paper/threadedregions/commands/CommandProfiler.java b/src/main/java/io/papermc/paper/threadedregions/commands/CommandProfiler.java
 new file mode 100644
-index 0000000000000000000000000000000000000000..e36fd244f71a92d11c6ee45944948be5c1be2932
+index 0000000000000000000000000000000000000000..3c6f0359bd6196eeb497bc2a43a82186b545df4e
 --- /dev/null
 +++ b/src/main/java/io/papermc/paper/threadedregions/commands/CommandProfiler.java
@@ -0,0 +1,245 @@
@ -1326,7 +1414,7 @@ index 0000000000000000000000000000000000000000..e36fd244f71a92d11c6ee45944948be5
 +            out.add("Max MSPT: " + THREE_DECIMAL_PLACES.get().format(tickReport == null ? 0.0 : 1.0E-6 *tickReport.timePerTickData().segmentAll().greatest()));
 +            out.add("");
 +
-+            out.addAll(regionTimings.profiler().dumpToString());
+            out.addAll(regionTimings.profiler().copyAccumulated().dumpToString());
 +            writeLines(regionProfile, out);
 +        }
 +