Dynmap-Forge/Fabric

Dynmap-Forge/Fabric

Mods
888k Downloads

dynmap startup sometimes invokes the ire of ServerHangWatchdog

miiichael opened this issue · 4 comments

commented

Issue Description: Sometimes my server fails to start up due to what looks like dynmap hanging for more than a minute

[16Feb.2021 22:50:32.801] [Server thread/INFO] [Dynmap/]: [Dynmap] Added 77 custom biome mappings
[16Feb.2021 22:50:32.806] [Server thread/INFO] [Dynmap/]: [Dynmap] Using ops.txt for access control
[16Feb.2021 22:50:32.967] [Server thread/INFO] [Dynmap/]: [Dynmap] Opening SQLite file /srv/minecraft/cheshpack-1.16/dynmap/dynmap.sqlite as map store
[16Feb.2021 22:50:33.130] [Server thread/INFO] [Dynmap/]: [Dynmap] Register commands
[16Feb.2021 22:51:32.600] [Server Watchdog/FATAL] [net.minecraft.server.dedicated.ServerHangWatchdog/]: A single server tick took 60.00 seconds (should be max 0.05)
[16Feb.2021 22:51:32.601] [Server Watchdog/FATAL] [net.minecraft.server.dedicated.ServerHangWatchdog/]: Considering it to be crashed, server will forcibly shutdown.
[16Feb.2021 22:51:33.632] [Server Watchdog/FATAL] [net.minecraftforge.common.ForgeMod/]: Preparing crash report with UUID c34b5c87-2a68-4aa1-bec5-f80417068057

When it succeeds, the log looks like:

[16Feb.2021 23:06:39.568] [Server thread/INFO] [Dynmap/]: [Dynmap] Added 77 custom biome mappings
[16Feb.2021 23:06:39.572] [Server thread/INFO] [Dynmap/]: [Dynmap] Using ops.txt for access control
[16Feb.2021 23:06:39.713] [Server thread/INFO] [Dynmap/]: [Dynmap] Opening SQLite file /srv/minecraft/cheshpack-1.16/dynmap/dynmap.sqlite as map store
[16Feb.2021 23:06:39.842] [Server thread/INFO] [Dynmap/]: [Dynmap] Register commands
[16Feb.2021 23:07:35.955] [Server thread/INFO] [Dynmap/]: [Dynmap] Found cwebp at /usr/bin/cwebp and dwebp at /usr/bin/dwebp: webp format enabled
[16Feb.2021 23:07:35.957] [Server thread/INFO] [Dynmap/]: [Dynmap] Mod Support processing completed
[16Feb.2021 23:07:36.796] [Server thread/INFO] [Dynmap/]: [Dynmap] Loaded 25 shaders.
[16Feb.2021 23:07:36.836] [Server thread/INFO] [Dynmap/]: [Dynmap] Loaded 82 perspectives.
[16Feb.2021 23:07:36.850] [Server thread/INFO] [Dynmap/]: [Dynmap] Loaded 22 lightings.
[16Feb.2021 23:07:36.861] [Server thread/INFO] [Dynmap/]: [Dynmap] Starting enter/exit processing

(and continues on its merry way)

  • Steps to Replicate: Um, create server, try to start it? Rather than just pave over it by bumping max-tick-time, I thought I'd report it here.

[✔️] I have looked at all other issues and this is not a duplicate
[✔️] I have been able to replicate this

commented

linked: #3278

I have the same issue as "When it fails" above, posted my log in the linked thread - however it happens to me on every single launch, I have never had a success with this modpack so gave up for now

same issue; forge 1.16.5

[13:53:52] [Server thread/INFO] [minecraft/LoggingChunkStatusListener]: Preparing spawn area: 0%
[13:53:52] [Server thread/INFO] [minecraft/LoggingChunkStatusListener]: Time elapsed: 2660 ms
[13:53:52] [Server thread/INFO] [minecraft/DedicatedServer]: Done (3.661s)! For help, type "help"
[13:53:53] [Server thread/INFO] [co.po.ex.Extlights/]: HELLO from server starting
[13:53:53] [Server thread/INFO] [co.po.ne.NeonCraft/]: HELLO from server starting
[13:53:53] [Server thread/INFO] [Dynmap/]: [Dynmap] Added 94 custom biome mappings
[13:53:53] [Server thread/INFO] [Dynmap/]: [Dynmap] Using ops.txt for access control
[13:53:53] [Server thread/FATAL] [Dynmap/]: [Dynmap] Error reading dynmap\markers.yml
[13:53:53] [Server thread/INFO] [Dynmap/]: [Dynmap] Register commands
[13:53:53] [Server thread/INFO] [Astral Sorcery/]: Loaded PerkTree!
[13:54:52] [Server Watchdog/FATAL] [minecraft/ServerHangWatchdog]: A single server tick took 60.00 seconds (should be max 0.05)
[13:54:52] [Server Watchdog/FATAL] [minecraft/ServerHangWatchdog]: Considering it to be crashed, server will forcibly shutdown.
[13:54:53] [Server Watchdog/FATAL] [ne.mi.co.ForgeMod/]: Preparing crash report with UUID f721ab46-64b9-4fa4-95b5-b5202c4a9a5c

