Frequent "Server Overloaded" messages on idle server.

[SeeJayEmm]

I have a Linux server running AoF 4 that up until a few days ago was running smoothly. There are only a small handful of players (4-5) and to the best of our knowledge there are no cpu expensive machines running. The server will frequently kick out "server overloaded" messages even when idle and no one is logged on.

Ubuntu 20.04.3 LTS, 4 cores, 16 GB of RAM. Linux minecraft 5.4.0-81-generic #91-Ubuntu SMP Thu Jul 15 19:09:17 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

openjdk 16.0.1 2021-04-20 OpenJDK Runtime Environment (build 16.0.1+9-Ubuntu-120.04) OpenJDK 64-Bit Server VM (build 16.0.1+9-Ubuntu-120.04, mixed mode, sharing)

While logged in I get lag spikes that rewind position and cause blocks to reappear. I also get moved too quickly messages.

[12:18:00] [Server thread/WARN]: Can't keep up! Is the server overloaded? Running 2074ms or 41 ticks behind
[12:18:06] [Server thread/WARN]: SeeJayEmm moved too quickly! -9.981105998469388,1.0,-0.40695045733152213

I've captures multiple /perf logs to try and figure out what's causing these lag spikes but I cannot find anything. The majority of the logs show "chunk_unload" taking up the majority of the time and under that "unspecified(1/1)". I'm hoping someone here can point me in the right direction to debug this as we would like to not lose our all our work on this world by starting over.

I've attached one of the perf logs. 2021-08-27_12_16_08-world-1_17_1.zip

Thanks

---- Minecraft Profiler Results ----
// Now with less numbers

Version: 1.17.1
Time span: 237 ms
Tick span: 1 ticks
// This is approximately 4.20 ticks per second. It should be 20 ticks per second

--- BEGIN PROFILE DUMP ---

[00] tick(1/1) - 98.56%/98.56%
[01] |   levels(1/1) - 99.39%/97.96%
[02] |   |   ServerLevel[world] minecraft:overworld(1/1) - 99.87%/97.83%
[03] |   |   |   tick(1/1) - 99.95%/97.78%
[04] |   |   |   |   chunkSource(1/1) - 92.37%/90.32%
[05] |   |   |   |   |   unload(1/1) - 97.87%/88.40%
[06] |   |   |   |   |   |   chunk_unload(1/1) - 99.93%/88.33%
[07] |   |   |   |   |   |   |   #chunkGenerate full 1/1
[07] |   |   |   |   |   |   |   #chunkGenerate carvers 5/5
[07] |   |   |   |   |   |   |   #chunkGenerate noise 5/5
[07] |   |   |   |   |   |   |   #chunkGenerate heightmaps 1/1
[07] |   |   |   |   |   |   |   #chunkGenerate structure_starts 51/51
[07] |   |   |   |   |   |   |   #chunkGenerate spawn 1/1
[07] |   |   |   |   |   |   |   #chunkGenerate structure_references 5/5
[07] |   |   |   |   |   |   |   #chunkGenerate light 1/1
[07] |   |   |   |   |   |   |   #runTask 181/181
[07] |   |   |   |   |   |   |   #chunkLoad 51/51
[07] |   |   |   |   |   |   |   #chunkGenerate features 3/3
[07] |   |   |   |   |   |   |   #chunkSave 1/1
[07] |   |   |   |   |   |   |   #chunkGenerate liquid_carvers 5/5
[07] |   |   |   |   |   |   |   #chunkGenerate biomes 5/5
[07] |   |   |   |   |   |   |   #chunkGenerate surface 5/5
[07] |   |   |   |   |   |   |   unspecified(1/1) - 99.69%/88.05%
[07] |   |   |   |   |   |   |   fabricServerChunkUnload(1/1) - 0.24%/0.21%
[08] |   |   |   |   |   |   |   |   net.fabricmc.fabric.impl.event.lifecycle.LifecycleEventsImpl$$Lambda$4782/0x00000008018b2220(1/1) - 95.59%/0.20%
[09] |   |   |   |   |   |   |   |   |   fabricServerBlockEntityUnload(39/39) - 86.29%/0.17%
[10] |   |   |   |   |   |   |   |   |   |   unspecified(39/39) - 52.29%/0.09%
[10] |   |   |   |   |   |   |   |   |   |   aztech.modern_industrialization.ModernIndustrialization$$Lambda$6033/0x0000000801b9f9a8(39/39) - 17.16%/0.03%
[10] |   |   |   |   |   |   |   |   |   |   net.fabricmc.fabric.impl.lookup.block.BlockApiCacheImpl$$Lambda$9439/0x0000000802007530(39/39) - 12.49%/0.02%
[10] |   |   |   |   |   |   |   |   |   |   io.github.lucaargolo.lifts.Lifts$$Lambda$4954/0x000000080190b5b8(39/39) - 9.52%/0.02%
[10] |   |   |   |   |   |   |   |   |   |   reborncore.RebornCore$$Lambda$5251/0x0000000801a6d250(39/39) - 8.53%/0.01%
[09] |   |   |   |   |   |   |   |   |   unspecified(1/1) - 13.71%/0.03%
[08] |   |   |   |   |   |   |   |   aztech.modern_industrialization.machines.multiblocks.world.ChunkEventListeners$$Lambda$6032/0x0000000801b9f788(1/1) - 1.98%/0.00%
[08] |   |   |   |   |   |   |   |   unspecified(1/1) - 1.57%/0.00%
[08] |   |   |   |   |   |   |   |   net.fabricmc.fabric.impl.event.lifecycle.LifecycleEventsImpl$$Lambda$4781/0x00000008018b2000(1/1) - 0.85%/0.00%
[07] |   |   |   |   |   |   |   fabricServerBlockEntityLoad(39/39) - 0.07%/0.06%
[08] |   |   |   |   |   |   |   |   unspecified(39/39) - 54.73%/0.03%
[08] |   |   |   |   |   |   |   |   net.fabricmc.fabric.impl.lookup.block.BlockApiCacheImpl$$Lambda$9438/0x0000000802007310(39/39) - 26.29%/0.02%
[08] |   |   |   |   |   |   |   |   me.steven.indrev.networks.NetworkEvents(39/39) - 18.98%/0.01%
[07] |   |   |   |   |   |   |   fabricServerChunkLoad(1/1) - 0.01%/0.01%
[08] |   |   |   |   |   |   |   |   unspecified(1/1) - 44.28%/0.00%
[08] |   |   |   |   |   |   |   |   net.fabricmc.fabric.impl.event.lifecycle.LifecycleEventsImpl$$Lambda$4780/0x00000008018b7d08(1/1) - 31.11%/0.00%
[08] |   |   |   |   |   |   |   |   aztech.modern_industrialization.machines.multiblocks.world.ChunkEventListeners$$Lambda$6031/0x0000000801b9f568(1/1) - 24.60%/0.00%
[06] |   |   |   |   |   |   unspecified(1/1) - 0.07%/0.07%
[06] |   |   |   |   |   |   poi(1/1) - 0.00%/0.00%

