PaperMC/patches/server/0690-Detail-more-information-in-watchdog-dumps.patch

From 0000000000000000000000000000000000000000 Mon Sep 17 00:00:00 2001
From: Spottedleaf <Spottedleaf@users.noreply.github.com>
Date: Thu, 26 Mar 2020 21:59:32 -0700
Subject: [PATCH] Detail more information in watchdog dumps

- Dump position, world, velocity, and uuid for currently ticking entities
- Dump player name, player uuid, position, and world for packet handling

diff --git a/src/main/java/net/minecraft/network/Connection.java b/src/main/java/net/minecraft/network/Connection.java
index 95f5ec348ab24b28c19b46cea7b023a1d49998b5..890d14503e157d6c07a6db1f180f49f81118e301 100644
--- a/src/main/java/net/minecraft/network/Connection.java
+++ b/src/main/java/net/minecraft/network/Connection.java
@@ -528,7 +528,13 @@ public class Connection extends SimpleChannelInboundHandler<Packet<?>> {
             if (!(this.packetListener instanceof net.minecraft.server.network.ServerLoginPacketListenerImpl loginPacketListener)
                 || loginPacketListener.state != net.minecraft.server.network.ServerLoginPacketListenerImpl.State.READY_TO_ACCEPT
                 || Connection.joinAttemptsThisTick++ < MAX_PER_TICK) {
+            // Paper start - detailed watchdog information
+            net.minecraft.network.protocol.PacketUtils.packetProcessing.push(this.packetListener);
+            try { // Paper end - detailed watchdog information
             tickablepacketlistener.tick();
+            } finally { // Paper start - detailed watchdog information
+                net.minecraft.network.protocol.PacketUtils.packetProcessing.pop();
+            } // Paper end - detailed watchdog information
             }
             // Paper end
         }
