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/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/io/papermc/paper/command/PaperCommand.java b/src/main/java/io/papermc/paper/command/PaperCommand.java index b5b4025c0ec07fbd0ec9bf6f6812d6422f549289..40cd55e610cbee25a7cff0e6001bad40b4418551 100644 --- a/src/main/java/io/papermc/paper/command/PaperCommand.java +++ b/src/main/java/io/papermc/paper/command/PaperCommand.java @@ -5,6 +5,7 @@ import io.papermc.paper.command.subcommands.EntityCommand; import io.papermc.paper.command.subcommands.FixLightCommand; import io.papermc.paper.command.subcommands.HeapDumpCommand; import io.papermc.paper.command.subcommands.ReloadCommand; +import io.papermc.paper.command.subcommands.SyncLoadInfoCommand; import io.papermc.paper.command.subcommands.VersionCommand; import it.unimi.dsi.fastutil.Pair; import java.util.ArrayList; @@ -44,6 +45,7 @@ public final class PaperCommand extends Command { commands.put(Set.of("version"), new VersionCommand()); commands.put(Set.of("debug", "chunkinfo"), new ChunkDebugCommand()); commands.put(Set.of("fixlight"), new FixLightCommand()); + 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..1120aef5b0dd983c467167f77245884e1198552a --- /dev/null +++ b/src/main/java/io/papermc/paper/command/subcommands/SyncLoadInfoCommand.java @@ -0,0 +1,78 @@ +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.time.LocalDateTime; +import java.time.format.DateTimeFormatter; +import java.util.List; +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; + +@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 tabComplete(final CommandSender sender, final String subCommand, final String[] args) { + return CommandUtil.getListMatchingLast(sender, args, "clear"); + } + + private void doSyncLoadInfo(final CommandSender sender, final String[] args) { + if (!SyncLoadFinder.ENABLED) { + sender.sendMessage(text("This command requires the server startup flag '-Dpaper.debug-sync-loads=true' to be set.", RED)); + 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" + DateTimeFormatter.ofPattern("yyyy-MM-dd_HH.mm.ss").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); + + String fileData = stringWriter.toString(); + + try ( + PrintStream out = new PrintStream(new FileOutputStream(file), false, "UTF-8") + ) { + out.print(fileData); + } + sender.sendMessage(text("Successfully written sync load information!", GREEN)); + } catch (Throwable thr) { + sender.sendMessage(text("Failed to write sync load information!", RED)); + thr.printStackTrace(); + } + } +} diff --git a/src/main/java/net/minecraft/server/level/ServerChunkCache.java b/src/main/java/net/minecraft/server/level/ServerChunkCache.java index c12c03b9e79f264ee593373f8a72ed37c0ae8514..509b2ee115584ce80717cc12a7ab548d103b4b92 100644 --- a/src/main/java/net/minecraft/server/level/ServerChunkCache.java +++ b/src/main/java/net/minecraft/server/level/ServerChunkCache.java @@ -633,6 +633,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 57abbcd9d59ea29e2feb238ee342f28a66122006..2531592ba605b15f16d7438829de51de65d7305c 100644 --- a/src/main/java/net/minecraft/server/level/ServerLevel.java +++ b/src/main/java/net/minecraft/server/level/ServerLevel.java @@ -389,6 +389,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