From 0000000000000000000000000000000000000000 Mon Sep 17 00:00:00 2001 From: Spottedleaf 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/PaperCommand.java b/src/main/java/com/destroystokyo/paper/PaperCommand.java index 3091c100eaf5a86ba270ef0d96de1852a2a0ac9e..51e469146f0712a509071c8438ff6b69f961f945 100644 --- a/src/main/java/com/destroystokyo/paper/PaperCommand.java +++ b/src/main/java/com/destroystokyo/paper/PaperCommand.java @@ -1,11 +1,17 @@ package com.destroystokyo.paper; +import com.destroystokyo.paper.io.SyncLoadFinder; import com.google.common.base.Functions; import com.google.common.base.Joiner; import com.google.common.collect.ImmutableSet; import com.google.common.collect.Iterables; import com.google.common.collect.Lists; import com.google.common.collect.Maps; +import com.google.gson.JsonObject; +import com.google.gson.internal.Streams; +import com.google.gson.stream.JsonWriter; +import net.minecraft.resources.ResourceLocation; +import net.minecraft.server.MCUtil; import net.minecraft.server.MinecraftServer; import net.minecraft.server.level.ChunkHolder; import net.minecraft.server.level.ServerChunkCache; @@ -30,6 +36,9 @@ import org.bukkit.craftbukkit.entity.CraftPlayer; import org.bukkit.entity.Player; import java.io.File; +import java.io.FileOutputStream; +import java.io.PrintStream; +import java.io.StringWriter; import java.time.LocalDateTime; import java.time.format.DateTimeFormatter; import java.util.ArrayDeque; @@ -47,7 +56,7 @@ import java.util.stream.Collectors; public class PaperCommand extends Command { private static final String BASE_PERM = "bukkit.command.paper."; - private static final ImmutableSet SUBCOMMANDS = ImmutableSet.builder().add("heap", "entity", "reload", "version", "debug", "chunkinfo", "fixlight").build(); + private static final ImmutableSet SUBCOMMANDS = ImmutableSet.builder().add("heap", "entity", "reload", "version", "debug", "chunkinfo", "fixlight", "syncloadinfo").build(); public PaperCommand(String name) { super(name); @@ -90,6 +99,11 @@ public class PaperCommand extends Command { return getListMatchingLast(sender, args, worldNames); } break; + case "syncloadinfo": + if (args.length == 2) { + return getListMatchingLast(sender, args, "clear"); + } + break; } return Collections.emptyList(); } @@ -165,6 +179,9 @@ public class PaperCommand extends Command { case "fixlight": this.doFixLight(sender, args); break; + case "syncloadinfo": + this.doSyncLoadInfo(sender, args); + break; case "ver": if (!testPermission(sender, "version")) break; // "ver" needs a special check because it's an alias. All other commands are checked up before the switch statement (because they are present in the SUBCOMMANDS set) case "version": @@ -182,6 +199,47 @@ public class PaperCommand extends Command { return true; } + private void doSyncLoadInfo(CommandSender sender, String[] args) { + if (!SyncLoadFinder.ENABLED) { + sender.sendMessage(ChatColor.RED + "This command requires the server startup flag '-Dpaper.debug-sync-loads=true' to be set."); + return; + } + + if (args.length > 1 && args[1].equals("clear")) { + SyncLoadFinder.clear(); + sender.sendMessage(ChatColor.GRAY + "Sync load data cleared."); + return; + } + + File file = new File(new File(new File("."), "debug"), + "sync-load-info" + DateTimeFormatter.ofPattern("yyyy-MM-dd_HH.mm.ss").format(LocalDateTime.now()) + ".txt"); + file.getParentFile().mkdirs(); + sender.sendMessage(ChatColor.GREEN + "Writing sync load info to " + file.toString()); + + + try { + final JsonObject data = SyncLoadFinder.serialize(); + + StringWriter stringWriter = new StringWriter(); + JsonWriter jsonWriter = new JsonWriter(stringWriter); + jsonWriter.setIndent(" "); + jsonWriter.setLenient(false); + Streams.write(data, jsonWriter); + + String fileData = stringWriter.toString(); + + try ( + PrintStream out = new PrintStream(new FileOutputStream(file), false, "UTF-8") + ) { + out.print(fileData); + } + sender.sendMessage(ChatColor.GREEN + "Successfully written sync load information!"); + } catch (Throwable thr) { + sender.sendMessage(ChatColor.RED + "Failed to write sync load information"); + thr.printStackTrace(); + } + } + private void doChunkInfo(CommandSender sender, String[] args) { List worlds; if (args.length < 2 || args[1].equals("*")) { 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..0bb4aaa546939b67a5d22865190f30478a9337c1 --- /dev/null +++ b/src/main/java/com/destroystokyo/paper/io/SyncLoadFinder.java @@ -0,0 +1,175 @@ +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.Level; + +public class SyncLoadFinder { + + public static final boolean ENABLED = Boolean.getBoolean("paper.debug-sync-loads"); + + private static final WeakHashMap> 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 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(IOUtil.getCoordinateKey(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> entry : SYNC_LOADS.entrySet()) { + final Level world = entry.getKey(); + + final JsonObject worldData = new JsonObject(); + + worldData.addProperty("name", world.getWorld().getName()); + + final List> data = new ArrayList<>(); + + entry.getValue().forEach((ThrowableWithEquals stacktrace, SyncLoadInformation times) -> { + data.add(new Pair<>(stacktrace, times)); + }); + + data.sort((Pair pair1, Pair pair2) -> { + return Integer.compare(pair2.getSecond().times, pair1.getSecond().times); // reverse order + }); + + final JsonArray stacktraces = new JsonArray(); + + for (Pair 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(); + coordinates.add("(" + IOUtil.getCoordinateX(key) + "," + IOUtil.getCoordinateZ(key) + "): " + 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/net/minecraft/server/level/ServerChunkCache.java b/src/main/java/net/minecraft/server/level/ServerChunkCache.java index fa95322c02f9eee7d2cca06c48c19383d414032f..1eab367b375bb7bf6fadb602f378f6817e519371 100644 --- a/src/main/java/net/minecraft/server/level/ServerChunkCache.java +++ b/src/main/java/net/minecraft/server/level/ServerChunkCache.java @@ -644,6 +644,7 @@ public class ServerChunkCache extends ChunkSource { this.level.asyncChunkTaskManager.raisePriority(x1, z1, com.destroystokyo.paper.io.PrioritizedTaskQueue.HIGHEST_PRIORITY); com.destroystokyo.paper.io.chunk.ChunkTaskManager.pushChunkWait(this.level, x1, z1); // Paper end + com.destroystokyo.paper.io.SyncLoadFinder.logSyncLoad(this.level, x1, z1); // Paper - sync load info this.level.timings.syncChunkLoad.startTiming(); // Paper chunkproviderserver_b.managedBlock(completablefuture::isDone); com.destroystokyo.paper.io.chunk.ChunkTaskManager.popChunkWait(); // Paper - async chunk debug diff --git a/src/main/java/net/minecraft/server/level/ServerLevel.java b/src/main/java/net/minecraft/server/level/ServerLevel.java index d26e42449a1f75898d06aba384178c0ef30d9aa7..a21300a866dc6c9f7097a894e0506515210090f5 100644 --- a/src/main/java/net/minecraft/server/level/ServerLevel.java +++ b/src/main/java/net/minecraft/server/level/ServerLevel.java @@ -379,6 +379,12 @@ public class ServerLevel extends Level implements WorldGenLevel { }; public final com.destroystokyo.paper.io.chunk.ChunkTaskManager asyncChunkTaskManager; // Paper end + // Paper start + @Override + public boolean hasChunk(int chunkX, int chunkZ) { + return this.getChunkSource().getChunkAtIfLoadedImmediately(chunkX, chunkZ) != null; + } + // Paper end // Paper start - optimise getPlayerByUUID @Nullable