PaperMC/patches/server/0313-Add-debug-for-sync-chunk-loads.patch
Bjarne Koll c5a10665b8
Remove wall-time / unused skip tick protection (#11412)
Spigot still maintains some partial implementation of "tick skipping", a
practice in which the MinecraftServer.currentTick field is updated not
by an increment of one per actual tick, but instead set to
System.currentTimeMillis() / 50. This behaviour means that the tracked
tick may "skip" a tick value in case a previous tick took more than the
expected 50ms.

To compensate for this in important paths, spigot/craftbukkit
implements "wall-time". Instead of incrementing/decrementing ticks on
block entities/entities by one for each call to their tick() method,
they instead increment/decrement important values, like
an ItemEntity's age or pickupDelay, by the difference of
`currentTick - lastTick`, where `lastTick` is the value of
`currentTick` during the last tick() call.

These "fixes" however do not play nicely with minecraft's simulation
distance as entities/block entities implementing the above behaviour
would "catch up" their values when moving from a non-ticking chunk to a
ticking one as their `lastTick` value remains stuck on the last tick in
a ticking chunk and hence lead to a large "catch up" once ticked again.

Paper completely removes the "tick skipping" behaviour (See patch
"Further-improve-server-tick-loop"), making the above precautions
completely unnecessary, which also rids paper of the previous described
incompatibility with non-ticking chunks.
2024-09-19 16:36:07 +02:00

333 lines
13 KiB
Diff

From 0000000000000000000000000000000000000000 Mon Sep 17 00:00:00 2001
From: Spottedleaf <Spottedleaf@users.noreply.github.com>
Date: Fri, 19 Jul 2019 03:29:14 -0700
Subject: [PATCH] Add debug for sync chunk loads
This patch adds a tool to find calls to getChunkAt which would load
chunks, however it must be enabled by setting the startup flag
-Dpaper.debug-sync-loads=true
- To get a debug log for sync loads, the command is
/paper syncloadinfo
- To clear clear the currently stored sync load info, use
/paper syncloadinfo clear
diff --git a/src/main/java/com/destroystokyo/paper/io/SyncLoadFinder.java b/src/main/java/com/destroystokyo/paper/io/SyncLoadFinder.java
new file mode 100644
index 0000000000000000000000000000000000000000..605a4a83d0a098a9977da00c710e798396dc5256
--- /dev/null
+++ b/src/main/java/com/destroystokyo/paper/io/SyncLoadFinder.java
@@ -0,0 +1,177 @@
+package com.destroystokyo.paper.io;
+
+import com.google.gson.JsonArray;
+import com.google.gson.JsonObject;
+import com.mojang.datafixers.util.Pair;
+import it.unimi.dsi.fastutil.longs.Long2IntMap;
+import it.unimi.dsi.fastutil.longs.Long2IntOpenHashMap;
+import it.unimi.dsi.fastutil.objects.Object2ObjectOpenHashMap;
+
+import java.util.ArrayList;
+import java.util.List;
+import java.util.Map;
+import java.util.WeakHashMap;
+import net.minecraft.world.level.ChunkPos;
+import net.minecraft.world.level.Level;
+
+public class SyncLoadFinder {
+
+ public static final boolean ENABLED = Boolean.getBoolean("paper.debug-sync-loads");
+
+ private static final WeakHashMap<Level, Object2ObjectOpenHashMap<ThrowableWithEquals, SyncLoadInformation>> SYNC_LOADS = new WeakHashMap<>();
+
+ private static final class SyncLoadInformation {
+
+ public int times;
+
+ public final Long2IntOpenHashMap coordinateTimes = new Long2IntOpenHashMap();
+ }
+
+ public static void clear() {
+ SYNC_LOADS.clear();
+ }
+
+ public static void logSyncLoad(final Level world, final int chunkX, final int chunkZ) {
+ if (!ENABLED) {
+ return;
+ }
+
+ final ThrowableWithEquals stacktrace = new ThrowableWithEquals(Thread.currentThread().getStackTrace());
+
+ SYNC_LOADS.compute(world, (final Level keyInMap, Object2ObjectOpenHashMap<ThrowableWithEquals, SyncLoadInformation> map) -> {
+ if (map == null) {
+ map = new Object2ObjectOpenHashMap<>();
+ }
+
+ map.compute(stacktrace, (ThrowableWithEquals keyInMap0, SyncLoadInformation valueInMap) -> {
+ if (valueInMap == null) {
+ valueInMap = new SyncLoadInformation();
+ }
+
+ ++valueInMap.times;
+
+ valueInMap.coordinateTimes.compute(ChunkPos.asLong(chunkX, chunkZ), (Long keyInMap1, Integer valueInMap1) -> {
+ return valueInMap1 == null ? Integer.valueOf(1) : Integer.valueOf(valueInMap1.intValue() + 1);
+ });
+
+ return valueInMap;
+ });
+
+ return map;
+ });
+ }
+
+ public static JsonObject serialize() {
+ final JsonObject ret = new JsonObject();
+
+ final JsonArray worldsData = new JsonArray();
+
+ for (final Map.Entry<Level, Object2ObjectOpenHashMap<ThrowableWithEquals, SyncLoadInformation>> entry : SYNC_LOADS.entrySet()) {
+ final Level world = entry.getKey();
+
+ final JsonObject worldData = new JsonObject();
+
+ worldData.addProperty("name", world.getWorld().getName());
+
+ final List<Pair<ThrowableWithEquals, SyncLoadInformation>> data = new ArrayList<>();
+
+ entry.getValue().forEach((ThrowableWithEquals stacktrace, SyncLoadInformation times) -> {
+ data.add(new Pair<>(stacktrace, times));
+ });
+
+ data.sort((Pair<ThrowableWithEquals, SyncLoadInformation> pair1, Pair<ThrowableWithEquals, SyncLoadInformation> pair2) -> {
+ return Integer.compare(pair2.getSecond().times, pair1.getSecond().times); // reverse order
+ });
+
+ final JsonArray stacktraces = new JsonArray();
+
+ for (Pair<ThrowableWithEquals, SyncLoadInformation> pair : data) {
+ final JsonObject stacktrace = new JsonObject();
+
+ stacktrace.addProperty("times", pair.getSecond().times);
+
+ final JsonArray traces = new JsonArray();
+
+ for (StackTraceElement element : pair.getFirst().stacktrace) {
+ traces.add(String.valueOf(element));
+ }
+
+ stacktrace.add("stacktrace", traces);
+
+ final JsonArray coordinates = new JsonArray();
+
+ for (Long2IntMap.Entry coordinate : pair.getSecond().coordinateTimes.long2IntEntrySet()) {
+ final long key = coordinate.getLongKey();
+ final int times = coordinate.getIntValue();
+ final ChunkPos chunkPos = new ChunkPos(key);
+ coordinates.add("(" + chunkPos.x + "," + chunkPos.z + "): " + times);
+ }
+
+ stacktrace.add("coordinates", coordinates);
+
+ stacktraces.add(stacktrace);
+ }
+
+
+ worldData.add("stacktraces", stacktraces);
+ worldsData.add(worldData);
+ }
+
+ ret.add("worlds", worldsData);
+
+ return ret;
+ }
+
+ static final class ThrowableWithEquals {
+
+ private final StackTraceElement[] stacktrace;
+ private final int hash;
+
+ public ThrowableWithEquals(final StackTraceElement[] stacktrace) {
+ this.stacktrace = stacktrace;
+ this.hash = ThrowableWithEquals.hash(stacktrace);
+ }
+
+ public static int hash(final StackTraceElement[] stacktrace) {
+ int hash = 0;
+
+ for (int i = 0; i < stacktrace.length; ++i) {
+ hash *= 31;
+ hash += stacktrace[i].hashCode();
+ }
+
+ return hash;
+ }
+
+ @Override
+ public int hashCode() {
+ return this.hash;
+ }
+
+ @Override
+ public boolean equals(final Object obj) {
+ if (obj == null || obj.getClass() != this.getClass()) {
+ return false;
+ }
+
+ final ThrowableWithEquals other = (ThrowableWithEquals)obj;
+ final StackTraceElement[] otherStackTrace = other.stacktrace;
+
+ if (this.stacktrace.length != otherStackTrace.length || this.hash != other.hash) {
+ return false;
+ }
+
+ if (this == obj) {
+ return true;
+ }
+
+ for (int i = 0; i < this.stacktrace.length; ++i) {
+ if (!this.stacktrace[i].equals(otherStackTrace[i])) {
+ return false;
+ }
+ }
+
+ return true;
+ }
+ }
+}
diff --git a/src/main/java/io/papermc/paper/command/PaperCommand.java b/src/main/java/io/papermc/paper/command/PaperCommand.java
index e1820a339452cd3388dd7cbb928c5f58779a77b6..3010d57efcc97fb409bfe43b1fc9af198c099a67 100644
--- a/src/main/java/io/papermc/paper/command/PaperCommand.java
+++ b/src/main/java/io/papermc/paper/command/PaperCommand.java
@@ -38,6 +38,7 @@ public final class PaperCommand extends Command {
commands.put(Set.of("reload"), new ReloadCommand());
commands.put(Set.of("version"), new VersionCommand());
commands.put(Set.of("dumpplugins"), new DumpPluginsCommand());
+ commands.put(Set.of("syncloadinfo"), new SyncLoadInfoCommand());
return commands.entrySet().stream()
.flatMap(entry -> entry.getKey().stream().map(s -> Map.entry(s, entry.getValue())))
diff --git a/src/main/java/io/papermc/paper/command/subcommands/SyncLoadInfoCommand.java b/src/main/java/io/papermc/paper/command/subcommands/SyncLoadInfoCommand.java
new file mode 100644
index 0000000000000000000000000000000000000000..95d6022c9cfb2e36ec5a71be6e34354027c2ec08
--- /dev/null
+++ b/src/main/java/io/papermc/paper/command/subcommands/SyncLoadInfoCommand.java
@@ -0,0 +1,88 @@
+package io.papermc.paper.command.subcommands;
+
+import com.destroystokyo.paper.io.SyncLoadFinder;
+import com.google.gson.JsonObject;
+import com.google.gson.internal.Streams;
+import com.google.gson.stream.JsonWriter;
+import io.papermc.paper.command.CommandUtil;
+import io.papermc.paper.command.PaperSubcommand;
+import java.io.File;
+import java.io.FileOutputStream;
+import java.io.PrintStream;
+import java.io.StringWriter;
+import java.nio.charset.StandardCharsets;
+import java.time.LocalDateTime;
+import java.time.format.DateTimeFormatter;
+import java.util.List;
+
+import net.kyori.adventure.text.event.ClickEvent;
+import net.kyori.adventure.text.event.HoverEvent;
+import net.minecraft.server.MinecraftServer;
+import org.bukkit.command.CommandSender;
+import org.checkerframework.checker.nullness.qual.NonNull;
+import org.checkerframework.framework.qual.DefaultQualifier;
+
+import static net.kyori.adventure.text.Component.text;
+import static net.kyori.adventure.text.format.NamedTextColor.GRAY;
+import static net.kyori.adventure.text.format.NamedTextColor.GREEN;
+import static net.kyori.adventure.text.format.NamedTextColor.RED;
+import static net.kyori.adventure.text.format.NamedTextColor.WHITE;
+
+@DefaultQualifier(NonNull.class)
+public final class SyncLoadInfoCommand implements PaperSubcommand {
+ @Override
+ public boolean execute(final CommandSender sender, final String subCommand, final String[] args) {
+ this.doSyncLoadInfo(sender, args);
+ return true;
+ }
+
+ @Override
+ public List<String> tabComplete(final CommandSender sender, final String subCommand, final String[] args) {
+ return CommandUtil.getListMatchingLast(sender, args, "clear");
+ }
+
+ private static final DateTimeFormatter FORMATTER = DateTimeFormatter.ofPattern("yyyy-MM-dd_HH.mm.ss");
+
+ private void doSyncLoadInfo(final CommandSender sender, final String[] args) {
+ if (!SyncLoadFinder.ENABLED) {
+ String systemFlag = "-Dpaper.debug-sync-loads=true";
+ sender.sendMessage(text().color(RED).append(text("This command requires the server startup flag '")).append(
+ text(systemFlag, WHITE).clickEvent(ClickEvent.copyToClipboard(systemFlag))
+ .hoverEvent(HoverEvent.showText(text("Click to copy the system flag")))).append(
+ text("' to be set.")));
+ return;
+ }
+
+ if (args.length > 0 && args[0].equals("clear")) {
+ SyncLoadFinder.clear();
+ sender.sendMessage(text("Sync load data cleared.", GRAY));
+ return;
+ }
+
+ File file = new File(new File(new File("."), "debug"),
+ "sync-load-info-" + FORMATTER.format(LocalDateTime.now()) + ".txt");
+ file.getParentFile().mkdirs();
+ sender.sendMessage(text("Writing sync load info to " + file, GREEN));
+
+
+ try {
+ final JsonObject data = SyncLoadFinder.serialize();
+
+ StringWriter stringWriter = new StringWriter();
+ JsonWriter jsonWriter = new JsonWriter(stringWriter);
+ jsonWriter.setIndent(" ");
+ jsonWriter.setLenient(false);
+ Streams.write(data, jsonWriter);
+
+ try (
+ PrintStream out = new PrintStream(new FileOutputStream(file), false, StandardCharsets.UTF_8)
+ ) {
+ out.print(stringWriter);
+ }
+ sender.sendMessage(text("Successfully written sync load information!", GREEN));
+ } catch (Throwable thr) {
+ sender.sendMessage(text("Failed to write sync load information! See the console for more info.", RED));
+ MinecraftServer.LOGGER.warn("Error occurred while dumping sync chunk load info", thr);
+ }
+ }
+}
diff --git a/src/main/java/net/minecraft/server/level/ServerChunkCache.java b/src/main/java/net/minecraft/server/level/ServerChunkCache.java
index 1049452baaf0381ffbf15b30da956c2a1994da35..60f678c26fb5144386d8697ddfd5b6d841563b6f 100644
--- a/src/main/java/net/minecraft/server/level/ServerChunkCache.java
+++ b/src/main/java/net/minecraft/server/level/ServerChunkCache.java
@@ -206,6 +206,7 @@ public class ServerChunkCache extends ChunkSource {
Objects.requireNonNull(completablefuture);
if (!completablefuture.isDone()) { // Paper
+ com.destroystokyo.paper.io.SyncLoadFinder.logSyncLoad(this.level, x, z); // Paper - Add debug for sync chunk loads
this.level.timings.syncChunkLoad.startTiming(); // Paper
chunkproviderserver_b.managedBlock(completablefuture::isDone);
this.level.timings.syncChunkLoad.stopTiming(); // Paper
diff --git a/src/main/java/net/minecraft/server/level/ServerLevel.java b/src/main/java/net/minecraft/server/level/ServerLevel.java
index c85d5b941b5cb1c37cd2619d419006c5956f6eaf..f1fa4cb11f69e248dd55b8aa69f5d07268f182a1 100644
--- a/src/main/java/net/minecraft/server/level/ServerLevel.java
+++ b/src/main/java/net/minecraft/server/level/ServerLevel.java
@@ -422,6 +422,13 @@ public class ServerLevel extends Level implements WorldGenLevel {
this.getCraftServer().addWorld(this.getWorld()); // CraftBukkit
}
+ // Paper start
+ @Override
+ public boolean hasChunk(int chunkX, int chunkZ) {
+ return this.getChunkSource().getChunkAtIfLoadedImmediately(chunkX, chunkZ) != null;
+ }
+ // Paper end
+
/** @deprecated */
@Deprecated
@VisibleForTesting