Extreme Tick Lag due to System.gc() calls

[CaiB]

Hi there,

First off, I want to say that I cannot narrow this down to being in one of your mods, however the circumstances make it seem likely. I cannot rule out other factors, as I made a lot of changes to the server at once. Here's a summary of what happened:

• Updated ChromatiCraft from 29g to 31b
• Updated DragonAPI from 29a to 31b
• Updated ElectriCraft from 29a to 31a
• Updated ExpandedRedstone 29b to 31a
• Updated ReactorCraft from 29e to 31b
• Updated RotaryCraft from 29g to 31b
• Updated TerritoryZone from 29a to 31a
• Moved to new host OS, from WinServ 2019 to WinServ 2022
• Updated Java to newest AdoptOpenJDK 8
• Moved to entirely different (significantly better) hardware
• Installed Log4j mitigation
• Java launch arguments potentially changed (can't easily confirm)

I noticed that while the server was running, it was not falling behind, but some ticks were taking a very long time. This was extremely noticeable when standing near a timer, you could hear it stop every second or two for about half a second. I did some profiling (which led me to discover #2960), but this wasn't the real issue. The GC was being forcibly called by System.gc() invocation about every second or two, and was completely halting the server for about 400-600ms each time. It apparently collected about 1MB on average, a massive waste of time.

Note the max tick time.

Since no mods were touched other than yours, my leading theory is you are calling System.gc(), or a change you made is causing other code to call it. Alternatively, it could have been like this all along but the change in environment caused the GC to begin taking significantly longer than before, but this seems unlikely to me.

My solution was to add the Java launch argument -XX:+DisableExplicitGC which causes it to completely ignore System.gc() calls. This immediately solved the issue, as seen below (I added it at about 01:50):

Not only did the tick lag disappear, CPU usage dropped from about 40-60% to under 10%.

Looking through your mods I find 2 potentially concerning calls to System.gc() in DepthFirstSearch and BreadthFirstSearch. These sound very general, but only you would know how often these were getting called. I don't think you need me to tell you that explicitly calling the GC is strongly discouraged, it knows what it's doing.

[Aivech]

BreadthFirstSearch$clear() which calls System.gc() is called by RoutingWeb$buildPaths().

There are also the calls in ChromaDimensionManager - GC is forced whenever the dimension is reset, and I don't really know how often that happens.

[CaiB]

I think the dimension only gets reset when a player leaves it, so that's fine. But the RoutingWeb$buildPaths() sounds like it could happen frequently. In that case it really shouldn't be explicitly called there.

[Aivech]

I actually can't find any references to RoutingWeb at all in the entire github, but reika would have to check that himself.