Modpack: Valhelsia 3

commented

I get this same error except with FTB Endeavour, every single time.

commented

After adding a couple of mods to my pack, dynmap startup time has gone from 60 to 90 seconds:

[03Mar.2021 20:00:29.520] [Server thread/INFO] [Dynmap/]: [Dynmap] Using permissions.yml for access control
[03Mar.2021 20:00:29.732] [Server thread/INFO] [Dynmap/]: [Dynmap] Opening SQLite file /srv/minecraft/cheshpack-1.16-test/dynmap/dynmap.sqlite as map store
[03Mar.2021 20:00:29.851] [Server thread/INFO] [Dynmap/]: [Dynmap] Register commands
[03Mar.2021 20:02:04.440] [Server thread/INFO] [Dynmap/]: [Dynmap] Extracted files upgraded
[03Mar.2021 20:02:04.445] [Server thread/INFO] [Dynmap/]: [Dynmap] Found cwebp at /usr/bin/cwebp and dwebp at /usr/bin/dwebp: webp format enabled
[03Mar.2021 20:02:04.448] [Server thread/INFO] [Dynmap/]: [Dynmap] Mod Support processing completed
[03Mar.2021 20:02:05.212] [Server thread/WARN] [Dynmap/]: [Dynmap] Blocks missing texture definition:
[snip]

Given that every server startup failure has nearly always in the same line of code:

java.lang.Error: ServerHangWatchdog detected that a single server tick took 60.35 seconds (should be max 0.05)
	at java.util.Arrays.copyOf(Arrays.java:3689) ~[?:?] {}
	at org.dynmap.forge_1_16_3.DynmapPlugin.initializeBlockStates(DynmapPlugin.java:242) ~[dynmap:?] {re:classloading}
--
java.lang.Error: ServerHangWatchdog detected that a single server tick took 60.00 seconds (should be max 0.05)
	at org.dynmap.forge_1_16_3.DynmapPlugin.initializeBlockStates(DynmapPlugin.java:289) ~[dynmap:?] {re:classloading}
	at org.dynmap.forge_1_16_3.DynmapPlugin.onStart(DynmapPlugin.java:1528) ~[dynmap:?] {re:classloading}
--
java.lang.Error: ServerHangWatchdog detected that a single server tick took 60.02 seconds (should be max 0.05)
	at java.util.Arrays.copyOf(Arrays.java:3689) ~[?:?] {}
	at org.dynmap.forge_1_16_3.DynmapPlugin.initializeBlockStates(DynmapPlugin.java:242) ~[dynmap:?] {re:classloading}
--
java.lang.Error: ServerHangWatchdog detected that a single server tick took 65.12 seconds (should be max 0.05)
	at java.util.Arrays.copyOf(Arrays.java:3689) ~[?:?] {}
	at org.dynmap.forge_1_16_5.DynmapPlugin.initializeBlockStates(DynmapPlugin.java:242) ~[dynmap:?] {re:classloading}
--
java.lang.Error: ServerHangWatchdog detected that a single server tick took 65.00 seconds (should be max 0.05)
	at java.util.Arrays.copyOf(Arrays.java:3689) ~[?:?] {}
	at org.dynmap.forge_1_16_5.DynmapPlugin.initializeBlockStates(DynmapPlugin.java:242) ~[dynmap:?] {re:classloading}
--
java.lang.Error: ServerHangWatchdog detected that a single server tick took 75.00 seconds (should be max 0.05)
	at java.util.Arrays.copyOf(Arrays.java:3689) ~[?:?] {}
	at org.dynmap.forge_1_16_5.DynmapPlugin.initializeBlockStates(DynmapPlugin.java:242) ~[dynmap:?] {re:classloading}

I'm not a Java programmer, but I'm inclined to think the issue is the choice of an O(n²) array expansion algorithm. (Also, wow, that indenting... 😅)

