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 32b84c59722970218a1515e21c6454d0ea4f781d..8f35943e71911b6d49b4cf210e56f5e11c5753e8 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 io.papermc.paper.command.subcommands.DumpPluginsCommand; import it.unimi.dsi.fastutil.Pair; @@ -46,6 +47,7 @@ public final class PaperCommand extends Command { commands.put(Set.of("dumpplugins"), new DumpPluginsCommand()); commands.put(Set.of("fixlight"), new FixLightCommand()); commands.put(Set.of("debug", "chunkinfo", "holderinfo"), new ChunkDebugCommand()); + 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..a73e35e7c71c1337c2846010b3ccd6875cae640e --- /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 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 f838a921a08981bac0d0c0a68e334ba06d11cb18..665e088cb0b73f6a0c62f29c56da462bab7c927e 100644 --- a/src/main/java/net/minecraft/server/level/ServerChunkCache.java +++ b/src/main/java/net/minecraft/server/level/ServerChunkCache.java @@ -445,6 +445,7 @@ public class ServerChunkCache extends ChunkSource { // Paper start - async chunk io/loading io.papermc.paper.chunk.system.scheduling.ChunkTaskScheduler.pushChunkWait(this.level, x1, z1); // Paper - rewrite chunk system // 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); io.papermc.paper.chunk.system.scheduling.ChunkTaskScheduler.popChunkWait(); // Paper - async chunk debug // Paper - rewrite chunk system diff --git a/src/main/java/net/minecraft/server/level/ServerLevel.java b/src/main/java/net/minecraft/server/level/ServerLevel.java index 76c388347ebbff2d50a975b40dbe93cc2760f6bb..52a514b657485246827bf9c153303b8b5229bf5b 100644 --- a/src/main/java/net/minecraft/server/level/ServerLevel.java +++ b/src/main/java/net/minecraft/server/level/ServerLevel.java @@ -424,6 +424,12 @@ public class ServerLevel extends Level implements WorldGenLevel { return this.entityLookup; } // Paper end - rewrite chunk system + // Paper start + @Override + public boolean hasChunk(int chunkX, int chunkZ) { + return this.getChunkSource().getChunkAtIfLoadedImmediately(chunkX, chunkZ) != null; + } + // Paper end // Paper start - optimise getPlayerByUUID @Nullable