fix(perf): refine idle and gc attribution

This commit is contained in:
MoePus committed 2026-08-18 14:20:53 +09:00
1 parent ed41c6134b
commit a31f8c486f
15 files changed
+165 -38

No files matched your search

@@ -201,7 +201,8 @@ public final class PerfReportScreen extends Screen {
String.format(Locale.ROOT, "%.2f", report.serverMspt()),
String.format(Locale.ROOT, "%.1f", report.elapsedMillis() / 1000.0),
String.format(Locale.ROOT, "%,d", report.tickCount()), report.intervalMicros(),
String.format(Locale.ROOT, "%,d", omittedForTab()), report.lastTickGcMillis());
String.format(Locale.ROOT, "%,d", omittedForTab()),
String.format(Locale.ROOT, "%.2f", report.recentGcMspt()), report.recentGcMaxMillis());
int y = geometry.panelY() + TITLE_HEIGHT + CONTROLS_HEIGHT + 3;
graphics.drawString(font, fit(font, text, geometry.contentWidth()), geometry.contentX(), y, MUTED, true);
}
@@ -10,7 +10,8 @@ import java.util.Objects;
public record PerfReportData(long reportId,
double serverMspt,
long lastTickGcMillis,
double recentGcMspt,
long recentGcMaxMillis,
long elapsedMillis,
long generatedAtEpochMillis,
long tickCount,
@@ -28,8 +29,11 @@ public record PerfReportData(long reportId,
if (reportId < 0L) {
throw new IllegalArgumentException("Report ID must be non-negative");
}
if (lastTickGcMillis < 0L) {
throw new IllegalArgumentException("Last tick GC time must be non-negative");
if (!Double.isFinite(recentGcMspt) || recentGcMspt < 0.0D) {
throw new IllegalArgumentException("Recent GC MSPT must be finite and non-negative");
}
if (recentGcMaxMillis < 0L) {
throw new IllegalArgumentException("Recent maximum GC time must be non-negative");
}
if (omittedChunks < 0 || omittedTickables < 0
|| omittedOwnerSources < 0 || omittedLoaderSources < 0) {
@@ -55,7 +59,7 @@ public record PerfReportData(long reportId,
List<TickableEntry> tickables,
List<OwnerEntry> owners,
List<LoaderSourceEntry> loaderSources) {
this(0L, serverMspt, 0L, elapsedMillis, generatedAtEpochMillis, tickCount, totalSamples,
this(0L, serverMspt, 0.0D, 0L, elapsedMillis, generatedAtEpochMillis, tickCount, totalSamples,
intervalMicros, omittedChunks, omittedTickables, omittedOwnerSources,
omittedLoaderSources, chunks, tickables, owners, loaderSources);
}
@@ -75,7 +79,7 @@ public record PerfReportData(long reportId,
List<TickableEntry> tickables,
List<OwnerEntry> owners,
List<LoaderSourceEntry> loaderSources) {
this(reportId, serverMspt, 0L, elapsedMillis, generatedAtEpochMillis, tickCount, totalSamples,
this(reportId, serverMspt, 0.0D, 0L, elapsedMillis, generatedAtEpochMillis, tickCount, totalSamples,
intervalMicros, omittedChunks, omittedTickables, omittedOwnerSources,
omittedLoaderSources, chunks, tickables, owners, loaderSources);
}
@@ -92,19 +96,19 @@ public record PerfReportData(long reportId,
List<ChunkEntry> chunks,
List<TickableEntry> tickables,
List<OwnerEntry> owners) {
this(0L, serverMspt, 0L, elapsedMillis, generatedAtEpochMillis, tickCount, totalSamples, intervalMicros,
this(0L, serverMspt, 0.0D, 0L, elapsedMillis, generatedAtEpochMillis, tickCount, totalSamples, intervalMicros,
omittedChunks, omittedTickables, omittedOwnerSources, 0,
chunks, tickables, owners, List.of());
}
public static PerfReportData empty(int intervalMicros) {
return new PerfReportData(0L, 0.0D, 0L, 0L, 0L, 0L, 0L, intervalMicros,
return new PerfReportData(0L, 0.0D, 0.0D, 0L, 0L, 0L, 0L, 0L, intervalMicros,
0, 0, 0, 0, List.of(), List.of(), List.of(), List.of());
}
public PerfReportData withLoaderSources(List<LoaderSourceEntry> nextLoaderSources) {
return loaderSources.equals(nextLoaderSources) ? this : new PerfReportData(
reportId, serverMspt, lastTickGcMillis, elapsedMillis, generatedAtEpochMillis,
reportId, serverMspt, recentGcMspt, recentGcMaxMillis, elapsedMillis, generatedAtEpochMillis,
tickCount, totalSamples,
intervalMicros, omittedChunks, omittedTickables, omittedOwnerSources,
omittedLoaderSources, chunks, tickables, owners, nextLoaderSources);
@@ -7,6 +7,7 @@ import it.unimi.dsi.fastutil.ints.IntOpenHashSet;
import net.minecraft.resources.ResourceLocation;
import net.minecraft.world.level.ChunkPos;
import java.util.ArrayDeque;
import java.util.ArrayList;
import java.util.Comparator;
import java.util.HashMap;
@@ -16,6 +17,7 @@ import java.util.SplittableRandom;
import java.util.function.ToDoubleFunction;
final class PerfSampleAggregator {
private static final long GC_WINDOW_NANOS = 1_000_000_000L;
private static final int CHUNK_VIEW_LIMIT_PER_METRIC = 256;
private static final int TICKABLE_VIEW_LIMIT_PER_METRIC = 256;
private static final int MAX_COORDINATES_PER_GROUP = 16;
@@ -28,13 +30,14 @@ final class PerfSampleAggregator {
private final Map<TickSamples.TickableKey, TickableAggregate> tickables = new HashMap<>();
private final Map<CoordinateGroup, CoordinateReservoir> coordinateGroups = new HashMap<>();
private final Map<TickSamples.ChunkKey, SampleStatistics> chunks = new HashMap<>();
private final ArrayDeque<GcTick> recentGcTicks = new ArrayDeque<>();
private final IntOpenHashSet droppedTickableHashes = new IntOpenHashSet();
private final IntOpenHashSet droppedChunkHashes = new IntOpenHashSet();
private int tickableDropsUntilReplacement = REPLACEMENT_INTERVAL;
private int chunkDropsUntilReplacement = REPLACEMENT_INTERVAL;
private long tickCount;
private long totalTickNanos;
private long lastTickGcMillis;
private long recentGcTotalMillis;
PerfSampleAggregator(long seed) {
reportId = seed;
@@ -51,7 +54,7 @@ final class PerfSampleAggregator {
void accept(TickSamples tick) {
tickCount++;
totalTickNanos += tick.durationNanos;
lastTickGcMillis = tick.gcTimeMillis;
recordGc(tick);
if (tick.totalSamples == 0) {
ownerAggregator.updateMetadata(tick.attribution);
} else {
@@ -73,8 +76,9 @@ final class PerfSampleAggregator {
sampledTickables.entries(), TICKABLE_VIEW_LIMIT_PER_METRIC,
PerfReportData.TickableEntry::metric);
PerfOwnerAggregator.Build ownerBuild = ownerAggregator.build(tickCount, nanosPerSample);
GcMetric gc = gcMetric();
double serverMspt = tickCount == 0 ? 0.0D : totalTickNanos / 1_000_000.0D / tickCount;
return new PerfReportData(reportId, serverMspt, lastTickGcMillis,
return new PerfReportData(reportId, serverMspt, gc.averageMillis(), gc.maxMillis(),
elapsedNanos / 1_000_000L, System.currentTimeMillis(),
tickCount, totalSamples, intervalMicros,
omitted(limitedChunks.omitted(), droppedChunkHashes),
@@ -83,6 +87,26 @@ final class PerfSampleAggregator {
limitedChunks.entries(), limitedTickables.entries(), ownerBuild.entries(), ownerBuild.loaderSources());
}
private void recordGc(TickSamples tick) {
long cutoff = tick.completedAtNanos - GC_WINDOW_NANOS;
while (!recentGcTicks.isEmpty() && recentGcTicks.getFirst().completedAtNanos() < cutoff) {
recentGcTotalMillis -= recentGcTicks.removeFirst().gcMillis();
}
recentGcTicks.addLast(new GcTick(tick.completedAtNanos, tick.gcTimeMillis));
recentGcTotalMillis += tick.gcTimeMillis;
}
private GcMetric gcMetric() {
if (recentGcTicks.isEmpty()) {
return new GcMetric(0.0D, 0L);
}
long maximum = 0L;
for (GcTick tick : recentGcTicks) {
maximum = Math.max(maximum, tick.gcMillis());
}
return new GcMetric((double) recentGcTotalMillis / recentGcTicks.size(), maximum);
}
private void recordTickables(TickSamples tick) {
for (var entry : tick.tickables.entrySet()) {
TickSamples.TickCount count = entry.getValue();
@@ -300,6 +324,12 @@ final class PerfSampleAggregator {
PerfReportLimits.Limited<PerfReportData.TickableEntry> tickables) {
}
private record GcTick(long completedAtNanos, long gcMillis) {
}
private record GcMetric(double averageMillis, long maxMillis) {
}
private static final class ObjectCounts {
private static final int TOP_LIMIT = 3;
static final ObjectCounts EMPTY = new ObjectCounts();
@@ -24,6 +24,7 @@ public final class PerfSamplerSession {
private final long durationNanos;
private final SplittableRandom intervalRandom;
private final AnalysisClock analysisClock;
private final LongSupplier nanoTime;
private final TickGcTimeTracker gcTimeTracker = new TickGcTimeTracker();
private final Thread samplerThread;
private final WindowsTimerResolution timerResolution = new WindowsTimerResolution();
@@ -50,11 +51,12 @@ public final class PerfSamplerSession {
this.intervalMicros = intervalMicros;
durationNanos = options.durationNanos();
aggregator = new PerfSampleAggregator(sessionId);
analysisClock = new AnalysisClock(options.nanoTime());
nanoTime = options.nanoTime();
analysisClock = new AnalysisClock(nanoTime);
latestReport = options.initialAttribution() == null
? PerfReportData.empty(intervalMicros)
: aggregator.buildLoaderLayoutOnly(options.initialAttribution(), intervalMicros);
intervalRandom = new SplittableRandom(sessionId ^ options.nanoTime().getAsLong());
intervalRandom = new SplittableRandom(sessionId ^ nanoTime.getAsLong());
samplerThread = new Thread(this::runSampler, "ServerWarashi-PerfSampler");
samplerThread.setDaemon(true);
}
@@ -153,6 +155,7 @@ public final class PerfSamplerSession {
}
tick.durationNanos = durationNanos;
tick.gcTimeMillis = gcTimeTracker.elapsedSince(tick.gcStartMillis);
tick.completedAtNanos = nanoTime.getAsLong();
currentTick = null;
closedTicks.add(tick);
}
@@ -99,14 +99,28 @@ final class PerfStackAttributor {
}
private static boolean isNormalTickIdle(StackTraceElement[] stack) {
boolean waiting = false;
boolean betweenTicks = false;
for (StackTraceElement frame : stack) {
waiting |= "waitForTasks".equals(frame.getMethodName());
betweenTicks |= MINECRAFT_SERVER_CLASS.equals(frame.getClassName())
&& "waitUntilNextTick".equals(frame.getMethodName());
int waitIndex = -1;
int tickWaitIndex = -1;
for (int index = 0; index < stack.length; index++) {
StackTraceElement frame = stack[index];
if (waitIndex < 0 && "waitForTasks".equals(frame.getMethodName())) {
waitIndex = index;
}
if (MINECRAFT_SERVER_CLASS.equals(frame.getClassName())
&& "waitUntilNextTick".equals(frame.getMethodName())) {
tickWaitIndex = index;
break;
}
}
return waiting && betweenTicks;
if (waitIndex < 0 || tickWaitIndex <= waitIndex) {
return false;
}
for (int index = waitIndex + 1; index < tickWaitIndex; index++) {
if ("doRunTask".equals(stack[index].getMethodName())) {
return false;
}
}
return true;
}
private static PerfWorkTracker.Snapshot handler(StackTraceElement frame, TickEvent event) {
@@ -13,6 +13,7 @@ final class TickSamples {
final Map<ChunkKey, Integer> chunks = new HashMap<>();
PerfAttributionSnapshot attribution;
long durationNanos;
long completedAtNanos;
long gcStartMillis;
long gcTimeMillis;
int totalSamples;
@@ -21,7 +21,8 @@ public final class PerfReportCodec {
EntryBudget budget = new EntryBudget();
buffer.writeVarLong(report.reportId());
buffer.writeDouble(report.serverMspt());
buffer.writeVarLong(report.lastTickGcMillis());
buffer.writeDouble(report.recentGcMspt());
buffer.writeVarLong(report.recentGcMaxMillis());
buffer.writeVarLong(report.elapsedMillis());
buffer.writeVarLong(report.generatedAtEpochMillis());
buffer.writeVarLong(report.tickCount());
@@ -41,7 +42,8 @@ public final class PerfReportCodec {
EntryBudget budget = new EntryBudget();
long reportId = buffer.readVarLong();
double serverMspt = buffer.readDouble();
long lastTickGcMillis = buffer.readVarLong();
double recentGcMspt = buffer.readDouble();
long recentGcMaxMillis = buffer.readVarLong();
long elapsedMillis = buffer.readVarLong();
long generatedAtEpochMillis = buffer.readVarLong();
long tickCount = buffer.readVarLong();
@@ -55,7 +57,8 @@ public final class PerfReportCodec {
List<PerfReportData.TickableEntry> tickables = readList(buffer, PerfReportCodec::readTickable, budget);
List<PerfReportData.OwnerEntry> owners = readList(buffer, PerfReportCodec::readOwner, budget);
List<PerfReportData.LoaderSourceEntry> loaders = PerfLoaderReportCodec.read(buffer, budget);
return new PerfReportData(reportId, serverMspt, lastTickGcMillis, elapsedMillis, generatedAtEpochMillis,
return new PerfReportData(reportId, serverMspt, recentGcMspt, recentGcMaxMillis,
elapsedMillis, generatedAtEpochMillis,
tickCount, totalSamples, intervalMicros, omittedChunks, omittedTickables,
omittedOwnerSources, omittedLoaderSources, chunks, tickables, owners, loaders);
}
@@ -15,7 +15,7 @@ import net.neoforged.neoforge.network.registration.NetworkRegistry;
@EventBusSubscriber(modid = ServerWarashi.MODID, bus = EventBusSubscriber.Bus.MOD)
public final class WarashiNetwork {
static final String NETWORK_VERSION = "4";
static final String NETWORK_VERSION = "5";
private WarashiNetwork() {
}
@@ -9,7 +9,7 @@
"screen.serverwarashi.profiler.game_paused_tooltip": "The current map screen pauses singleplayer, so performance data cannot be collected while it is open. Close the map to start collecting.",
"screen.serverwarashi.profiler.page": "Page %1$s/%2$s",
"screen.serverwarashi.profiler.summary": "Server %1$s MSPT | %2$ss | %3$s ticks | %4$sus | omitted %5$s",
"screen.serverwarashi.profiler.summary.tickables": "Server %1$s MSPT | Previous tick GC %6$s ms | %2$ss | %3$s ticks | %4$sus | omitted %5$s",
"screen.serverwarashi.profiler.summary.tickables": "Server %1$s MSPT | GC 1s avg %6$s ms/tick, max %7$s ms | %2$ss | %3$s ticks | %4$sus | omitted %5$s",
"screen.serverwarashi.profiler.no_data": "No data",
"screen.serverwarashi.profiler.tab.chunks": "Chunks",
"screen.serverwarashi.profiler.tab.tickables": "Tickables",
@@ -9,7 +9,7 @@
"screen.serverwarashi.profiler.game_paused_tooltip": "当前地图界面会暂停单人游戏,无法在地图打开时采集性能数据。你需要关闭地图才能正常采集。",
"screen.serverwarashi.profiler.page": "第 %1$s/%2$s 页",
"screen.serverwarashi.profiler.summary": "服务器 %1$s MSPT | %2$s 秒 | %3$s tick | %4$s 微秒 | 省略 %5$s",
"screen.serverwarashi.profiler.summary.tickables": "服务器 %1$s MSPT | 上一 tick GC %6$s 毫秒 | %2$s 秒 | %3$s tick | %4$s 微秒 | 省略 %5$s",
"screen.serverwarashi.profiler.summary.tickables": "服务器 %1$s MSPT | GC 近 1 秒均值 %6$s 毫秒/tick,最大 %7$s 毫秒 | %2$s 秒 | %3$s tick | %4$s 微秒 | 省略 %5$s",
"screen.serverwarashi.profiler.no_data": "暂无数据",
"screen.serverwarashi.profiler.tab.chunks": "区块",
"screen.serverwarashi.profiler.tab.tickables": "Tick 对象",
@@ -38,18 +38,30 @@ class PerfSampleAggregatorTest {
}
@Test
void reportsGcTimeFromTheMostRecentlyCompletedTick() {
void reportsAverageAndMaximumGcFromTheLastSecond() {
PerfSampleAggregator aggregator = new PerfSampleAggregator(11L);
TickSamples previous = new TickSamples(null);
previous.gcTimeMillis = 3L;
previous.completedAtNanos = 0L;
aggregator.accept(previous);
TickSamples latest = new TickSamples(null);
latest.gcTimeMillis = 8L;
latest.gcTimeMillis = 9L;
latest.completedAtNanos = 500_000_000L;
aggregator.accept(latest);
PerfReportData report = aggregator.build(milliseconds(2L), 0L, 1_000);
assertEquals(8L, report.lastTickGcMillis());
assertEquals(6.0D, report.recentGcMspt());
assertEquals(9L, report.recentGcMaxMillis());
TickSamples nextWindow = new TickSamples(null);
nextWindow.gcTimeMillis = 1L;
nextWindow.completedAtNanos = 1_100_000_000L;
aggregator.accept(nextWindow);
PerfReportData shifted = aggregator.build(milliseconds(3L), 0L, 1_000);
assertEquals(5.0D, shifted.recentGcMspt());
assertEquals(9L, shifted.recentGcMaxMillis());
}
@Test
@@ -64,7 +76,8 @@ class PerfSampleAggregatorTest {
PerfReportData report = aggregator.build(milliseconds(6_000L), 1L, 1_000);
assertEquals(30_000.0D, report.serverMspt(), 0.000_001D);
assertEquals(7L, report.lastTickGcMillis());
assertEquals(7.0D, report.recentGcMspt());
assertEquals(7L, report.recentGcMaxMillis());
assertEquals(observedMillis(6_000L, 1), report.tickables().getFirst().metric().mspt(), 0.000_001D);
}
@@ -3,6 +3,9 @@ package com.moepus.serverwarashi.common.modules.performance.sampling;
import com.moepus.serverwarashi.ServerWarashi;
import net.minecraft.gametest.framework.GameTest;
import net.minecraft.gametest.framework.GameTestHelper;
import net.neoforged.bus.api.SubscribeEvent;
import net.neoforged.neoforge.common.NeoForge;
import net.neoforged.neoforge.event.tick.ServerTickEvent;
import net.neoforged.neoforge.gametest.GameTestHolder;
import net.neoforged.neoforge.gametest.PrefixGameTestTemplate;
@@ -12,8 +15,41 @@ public final class PerfStackAttributorGameTest {
private PerfStackAttributorGameTest() {
}
@GameTest(templateNamespace = "minecraft", template = "bastion/mobs/empty")
public static void serverStartsWithStackSampling(GameTestHelper helper) {
helper.succeed();
@GameTest(templateNamespace = "minecraft", template = "bastion/mobs/empty", timeoutTicks = 20)
public static void attributesRealServerTickListener(GameTestHelper helper) {
RuntimeProbe probe = new RuntimeProbe();
NeoForge.EVENT_BUS.register(probe);
helper.runAfterDelay(10, () -> NeoForge.EVENT_BUS.unregister(probe));
helper.succeedWhen(() -> probe.assertCaptured(helper));
}
private static final class RuntimeProbe {
private PerfWorkTracker.Snapshot captured;
private boolean invoked;
@SubscribeEvent
public void onServerTick(ServerTickEvent.Pre event) {
captured = PerfStackAttributor.capture(Thread.currentThread());
invoked = true;
NeoForge.EVENT_BUS.unregister(this);
}
void assertCaptured(GameTestHelper helper) {
if (!invoked) {
helper.fail("ServerTickEvent.Pre listener was not invoked");
}
if (captured == null || captured.type() != TickType.HANDLER) {
helper.fail("ServerTickEvent.Pre listener was not attributed as HANDLER");
}
String shortName = "PerfStackAttributorGameTest.RuntimeProbe#onServerTick(ServerTickEvent.Pre)";
if (!shortName.equals(captured.displayName())) {
helper.fail("Unexpected handler short name: " + captured.displayName());
}
String fullName = RuntimeProbe.class.getName().replace('$', '.') + "#onServerTick("
+ ServerTickEvent.Pre.class.getName().replace('$', '.') + ")";
if (!fullName.equals(captured.eventLoop())) {
helper.fail("Unexpected handler full name: " + captured.eventLoop());
}
}
}
}
@@ -67,6 +67,24 @@ class PerfStackAttributorTest {
)));
}
@Test
void treatsTaskBlockingInsideWaitUntilNextTickAsUnknown() {
PerfWorkTracker.Snapshot sample = PerfStackAttributor.classify(stack(
frame("java.util.concurrent.locks.LockSupport", "parkNanos"),
frame("net.minecraft.util.thread.BlockableEventLoop", "waitForTasks"),
frame("net.minecraft.util.thread.BlockableEventLoop", "managedBlock"),
frame("net.minecraft.server.level.ServerChunkCache", "getChunk"),
frame("com.example.LongTask", "run"),
frame("net.minecraft.util.thread.BlockableEventLoop", "doRunTask"),
frame("net.minecraft.util.thread.BlockableEventLoop", "pollTask"),
frame("net.minecraft.util.thread.BlockableEventLoop", "managedBlock"),
frame("net.minecraft.server.MinecraftServer", "waitUntilNextTick")
));
assertEquals(TickType.TASK, sample.type());
assertEquals("Unknown", sample.displayName());
}
@Test
void collapsesTasksBlockingWaitsAndOtherActiveWorkIntoUnknown() {
List<StackTraceElement[]> stacks = List.of(
@@ -23,7 +23,7 @@ class PerfReportCodecTest {
void roundTripsTypedReport() {
PerfReportData.Metric metric = new PerfReportData.Metric(1.25D, 3.5D, 42L);
PerfReportData expected = new PerfReportData(
17L, 48.75D, 6L, 10_000L, 123_456_789L, 200L, 9_999L, 1_000, 2, 3, 4, 5,
17L, 48.75D, 2.5D, 12L, 10_000L, 123_456_789L, 200L, 9_999L, 1_000, 2, 3, 4, 5,
List.of(new PerfReportData.ChunkEntry("minecraft:overworld", 2, -3, 7, 4,
List.of(new PerfReportData.ObjectCount("ItemEntity", "minecraft:stone",
TickDetailKind.ITEM, 3, 33, 64, -40)),
@@ -209,7 +209,10 @@ class PerfReportCodecTest {
() -> new PerfReportData(0.0D, 0L, 0L, 0L, 0L, 1_000,
-1, 0, 0, 0, List.of(), List.of(), List.of(), List.of()));
assertThrows(IllegalArgumentException.class,
() -> new PerfReportData(0L, 0.0D, -1L, 0L, 0L, 0L, 0L, 1_000,
() -> new PerfReportData(0L, 0.0D, -1.0D, 0L, 0L, 0L, 0L, 0L, 1_000,
0, 0, 0, 0, List.of(), List.of(), List.of(), List.of()));
assertThrows(IllegalArgumentException.class,
() -> new PerfReportData(0L, 0.0D, 0.0D, -1L, 0L, 0L, 0L, 0L, 1_000,
0, 0, 0, 0, List.of(), List.of(), List.of(), List.of()));
assertThrows(IllegalArgumentException.class,
() -> new PerfReportData.LoaderSourceEntry(
@@ -257,6 +260,7 @@ class PerfReportCodecTest {
private static void writeEmptyReportHeader(RegistryFriendlyByteBuf buffer) {
buffer.writeVarLong(0L);
buffer.writeDouble(0.0D);
buffer.writeDouble(0.0D);
buffer.writeVarLong(0L);
buffer.writeVarLong(0L);
buffer.writeVarLong(0L);
@@ -76,8 +76,8 @@ class WeakChunkPayloadTest {
}
@Test
void networkProtocolIsVersionFour() {
assertEquals("4", WarashiNetwork.NETWORK_VERSION);
void networkProtocolIsVersionFive() {
assertEquals("5", WarashiNetwork.NETWORK_VERSION);
}
private static RegistryFriendlyByteBuf buffer() {