diff --git a/src/main/java/net/minecraft/network/protocol/PacketUtils.java b/src/main/java/net/minecraft/network/protocol/PacketUtils.java
index 4a1148a76020089caf01f888f87afdbb35788dc0..52a84eeb3b7df782cbf91aac6df42fb8f99077f6 100644
--- a/src/main/java/net/minecraft/network/protocol/PacketUtils.java
+++ b/src/main/java/net/minecraft/network/protocol/PacketUtils.java
@@ -15,6 +15,24 @@ public class PacketUtils {
 
     private static final Logger LOGGER = LogUtils.getLogger();
 
+    // Paper start - detailed watchdog information
+    public static final java.util.concurrent.ConcurrentLinkedDeque<PacketListener> packetProcessing = new java.util.concurrent.ConcurrentLinkedDeque<>();
+    static final java.util.concurrent.atomic.AtomicLong totalMainThreadPacketsProcessed = new java.util.concurrent.atomic.AtomicLong();
+
+    public static long getTotalProcessedPackets() {
+        return totalMainThreadPacketsProcessed.get();
+    }
+
+    public static java.util.List<PacketListener> getCurrentPacketProcessors() {
+        java.util.List<PacketListener> ret = new java.util.ArrayList<>(4);
+        for (PacketListener listener : packetProcessing) {
+            ret.add(listener);
+        }
+
+        return ret;
+    }
+    // Paper end - detailed watchdog information
+
     public PacketUtils() {}
 
     public static <T extends PacketListener> void ensureRunningOnSameThread(Packet<T> packet, T listener, ServerLevel world) throws RunningOnDifferentThreadException {
@@ -24,6 +42,8 @@ public class PacketUtils {
     public static <T extends PacketListener> void ensureRunningOnSameThread(Packet<T> packet, T listener, BlockableEventLoop<?> engine) throws RunningOnDifferentThreadException {
         if (!engine.isSameThread()) {
             engine.executeIfPossible(() -> {
+                packetProcessing.push(listener); // Paper - detailed watchdog information
+                try { // Paper - detailed watchdog information
                 if (MinecraftServer.getServer().hasStopped() || (listener instanceof ServerGamePacketListenerImpl && ((ServerGamePacketListenerImpl) listener).processedDisconnect)) return; // CraftBukkit, MC-142590
                 if (listener.isAcceptingMessages()) {
                     co.aikar.timings.Timing timing = co.aikar.timings.MinecraftTimings.getPacketTiming(packet); // Paper - timings
@@ -39,6 +59,12 @@ public class PacketUtils {
                 } else {
                     PacketUtils.LOGGER.debug("Ignoring packet due to disconnection: {}", packet);
                 }
+                // Paper start - detailed watchdog information
+                } finally {
+                    totalMainThreadPacketsProcessed.getAndIncrement();
+                    packetProcessing.pop();
+                }
+                // Paper end - detailed watchdog information
 
             });
             throw RunningOnDifferentThreadException.RUNNING_ON_DIFFERENT_THREAD;
diff --git a/src/main/java/net/minecraft/server/level/ServerLevel.java b/src/main/java/net/minecraft/server/level/ServerLevel.java
index 1d0f87185a8a74394bc2da29828407fd4210754c..d6429d721116aac2a4df8d0b217e9efcb698094e 100644
--- a/src/main/java/net/minecraft/server/level/ServerLevel.java
+++ b/src/main/java/net/minecraft/server/level/ServerLevel.java
@@ -1200,7 +1200,26 @@ public class ServerLevel extends Level implements WorldGenLevel {
 
     }
 
+    // Paper start - log detailed entity tick information
+    // TODO replace with varhandle
+    static final java.util.concurrent.atomic.AtomicReference<Entity> currentlyTickingEntity = new java.util.concurrent.atomic.AtomicReference<>();
+
+    public static List<Entity> getCurrentlyTickingEntities() {
+        Entity ticking = currentlyTickingEntity.get();
+        List<Entity> ret = java.util.Arrays.asList(ticking == null ? new Entity[0] : new Entity[] { ticking });
+
+        return ret;
+    }
+    // Paper end - log detailed entity tick information
+
     public void tickNonPassenger(Entity entity) {
+        // Paper start - log detailed entity tick information
+        io.papermc.paper.util.TickThread.ensureTickThread("Cannot tick an entity off-main");
+        try {
+            if (currentlyTickingEntity.get() == null) {
+                currentlyTickingEntity.lazySet(entity);
+            }
+            // Paper end - log detailed entity tick information
         ++TimingHistory.entityTicks; // Paper - timings
         // Spigot start
         co.aikar.timings.Timing timer; // Paper
@@ -1240,7 +1259,13 @@ public class ServerLevel extends Level implements WorldGenLevel {
             this.tickPassenger(entity, entity1);
         }
         // } finally { timer.stopTiming(); } // Paper - timings - move up
-
+        // Paper start - log detailed entity tick information
+        } finally {
+            if (currentlyTickingEntity.get() == entity) {
+                currentlyTickingEntity.lazySet(null);
+            }
+        }
+        // Paper end - log detailed entity tick information
     }
 
     private void tickPassenger(Entity vehicle, Entity passenger) {
diff --git a/src/main/java/net/minecraft/world/entity/Entity.java b/src/main/java/net/minecraft/world/entity/Entity.java
index d28c3834aeefc8ab553c366a037549f46fb7cfc3..b421f4f8f32dd3df97ba465e6d865d23fc0afda8 100644
--- a/src/main/java/net/minecraft/world/entity/Entity.java
+++ b/src/main/java/net/minecraft/world/entity/Entity.java
@@ -1024,7 +1024,42 @@ public abstract class Entity implements Nameable, EntityAccess, CommandSource {
         return this.onGround;
     }
 
+    // Paper start - detailed watchdog information
+    public final Object posLock = new Object(); // Paper - log detailed entity tick information
+
+    private Vec3 moveVector;
+    private double moveStartX;
+    private double moveStartY;
+    private double moveStartZ;
+
+    public final Vec3 getMoveVector() {
+        return this.moveVector;
+    }
+
+    public final double getMoveStartX() {
+        return this.moveStartX;
+    }
+
+    public final double getMoveStartY() {
+        return this.moveStartY;
+    }
+
+    public final double getMoveStartZ() {
+        return this.moveStartZ;
+    }
+    // Paper end - detailed watchdog information
+
     public void move(MoverType movementType, Vec3 movement) {
+        // Paper start - detailed watchdog information
+        io.papermc.paper.util.TickThread.ensureTickThread("Cannot move an entity off-main");
+        synchronized (this.posLock) {
+            this.moveStartX = this.getX();
+            this.moveStartY = this.getY();
+            this.moveStartZ = this.getZ();
+            this.moveVector = movement;
+        }
+        try {
+        // Paper end - detailed watchdog information
         if (this.noPhysics) {
             this.setPos(this.getX() + movement.x, this.getY() + movement.y, this.getZ() + movement.z);
         } else {
@@ -1194,6 +1229,13 @@ public abstract class Entity implements Nameable, EntityAccess, CommandSource {
                 this.level().getProfiler().pop();
             }
         }
+        // Paper start - detailed watchdog information
+        } finally {
+            synchronized (this.posLock) { // Paper
+                this.moveVector = null;
+            } // Paper
+        }
+        // Paper end - detailed watchdog information
     }
 
     private boolean isStateClimbable(BlockState state) {
@@ -4219,7 +4261,9 @@ public abstract class Entity implements Nameable, EntityAccess, CommandSource {
     }
 
     public void setDeltaMovement(Vec3 velocity) {
+        synchronized (this.posLock) { // Paper
         this.deltaMovement = velocity;
+        } // Paper
     }
 
     public void addDeltaMovement(Vec3 velocity) {
@@ -4305,7 +4349,9 @@ public abstract class Entity implements Nameable, EntityAccess, CommandSource {
         }
         // Paper end - fix MC-4
         if (this.position.x != x || this.position.y != y || this.position.z != z) {
+            synchronized (this.posLock) { // Paper
             this.position = new Vec3(x, y, z);
+            } // Paper
             int i = Mth.floor(x);
             int j = Mth.floor(y);
             int k = Mth.floor(z);
diff --git a/src/main/java/org/spigotmc/WatchdogThread.java b/src/main/java/org/spigotmc/WatchdogThread.java
index e0a71bfc1498a517456b21747ab6ef3f1067a3f3..98fba0288be9ed2cb18ffba5cf81148157dd4fcf 100644
--- a/src/main/java/org/spigotmc/WatchdogThread.java
+++ b/src/main/java/org/spigotmc/WatchdogThread.java
@@ -22,6 +22,78 @@ public final class WatchdogThread extends io.papermc.paper.util.TickThread // Pa
     private volatile long lastTick;
     private volatile boolean stopping;
 
+    // Paper start - log detailed tick information
+    private void dumpEntity(net.minecraft.world.entity.Entity entity) {
+        Logger log = Bukkit.getServer().getLogger();
+        double posX, posY, posZ;
+        net.minecraft.world.phys.Vec3 mot;
+        double moveStartX, moveStartY, moveStartZ;
+        net.minecraft.world.phys.Vec3 moveVec;
+        synchronized (entity.posLock) {
+            posX = entity.getX();
+            posY = entity.getY();
+            posZ = entity.getZ();
+            mot = entity.getDeltaMovement();
+            moveStartX = entity.getMoveStartX();
+            moveStartY = entity.getMoveStartY();
+            moveStartZ = entity.getMoveStartZ();
+            moveVec = entity.getMoveVector();
+        }
+
+        String entityType = net.minecraft.world.entity.EntityType.getKey(entity.getType()).toString();
+        java.util.UUID entityUUID = entity.getUUID();
+        net.minecraft.world.level.Level world = entity.level();
+
+        log.log(Level.SEVERE, "Ticking entity: " + entityType + ", entity class: " + entity.getClass().getName());
+        log.log(Level.SEVERE, "Entity status: removed: " + entity.isRemoved() + ", valid: " + entity.valid + ", alive: " + entity.isAlive() + ", is passenger: " + entity.isPassenger());
+        log.log(Level.SEVERE, "Entity UUID: " + entityUUID);
+        log.log(Level.SEVERE, "Position: world: '" + (world == null ? "unknown world?" : world.getWorld().getName()) + "' at location (" + posX + ", " + posY + ", " + posZ + ")");
+        log.log(Level.SEVERE, "Velocity: " + (mot == null ? "unknown velocity" : mot.toString()) + " (in blocks per tick)");
+        log.log(Level.SEVERE, "Entity AABB: " + entity.getBoundingBox());
+        if (moveVec != null) {
+            log.log(Level.SEVERE, "Move call information: ");
+            log.log(Level.SEVERE, "Start position: (" + moveStartX + ", " + moveStartY + ", " + moveStartZ + ")");
+            log.log(Level.SEVERE, "Move vector: " + moveVec.toString());
+        }
+    }
+
+    private void dumpTickingInfo() {
+        Logger log = Bukkit.getServer().getLogger();
+
+        // ticking entities
+        for (net.minecraft.world.entity.Entity entity : net.minecraft.server.level.ServerLevel.getCurrentlyTickingEntities()) {
+            this.dumpEntity(entity);
+            net.minecraft.world.entity.Entity vehicle = entity.getVehicle();
+            if (vehicle != null) {
+                log.log(Level.SEVERE, "Detailing vehicle for above entity:");
+                this.dumpEntity(vehicle);
+            }
+        }
+
+        // packet processors
+        for (net.minecraft.network.PacketListener packetListener : net.minecraft.network.protocol.PacketUtils.getCurrentPacketProcessors()) {
+            if (packetListener instanceof net.minecraft.server.network.ServerGamePacketListenerImpl) {
+                net.minecraft.server.level.ServerPlayer player = ((net.minecraft.server.network.ServerGamePacketListenerImpl)packetListener).player;
+                long totalPackets = net.minecraft.network.protocol.PacketUtils.getTotalProcessedPackets();
+                if (player == null) {
+                    log.log(Level.SEVERE, "Handling packet for player connection or ticking player connection (null player): " + packetListener);
+                    log.log(Level.SEVERE, "Total packets processed on the main thread for all players: " + totalPackets);
+                } else {
+                    this.dumpEntity(player);
+                    net.minecraft.world.entity.Entity vehicle = player.getVehicle();
+                    if (vehicle != null) {
+                        log.log(Level.SEVERE, "Detailing vehicle for above entity:");
+                        this.dumpEntity(vehicle);
+                    }
+                    log.log(Level.SEVERE, "Total packets processed on the main thread for all players: " + totalPackets);
+                }
+            } else {
+                log.log(Level.SEVERE, "Handling packet for connection: " + packetListener);
+            }
+        }
+    }
+    // Paper end - log detailed tick information
+
     private WatchdogThread(long timeoutTime, boolean restart)
     {
         super( "Paper Watchdog Thread" );
@@ -120,6 +192,7 @@ public final class WatchdogThread extends io.papermc.paper.util.TickThread // Pa
                 log.log( Level.SEVERE, "------------------------------" );
                 log.log( Level.SEVERE, "Server thread dump (Look for plugins here before reporting to Paper!):" ); // Paper
                 io.papermc.paper.chunk.system.scheduling.ChunkTaskScheduler.dumpAllChunkLoadInfo(isLongTimeout); // Paper // Paper - rewrite chunk system
+                this.dumpTickingInfo(); // Paper - log detailed tick information
                 WatchdogThread.dumpThread( ManagementFactory.getThreadMXBean().getThreadInfo( MinecraftServer.getServer().serverThread.getId(), Integer.MAX_VALUE ), log );
                 log.log( Level.SEVERE, "------------------------------" );
                 //