[JFMillerUSA]

Not sure if it would, there is an openjdk 16.0.2 out.

[dandin87]

chunk_unload(1/1) - 99.93%/88.33%

Ignore the above, this is not a java isssue..... This sounds like the Modern Industrialization fluid pipe bug, When unloading a chunk it would cause all nearby chunks to load, which you might imagine is going to cause a bit of infinite unload/reload if the pipe network is across chunks. What version of the modpack is this? Should be fixed in 0.0.9

A tool to help you out with finding things that are causing lag. https://www.curseforge.com/minecraft/mc-mods/observable I just recently added it to the public server (it requires OP to run a profile and view the results) when the dev was nice enough to release it for 1.17 when I asked about an update for it.

[SeeJayEmm]

@dandin87 Thanks! I'll check this out. I did update the server to 0.0.9 yesterday but then didn't have much time to test.

[SeeJayEmm]

Server is running 0.0.9. Observable I'm still trying to make sense of, all the heavy hitters are just mob/villager entities but I did manage to catch a couple of the rubber-bands on a perf run.

2@2021-08-28_11.50.21.362.txt 86@2021-08-28_11.50.28.851.txt

[SeeJayEmm]

Moved the server to newer hardware just to eliminate that as a potential cause. The overloaded message have stopped so that can be chalked up to the age of the cpu but the moved too fast and SIGNIFICANT rubber banding has not. /perf still show chunk_unload as the primary culprit.

As a test: Empty server except me. Dropped about 70m straight down and rubber banded about 6 times during that process.

There should have been no chunk activity at all happening in this scenario. I'm going to start disabling mods to try and isolate the cause.

2021-08-28_18_38_14-world-1_17_1.zip

[SeeJayEmm]

Disabled Modern Industrialization on a test copy solved the problem. Also isolated why it was sporadic. One of the players has an MI quarry and when he's logged on and near his base everything runs smoothly. When the chunks SHOULD be unloaded it runs terribly. He had 2 pipes, all well within the same chunk border. One was an "item pipe" connecting the quarry to a chest and the other was a "fluid pipe".

Went back to the original copy and broke his pipes. That removed the lag. So the lag still seems to be centered around the MI pipes and is not limited to them being on a chunk boundary.

What, if any, information can I provide for further debugging of this? Screenshot attached. I have a backup of the world if necessary.

[Technici4n]

Hi, MI dev here. A more detailed profile would help a lot if you are able to provide one. Would it be possible for you to install spark on your server and run the profiler (/spark profiler start --timeout 30 iirc)? Many thanks.

[SeeJayEmm]

@Technici4n I'll have to spin up a backup made before we broke the pipes. I'll get that to you soon as I can.

[SeeJayEmm]

@Technici4n https://spark.lucko.me/MDIUrZKIw1 This is after launching the server with no one even logged in.

[Technici4n]

This is really weird, as far as I can tell that was fixed in MI 0.5.4, and AOF 0.0.9 should have the fix.

Moved the server to newer hardware just to eliminate that as a potential cause. The overloaded message have stopped so that can be chalked up to the age of the cpu but the moved too fast and SIGNIFICANT rubber banding has not. /perf still show chunk_unload as the primary culprit.

As a test: Empty server except me. Dropped about 70m straight down and rubber banded about 6 times during that process.

There should have been no chunk activity at all happening in this scenario. I'm going to start disabling mods to try and isolate the cause.

2021-08-28_18_38_14-world-1_17_1.zip

In this zip archive (system.txt file) I can see that you are running Modern Industrialization 0.5.3. Are you sure the server is really running 0.0.9? 0.0.9 should have MI version 0.5.8.

[SeeJayEmm]

@Technici4n I thought it was. I updated the server launcher, it went through the motions of downloading the new pack and moving the old mods folder to the side. I'll manually do it from scratch.

If this is the case I apologize for not noticing that sooner.