commented

The above patch took dynmap blockstate initialisation on my server from 6 minutes:

[06Mar.2021 17:40:46.357] [Server thread/INFO] [Dynmap/]: [Dynmap] Using permissions.yml for access control
[06Mar.2021 17:40:46.411] [Server thread/INFO] [Dynmap/]: [Dynmap] Opening SQLite file /srv/minecraft/cheshpack-1.16-test/dynmap/dynmap.sqlite as map store
[06Mar.2021 17:40:46.484] [Server thread/INFO] [Dynmap/]: [Dynmap] Register commands
[06Mar.2021 17:46:54.008] [Server thread/INFO] [Dynmap/]: [Dynmap] Found cwebp at /usr/bin/cwebp and dwebp at /usr/bin/dwebp: webp format enabled
[06Mar.2021 17:46:54.010] [Server thread/INFO] [Dynmap/]: [Dynmap] Mod Support processing completed
[06Mar.2021 17:46:54.703] [Server thread/WARN] [Dynmap/]: [Dynmap] Blocks missing texture definition:

down to three seconds:

[06Mar.2021 20:02:14.229] [Server thread/INFO] [Dynmap/]: [Dynmap] Using permissions.yml for access control
[06Mar.2021 20:02:14.294] [Server thread/INFO] [Dynmap/]: [Dynmap] Opening SQLite file /srv/minecraft/cheshpack-1.16-test/dynmap/dynmap.sqlite as map store
[06Mar.2021 20:02:14.373] [Server thread/INFO] [Dynmap/]: [Dynmap] Register commands
[06Mar.2021 20:02:14.538] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 16384 to 18022
[06Mar.2021 20:02:14.554] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 18022 to 19824
[06Mar.2021 20:02:14.561] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 19824 to 21806
[06Mar.2021 20:02:14.571] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 21806 to 23986
[06Mar.2021 20:02:14.578] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 23986 to 26384
[06Mar.2021 20:02:14.586] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 26384 to 29022
[06Mar.2021 20:02:14.598] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 29022 to 31924
[06Mar.2021 20:02:14.610] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 31924 to 35116
[06Mar.2021 20:02:14.623] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 35116 to 38627
[06Mar.2021 20:02:14.638] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 38627 to 42489
[06Mar.2021 20:02:14.670] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 42489 to 46737
[06Mar.2021 20:02:14.699] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 46737 to 51410
[06Mar.2021 20:02:14.861] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 51410 to 56551
[06Mar.2021 20:02:14.906] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 56551 to 62206
[06Mar.2021 20:02:14.928] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 62206 to 68426
[06Mar.2021 20:02:14.953] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 68426 to 75268
[06Mar.2021 20:02:14.980] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 75268 to 82794
[06Mar.2021 20:02:15.013] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 82794 to 91073
[06Mar.2021 20:02:15.050] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 91073 to 100180
[06Mar.2021 20:02:15.094] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 100180 to 110198
[06Mar.2021 20:02:15.137] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 110198 to 121217
[06Mar.2021 20:02:15.185] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 121217 to 133338
[06Mar.2021 20:02:15.236] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 133338 to 146671
[06Mar.2021 20:02:15.298] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 146671 to 161338
[06Mar.2021 20:02:15.369] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 161338 to 177471
[06Mar.2021 20:02:15.423] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 177471 to 195218
[06Mar.2021 20:02:15.466] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 195218 to 214739
[06Mar.2021 20:02:15.532] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 214739 to 236212
[06Mar.2021 20:02:15.606] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 236212 to 259833
[06Mar.2021 20:02:15.679] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 259833 to 285816
[06Mar.2021 20:02:15.935] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 285816 to 314397
[06Mar.2021 20:02:16.019] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 314397 to 345836
[06Mar.2021 20:02:16.129] [Server thread/INFO] [Dynmap/]: [Dynmap] Resized stateByID from 345836 to 380419
[06Mar.2021 20:02:16.295] [Server thread/INFO] [Dynmap/]: [Dynmap] Extracted files upgraded
[06Mar.2021 20:02:16.299] [Server thread/INFO] [Dynmap/]: [Dynmap] Found cwebp at /usr/bin/cwebp and dwebp at /usr/bin/dwebp: webp format enabled
[06Mar.2021 20:02:16.301] [Server thread/INFO] [Dynmap/]: [Dynmap] Mod Support processing completed
[06Mar.2021 20:02:17.099] [Server thread/WARN] [Dynmap/]: [Dynmap] Blocks missing texture definition: