Sponge crash

[forresthopkinsa]

Describe the issue

Server spontaneously crashed due to tick time exceeding 60 seconds. Not clear what caused it or how to repro.

Server information

• SpongeForge version: 1.12.2-2838-7.3.0

• Forge version: 14.23.5.2838

• Java version: 1.8.0_272

• Operating System: Ubuntu Server 20.04 "Focal"

• Mods (79): Minecraft, Minecraft Coder Pack, Forge Mod Loader, Minecraft Forge, SpongeAPI, Sponge, AppleCore, Astral Sorcery, AutoRegLib, Baubles, Biomes O' Plenty, Blockcraftery, CD4017BE_lib, Chameleon, CoFH Core, CoFH World, CodeChicken Lib, Construct's Armory, Cooking for Blockheads, DarknessLib, Davinci's Vessels, Dynamic Surroundings, Dynamic Trees, Dynamic Trees BOP, Dynamic Trees PHC, Dynamic Trees TC, Dynamic Trees for Natura, Dynamic Trees for Quark, Dynamic Trees for The Aether Legacy, Dynamic Trees for Tinkers Construct, Grue, Hunger Overhaul, Ice and Fire, Immersive Cables, Immersive Engineering, Inventory Tweaks, Just Enough Items, LLibrary, LibraryEx, Mantle, Mo' Bends, Moving World, MovingWorld CORE, Mystical Lib, Natura, NetherEx, OreLib Support Mod, Pam's HarvestCraft, PortalGun, Quark, Railcraft, RandomPatches, Redstone Flux, Refined Storage, Rustic, Serene Seasons, Shadowfacts' Forgelin, SpongeForge, Storage Drawers, Storage Drawers Extras, Thaumcraft, The Aether, The Beneath, Thermal Dynamics, Thermal Expansion, Thermal Foundation, Tinker's Aether, Tinker's JEI, Tinkers' Construct, Tumbleweed, UniDict, Vertically Stacked Dimensions, Waila, WanionLib, Xaero's Minimap, XaeroMinimapCore, YUNG's Better Caves, YUNG's Better Mineshafts, iChunUtil

• Plugins (7): Minecraft, Minecraft Coder Pack, SpongeAPI, Sponge, LuckPerms, Nucleus, Plan

Exceptions & Other Logs

Log snip:

Time: 11/4/20 10:41 PM
Description: Watching Server

java.lang.Error: ServerHangWatchdog detected that a single server tick took 60.00 seconds (should be max 0.05)
    at java.io.FileOutputStream.close0(Native Method)
    at java.io.FileOutputStream.access$000(FileOutputStream.java:53)
    at java.io.FileOutputStream$1.close(FileOutputStream.java:356)
    at java.io.FileDescriptor.closeAll(FileDescriptor.java:212)
    at java.io.FileOutputStream.close(FileOutputStream.java:354)
    at org.apache.commons.io.FileUtils.writeStringToFile(FileUtils.java:1983)
    at org.apache.commons.io.FileUtils.writeStringToFile(FileUtils.java:2017)
    at net.minecraft.stats.StatisticsManagerServer.func_150883_b(SourceFile:52)
    at net.minecraft.server.management.PlayerList.func_72391_b(PlayerList.java:353)
    at net.minecraft.server.management.PlayerList.func_72389_g(PlayerList.java:943)
    at net.minecraft.server.MinecraftServer.constant$zjg000$getSaveTickInterval(MinecraftServer.java:4566)
    at net.minecraft.server.MinecraftServer.func_71217_p(MinecraftServer.java:687)
    at net.minecraft.server.MinecraftServer.run(MinecraftServer.java:526)
    at java.lang.Thread.run(Thread.java:748)

-- Head --
Thread: Server Watchdog
Stacktrace:
    at java.io.FileOutputStream.close0(Native Method)
    at java.io.FileOutputStream.access$000(FileOutputStream.java:53)
    at java.io.FileOutputStream$1.close(FileOutputStream.java:356)
    at java.io.FileDescriptor.closeAll(FileDescriptor.java:212)
    at java.io.FileOutputStream.close(FileOutputStream.java:354)
    at org.apache.commons.io.FileUtils.writeStringToFile(FileUtils.java:1983)
    at org.apache.commons.io.FileUtils.writeStringToFile(FileUtils.java:2017)
    at net.minecraft.stats.StatisticsManagerServer.func_150883_b(SourceFile:52)
    at net.minecraft.server.management.PlayerList.func_72391_b(PlayerList.java:353)

