From 2f48e58760d9e8f2e19c16e04ba6127567d8f368 Mon Sep 17 00:00:00 2001 From: miclebrick Date: Wed, 8 Aug 2018 15:30:52 -0400 Subject: [PATCH] Add Early Warning Feature to WatchDog Detect when the server has been hung for a long duration, and start printing thread dumps at an interval until the point of crash. This will help diagnose what was going on in that time before the crash. diff --git a/src/main/java/com/destroystokyo/paper/PaperConfig.java b/src/main/java/com/destroystokyo/paper/PaperConfig.java index a92914576..f3f2a0b69 100644 --- a/src/main/java/com/destroystokyo/paper/PaperConfig.java +++ b/src/main/java/com/destroystokyo/paper/PaperConfig.java @@ -25,6 +25,7 @@ import org.bukkit.configuration.file.YamlConfiguration; import co.aikar.timings.Timings; import co.aikar.timings.TimingsManager; import org.spigotmc.SpigotConfig; +import org.spigotmc.WatchdogThread; public class PaperConfig { @@ -333,6 +334,14 @@ public class PaperConfig { } } + public static int watchdogPrintEarlyWarningEvery = 5000; + public static int watchdogPrintEarlyWarningDelay = 10000; + private static void watchdogEarlyWarning() { + watchdogPrintEarlyWarningEvery = getInt("settings.watchdog.early-warning-every", 5000); + watchdogPrintEarlyWarningDelay = getInt("settings.watchdog.early-warning-delay", 10000); + WatchdogThread.doStart(SpigotConfig.timeoutTime, SpigotConfig.restartOnCrash ); + } + public static int tabSpamIncrement = 1; public static int tabSpamLimit = 500; private static void tabSpamLimiters() { diff --git a/src/main/java/net/minecraft/server/MinecraftServer.java b/src/main/java/net/minecraft/server/MinecraftServer.java index c3efb5e1b..ca72e6ad1 100644 --- a/src/main/java/net/minecraft/server/MinecraftServer.java +++ b/src/main/java/net/minecraft/server/MinecraftServer.java @@ -796,6 +796,7 @@ public abstract class MinecraftServer implements IAsyncTaskHandler, IMojangStati this.a(this.m); // Spigot start + org.spigotmc.WatchdogThread.hasStarted = true; // Paper Arrays.fill( recentTps, 20 ); long start = System.nanoTime(), curTime, wait, tickSection = start; // Paper - Further improve server tick loop lastTick = start - TICK_TIME; // Paper diff --git a/src/main/java/org/bukkit/craftbukkit/CraftServer.java b/src/main/java/org/bukkit/craftbukkit/CraftServer.java index 71d1929c1..93a8f4cdf 100644 --- a/src/main/java/org/bukkit/craftbukkit/CraftServer.java +++ b/src/main/java/org/bukkit/craftbukkit/CraftServer.java @@ -750,6 +750,7 @@ public final class CraftServer implements Server { @Override public void reload() { + org.spigotmc.WatchdogThread.hasStarted = false; // Paper - Disable watchdog early timeout on reload reloadCount++; configuration = YamlConfiguration.loadConfiguration(getConfigFile()); commandsConfiguration = YamlConfiguration.loadConfiguration(getCommandsConfigFile()); @@ -855,6 +856,7 @@ public final class CraftServer implements Server { enablePlugins(PluginLoadOrder.STARTUP); enablePlugins(PluginLoadOrder.POSTWORLD); getPluginManager().callEvent(new ServerLoadEvent(ServerLoadEvent.LoadType.RELOAD)); + org.spigotmc.WatchdogThread.hasStarted = true; // Paper - Disable watchdog early timeout on reload } @Override diff --git a/src/main/java/org/spigotmc/SpigotConfig.java b/src/main/java/org/spigotmc/SpigotConfig.java index eed96c60c..496c5cbdf 100644 --- a/src/main/java/org/spigotmc/SpigotConfig.java +++ b/src/main/java/org/spigotmc/SpigotConfig.java @@ -226,7 +226,7 @@ public class SpigotConfig restartScript = getString( "settings.restart-script", restartScript ); restartMessage = transform( getString( "messages.restart", "Server is restarting" ) ); commands.put( "restart", new RestartCommand( "restart" ) ); - WatchdogThread.doStart( timeoutTime, restartOnCrash ); + //WatchdogThread.doStart( timeoutTime, restartOnCrash ); // Paper - moved to PaperConfig } public static boolean bungee; diff --git a/src/main/java/org/spigotmc/WatchdogThread.java b/src/main/java/org/spigotmc/WatchdogThread.java index ed5f46bf6..9dba9510f 100644 --- a/src/main/java/org/spigotmc/WatchdogThread.java +++ b/src/main/java/org/spigotmc/WatchdogThread.java @@ -5,6 +5,7 @@ import java.lang.management.MonitorInfo; import java.lang.management.ThreadInfo; import java.util.logging.Level; import java.util.logging.Logger; +import com.destroystokyo.paper.PaperConfig; import net.minecraft.server.MinecraftServer; import org.bukkit.Bukkit; @@ -13,6 +14,10 @@ public class WatchdogThread extends Thread private static WatchdogThread instance; private final long timeoutTime; + private final long earlyWarningEvery; // Paper - Timeout time for just printing a dump but not restarting + private final long earlyWarningDelay; // Paper + public static volatile boolean hasStarted; // Paper + private long lastEarlyWarning; // Paper - Keep track of short dump times to avoid spamming console with short dumps private final boolean restart; private volatile long lastTick; private volatile boolean stopping; @@ -22,6 +27,8 @@ public class WatchdogThread extends Thread super( "Paper Watchdog Thread" ); this.timeoutTime = timeoutTime; this.restart = restart; + earlyWarningEvery = Math.min(PaperConfig.watchdogPrintEarlyWarningEvery, timeoutTime); // Paper + earlyWarningDelay = Math.min(PaperConfig.watchdogPrintEarlyWarningDelay, timeoutTime); // Paper } private static long monotonicMillis() @@ -56,10 +63,17 @@ public class WatchdogThread extends Thread { while ( !stopping ) { - // - if ( lastTick != 0 && monotonicMillis() > lastTick + timeoutTime && !Boolean.getBoolean("disable.watchdog")) // Paper - Add property to disable + // Paper start + Logger log = Bukkit.getServer().getLogger(); + long currentTime = monotonicMillis(); + if ( lastTick != 0 && currentTime > lastTick + earlyWarningEvery && !Boolean.getBoolean("disable.watchdog") ) { - Logger log = Bukkit.getServer().getLogger(); + boolean isLongTimeout = currentTime > lastTick + timeoutTime; + // Don't spam early warning dumps + if ( !isLongTimeout && (earlyWarningEvery <= 0 || !hasStarted || currentTime < lastEarlyWarning + earlyWarningEvery || currentTime < lastTick + earlyWarningDelay)) continue; + lastEarlyWarning = currentTime; + if (isLongTimeout) { + // Paper end log.log( Level.SEVERE, "------------------------------" ); log.log( Level.SEVERE, "The server has stopped responding! This is (probably) not a Paper bug." ); // Paper log.log( Level.SEVERE, "If you see a plugin in the Server thread dump below, then please report it to that author" ); @@ -89,29 +103,46 @@ public class WatchdogThread extends Thread } } // Paper end + } else + { + log.log(Level.SEVERE, "--- DO NOT REPORT THIS TO PAPER - THIS IS NOT A BUG OR A CRASH - " + Bukkit.getServer().getVersion() + " ---"); + log.log(Level.SEVERE, "The server has not responded for " + (currentTime - lastTick) / 1000 + " seconds! Creating thread dump"); + } + // Paper end - Different message for short timeout log.log( Level.SEVERE, "------------------------------" ); log.log( Level.SEVERE, "Server thread dump (Look for plugins here before reporting to Paper!):" ); dumpThread( ManagementFactory.getThreadMXBean().getThreadInfo( MinecraftServer.getServer().primaryThread.getId(), Integer.MAX_VALUE ), log ); log.log( Level.SEVERE, "------------------------------" ); // + // Paper start - Only print full dump on long timeouts + if ( isLongTimeout ) + { log.log( Level.SEVERE, "Entire Thread Dump:" ); ThreadInfo[] threads = ManagementFactory.getThreadMXBean().dumpAllThreads( true, true ); for ( ThreadInfo thread : threads ) { dumpThread( thread, log ); } + } else { + log.log(Level.SEVERE, "--- DO NOT REPORT THIS TO PAPER - THIS IS NOT A BUG OR A CRASH ---"); + } + + log.log( Level.SEVERE, "------------------------------" ); + if ( isLongTimeout ) + { if ( restart ) { RestartCommand.restart(); } break; + } // Paper end } try { - sleep( 10000 ); + sleep( 1000 ); // Paper - Reduce check time to every second instead of every ten seconds, more consistent and allows for short timeout } catch ( InterruptedException ex ) { interrupt(); -- 2.20.0