From 97805cb5c92aaf00e9b14010a0d7ad38001cea15 Mon Sep 17 00:00:00 2001 From: Spottedleaf Date: Wed, 27 Nov 2024 08:00:41 -0800 Subject: [PATCH] Update LeafProfiler formatting --- patches/server/0017-Region-profiler.patch | 370 +++++++++++++--------- 1 file changed, 229 insertions(+), 141 deletions(-) diff --git a/patches/server/0017-Region-profiler.patch b/patches/server/0017-Region-profiler.patch index 2adeb9d3c..8291380cf 100644 --- 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,167 +469,209 @@ 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 dumpToString() { -+ final List graphDFS = this.graph.getDFS(); -+ final Reference2ReferenceOpenHashMap nodeMap = new Reference2ReferenceOpenHashMap<>(); ++ this.incrementTimersDirect(currentNode, endTime - lastStart); ++ this.incrementCountersDirect(currentNode, 1L); ++ } + -+ final ArrayDeque orderedNodes = new ArrayDeque<>(); ++ private static final class ProfileNode { + -+ 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(); ++ public final ProfileNode parent; ++ public final int nodeId; ++ public final LProfilerRegistry.ProfilerEntry profiler; ++ public final long totalTime; ++ public final long totalCount; ++ public final List children = new ArrayList<>(); ++ public long childrenTimingCount; ++ public int depth = -1; ++ public boolean lastChild; + -+ 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()); ++ private ProfileNode(final ProfileNode parent, final int nodeId, final LProfilerRegistry.ProfilerEntry profiler, ++ final long totalTime, final long totalCount) { ++ this.parent = parent; ++ this.nodeId = nodeId; ++ this.profiler = profiler; ++ this.totalTime = totalTime; ++ this.totalCount = totalCount; ++ } ++ } + -+ 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); -+ } ++ public static final record ProfilingData( ++ LProfilerRegistry registry, ++ LProfileGraph graph, ++ long[] timers, ++ long[] counters ++ ) { ++ public List dumpToString() { ++ final List graphDFS = this.graph.getDFS(); ++ final Reference2ReferenceOpenHashMap nodeMap = new Reference2ReferenceOpenHashMap<>(); + -+ final List ret = new ArrayList<>(); ++ final ArrayDeque orderedNodes = new ArrayDeque<>(); + -+ long totalTime = 0L; ++ 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(); + -+ // totalTime = sum of times for root node's children -+ for (final ProfileNode node : orderedNodes.peekFirst().children) { -+ totalTime += node.totalTime; -+ } ++ 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()); + -+ 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 ProfileNode profileNode = new ProfileNode(parent, nodeId, profiler, totalTime, totalCount); + -+ 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); ++ 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 { -+ // highest time first -+ return Long.compare(p2.totalTime, p1.totalTime); ++ // set up ++ orderedNodes.add(profileNode); + } -+ }); + -+ for (int i = profileNode.children.size() - 1; i >= 0; --i) { -+ final ProfileNode child = profileNode.children.get(i); -+ child.depth = depth + 1; -+ orderedNodes.addFirst(child); ++ nodeMap.put(graphNode, profileNode); + } + -+ if (profileNode.nodeId == LProfileGraph.ROOT_NODE) { -+ // don't display root -+ continue; -+ } ++ final List ret = new ArrayList<>(); + -+ 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: -+ // X% total, Y% parent, self A% total, self B% children, avg X sum Y, Dms raw sum -+ // For counter type: -+ // # 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); ++ long totalTime = 0L; ++ ++ // totalTime = sum of times for root node's children ++ for (final ProfileNode node : orderedNodes.peekFirst().children) { ++ totalTime += node.totalTime; + } + -+ 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()); ++ final ArrayDeque 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); + } -+ } + -+ return ret; -+ } ++ 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; ++ } + -+ private static final class ProfileNode { ++ 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: ++ // X% total, Y% parent, self A% total, self B% children, avg X sum Y, Dms raw sum ++ // For counter type: ++ // # 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(" "); ++ } ++ } + -+ public final ProfileNode parent; -+ public final int nodeId; -+ public final LProfilerRegistry.ProfilerEntry profiler; -+ public final long totalTime; -+ public final long totalCount; -+ public final List children = new ArrayList<>(); -+ public long childrenTimingCount; -+ public int depth = -1; ++ 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()); ++ } ++ } ++ } + -+ private ProfileNode(final ProfileNode parent, final int nodeId, final LProfilerRegistry.ProfilerEntry profiler, -+ final long totalTime, final long totalCount) { -+ this.parent = parent; -+ this.nodeId = nodeId; -+ this.profiler = profiler; -+ this.totalTime = totalTime; -+ this.totalCount = totalCount; ++ return ret; + } + } + @@ -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); + } +