From 0000000000000000000000000000000000000000 Mon Sep 17 00:00:00 2001 From: Spottedleaf 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/io/papermc/paper/FeatureHooks.java b/io/papermc/paper/FeatureHooks.java index d3aebc7f833764351c8e5fe1fad1aa2f8718ca37..5a561c8f48f4b5f7a3077c21f5ddd19cbcaa6aac 100644 --- a/io/papermc/paper/FeatureHooks.java +++ b/io/papermc/paper/FeatureHooks.java @@ -83,8 +83,72 @@ public final class FeatureHooks { } public static void dumpTickingInfo() { + java.util.logging.Logger log = org.bukkit.Bukkit.getServer().getLogger(); + + // ticking entities + for (net.minecraft.world.entity.Entity entity : net.minecraft.server.level.ServerLevel.getCurrentlyTickingEntities()) { + dumpEntity(entity); + net.minecraft.world.entity.Entity vehicle = entity.getVehicle(); + if (vehicle != null) { + log.log(java.util.logging.Level.SEVERE, "Detailing vehicle for above entity:"); + 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(java.util.logging.Level.SEVERE, "Handling packet for player connection or ticking player connection (null player): " + packetListener); + log.log(java.util.logging.Level.SEVERE, "Total packets processed on the main thread for all players: " + totalPackets); + } else { + dumpEntity(player); + net.minecraft.world.entity.Entity vehicle = player.getVehicle(); + if (vehicle != null) { + log.log(java.util.logging.Level.SEVERE, "Detailing vehicle for above entity:"); + dumpEntity(vehicle); + } + log.log(java.util.logging.Level.SEVERE, "Total packets processed on the main thread for all players: " + totalPackets); + } + } else { + log.log(java.util.logging.Level.SEVERE, "Handling packet for connection: " + packetListener); + } + } } private static void dumpEntity(final Entity entity) { + java.util.logging.Logger log = org.bukkit.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(java.util.logging.Level.SEVERE, "Ticking entity: " + entityType + ", entity class: " + entity.getClass().getName()); + log.log(java.util.logging.Level.SEVERE, "Entity status: removed: " + entity.isRemoved() + ", valid: " + entity.valid + ", alive: " + entity.isAlive() + ", is passenger: " + entity.isPassenger()); + log.log(java.util.logging.Level.SEVERE, "Entity UUID: " + entityUUID); + log.log(java.util.logging.Level.SEVERE, "Position: world: '" + (world == null ? "unknown world?" : world.getWorld().getName()) + "' at location (" + posX + ", " + posY + ", " + posZ + ")"); + log.log(java.util.logging.Level.SEVERE, "Velocity: " + (mot == null ? "unknown velocity" : mot.toString()) + " (in blocks per tick)"); + log.log(java.util.logging.Level.SEVERE, "Entity AABB: " + entity.getBoundingBox()); + if (moveVec != null) { + log.log(java.util.logging.Level.SEVERE, "Move call information: "); + log.log(java.util.logging.Level.SEVERE, "Start position: (" + moveStartX + ", " + moveStartY + ", " + moveStartZ + ")"); + log.log(java.util.logging.Level.SEVERE, "Move vector: " + moveVec.toString()); + } } -} \ No newline at end of file +} diff --git a/net/minecraft/network/Connection.java b/net/minecraft/network/Connection.java index 8fe485c5bf79804bb4d1f774f95a92b14a576e80..0bcae6256d3b3fb6b2e0c2f23907d4659b236ef3 100644 --- a/net/minecraft/network/Connection.java +++ b/net/minecraft/network/Connection.java @@ -603,7 +603,13 @@ public class Connection extends SimpleChannelInboundHandler> { if (!(this.packetListener instanceof net.minecraft.server.network.ServerLoginPacketListenerImpl loginPacketListener) || loginPacketListener.state != net.minecraft.server.network.ServerLoginPacketListenerImpl.State.VERIFYING || Connection.joinAttemptsThisTick++ < MAX_PER_TICK) { + // Paper start - detailed watchdog information + net.minecraft.network.protocol.PacketUtils.packetProcessing.push(this.packetListener); + try { tickablePacketListener.tick(); + } finally { + net.minecraft.network.protocol.PacketUtils.packetProcessing.pop(); + } // Paper end - detailed watchdog information } // Paper end - Buffer joins to world } diff --git a/net/minecraft/network/protocol/PacketUtils.java b/net/minecraft/network/protocol/PacketUtils.java index e65c62dbe4c1560ae153e4c4344e9194c783a2f4..4535858701b2bb232b9d2feb2af6551526232ddc 100644 --- a/net/minecraft/network/protocol/PacketUtils.java +++ b/net/minecraft/network/protocol/PacketUtils.java @@ -21,6 +21,8 @@ public class PacketUtils { public static void ensureRunningOnSameThread(Packet packet, T processor, BlockableEventLoop executor) throws RunningOnDifferentThreadException { if (!executor.isSameThread()) { executor.executeIfPossible(() -> { + packetProcessing.push(processor); // Paper - detailed watchdog information + try { // Paper - detailed watchdog information if (processor instanceof net.minecraft.server.network.ServerCommonPacketListenerImpl serverCommonPacketListener && serverCommonPacketListener.processedDisconnect) return; // Paper - Don't handle sync packets for kicked players if (processor.shouldHandleMessage(packet)) { try { @@ -35,6 +37,12 @@ public class PacketUtils { } else { 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; } @@ -61,4 +69,22 @@ public class PacketUtils { packetListener.fillCrashReport(crashReport); } + + // Paper start - detailed watchdog information + public static final java.util.concurrent.ConcurrentLinkedDeque 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 getCurrentPacketProcessors() { + java.util.List listeners = new java.util.ArrayList<>(4); + for (PacketListener listener : packetProcessing) { + listeners.add(listener); + } + + return listeners; + } + // Paper end - detailed watchdog information } diff --git a/net/minecraft/server/level/ServerLevel.java b/net/minecraft/server/level/ServerLevel.java index 9cc47bda7197ca3f63b0ede9905c9a13931f84ed..05f45b490e823a455b23b23b26a7da3b447059ea 100644 --- a/net/minecraft/server/level/ServerLevel.java +++ b/net/minecraft/server/level/ServerLevel.java @@ -956,7 +956,26 @@ public class ServerLevel extends Level implements ServerEntityGetter, WorldGenLe } } + // Paper start - log detailed entity tick information + // TODO replace with varhandle + static final java.util.concurrent.atomic.AtomicReference currentlyTickingEntity = new java.util.concurrent.atomic.AtomicReference<>(); + + public static List getCurrentlyTickingEntities() { + Entity ticking = currentlyTickingEntity.get(); + List 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 + ca.spottedleaf.moonrise.common.util.TickThread.ensureTickThread("Cannot tick an entity off-main"); + try { + if (currentlyTickingEntity.get() == null) { + currentlyTickingEntity.lazySet(entity); + } + // Paper end - log detailed entity tick information entity.setOldPosAndRot(); ProfilerFiller profilerFiller = Profiler.get(); entity.tickCount++; @@ -972,6 +991,13 @@ public class ServerLevel extends Level implements ServerEntityGetter, WorldGenLe for (Entity entity1 : entity.getPassengers()) { this.tickPassenger(entity, entity1, isActive); // Paper - EAR 2 } + // 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 ridingEntity, Entity passengerEntity, final boolean isActive) { // Paper - EAR 2 diff --git a/net/minecraft/world/entity/Entity.java b/net/minecraft/world/entity/Entity.java index 5a67aa9f1fe103e5622ed6fa93bc4bc25ddbb688..1ff09959aa95d9822ccb6724bbb3f441c768511a 100644 --- a/net/minecraft/world/entity/Entity.java +++ b/net/minecraft/world/entity/Entity.java @@ -956,8 +956,43 @@ public abstract class Entity implements SyncedDataHolder, Nameable, EntityAccess 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 type, Vec3 movement) { final Vec3 originalMovement = movement; // Paper - Expose pre-collision velocity + // Paper start - detailed watchdog information + ca.spottedleaf.moonrise.common.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 { @@ -1075,6 +1110,13 @@ public abstract class Entity implements SyncedDataHolder, Nameable, EntityAccess profilerFiller.pop(); } } + // Paper start - detailed watchdog information + } finally { + synchronized (this.posLock) { // Paper + this.moveVector = null; + } // Paper + } + // Paper end - detailed watchdog information } private void applyMovementEmissionAndPlaySound(Entity.MovementEmission movementEmission, Vec3 movement, BlockPos pos, BlockState state) { @@ -4348,7 +4390,9 @@ public abstract class Entity implements SyncedDataHolder, Nameable, EntityAccess } public void setDeltaMovement(Vec3 deltaMovement) { + synchronized (this.posLock) { // Paper this.deltaMovement = deltaMovement; + } // Paper } public void addDeltaMovement(Vec3 addend) { @@ -4445,7 +4489,9 @@ public abstract class Entity implements SyncedDataHolder, Nameable, EntityAccess } // 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 floor = Mth.floor(x); int floor1 = Mth.floor(y); int floor2 = Mth.floor(z);