-- Sponge PhaseTracker --
Details:
    Phase Stack: [Empty stack]
Stacktrace:
    at net.minecraft.server.MinecraftServer.handler$zjg000$onCrashReport(MinecraftServer.java:4687)
    at net.minecraft.server.MinecraftServer.func_71230_b(MinecraftServer.java:889)
    at net.minecraft.server.dedicated.DedicatedServer.func_71230_b(DedicatedServer.java:371)
    at net.minecraft.server.dedicated.ServerHangWatchdog.run(ServerHangWatchdog.java:61)
    at java.lang.Thread.run(Thread.java:748)

-- Thread Dump --
Details:
    Threads: "pool-3-thread-46" Id=193 TIMED_WAITING on java.util.concurrent.SynchronousQueue$TransferStack@15f47a00
    at sun.misc.Unsafe.park(Native Method)
    -  waiting on java.util.concurrent.SynchronousQueue$TransferStack@15f47a00
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
    at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
    at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:941)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    ...

"pool-3-thread-45" Id=192 TIMED_WAITING on java.util.concurrent.SynchronousQueue$TransferStack@15f47a00
    at sun.misc.Unsafe.park(Native Method)
    -  waiting on java.util.concurrent.SynchronousQueue$TransferStack@15f47a00
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
    at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
    at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:941)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1073)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    ...

"pool-3-thread-44" Id=191 BLOCKED on org.sqlite.core.NativeDB@1b3386ce owned by "Plan SQLiteDB-transaction-thread-1" Id=75
    at org.sqlite.core.DB.prepare(DB.java:221)
    -  blocked on org.sqlite.core.NativeDB@1b3386ce
    at org.sqlite.jdbc3.JDBC3Statement.executeQuery(JDBC3Statement.java:81)
    at com.djrapitops.plan.storage.upkeep.DBKeepAliveTask.run(DBKeepAliveTask.java:56)
    at com.djrapitops.plugin.task.sponge.SpongeRunnableFactory$1.run(SpongeRunnableFactory.java:57)
    at org.spongepowered.api.scheduler.Task$Builder.lambda$execute$0(Task.java:139)
    at org.spongepowered.api.scheduler.Task$Builder$$Lambda$686/1001239446.accept(Unknown Source)
    at org.spongepowered.common.scheduler.SchedulerBase.lambda$startTask$0(SchedulerBase.java:197)
    at org.spongepowered.common.scheduler.SchedulerBase$$Lambda$846/436577375.run(Unknown Source)
    ...

    Number of locked synchronizers = 1
    - java.util.concurrent.ThreadPoolExecutor$Worker@658b2764

Full log:

https://gist.github.com/forresthopkinsa/b9960a2a9b190b6110b76ec86ace5b05

[AuroraLS3]

To me this does not seem to be Plan related. On Sponge Plan only reads tps & entity count on the server thread, which doesn't take this long (It is a in-memory operation, and something blocking server thread for 60 seconds has to be IO, or disk operation).

"Server thread" Id=18 RUNNABLE (in native)
    at java.io.FileOutputStream.close0(Native Method)
    at java.io.FileOutputStream.access$000(FileOutputStream.java:53)
    at java.io.FileOutputStream$1.close(FileOutputStream.java:356)
    at java.io.FileDescriptor.closeAll(FileDescriptor.java:212)
    -  locked java.io.FileDescriptor@182194c1
    at java.io.FileOutputStream.close(FileOutputStream.java:354)
    at org.apache.commons.io.FileUtils.writeStringToFile(FileUtils.java:1983)
    at org.apache.commons.io.FileUtils.writeStringToFile(FileUtils.java:2017)
    at net.minecraft.stats.StatisticsManagerServer.func_150883_b(SourceFile:52)
    ...

Your server thread was performing IO writing a statistic on disk or something (I don't know what it is doing)

Plan is running database IO on a non-server thread, and that's why that thread says BLOCKED - it does not block the server thread.

---

To clear up some misconceptions, a deadlock occurs when two threads are trying to reserve two things but only manage to get one of them at the same time. In case of databases this occurs when two transactions are trying to write to two tables at the same time. In Plan SQLite transactions are executed on a single thread so a deadlock should never occur with SQLite (Unless some other process is writing the Plan database file at the same time).