Problems with world leaking and coinciding "Can't keep up" messages on SMP

[thr33p10]

I've been troubleshooting for some time on this issue and after being unable to pin this down to a specific mod, I'm coming here for any help/suggestions that can be offered.

 

In short:

Messages like these (from "latest.log"): [server thread/WARN]: Can't keep up! Did the system time change, or is the server overloaded? Running 2065ms behind, skipping 41 tick(s)

 

occur about 3 seconds after messages like these (from "fml-server-latest"): [server thread/DEBUG] [FML/]: Gathering id map for writing to world save Answer

 

which are then very shortly followed by messages like this (also from "fml-server-latest"): [server thread/DEBUG] [FML/]: The world 65ade8e7 (Answer) may have leaked: seen 3955 times.

 

This, when a player is online, is noticed as as lag in block placement/destruction in most cases, lasting anywhere between 2 to 10 seconds, and can happen every 45 seconds.  The tick rate (using server tools TPS command) on the server is generally 12-40ms, except when the spikes occur.

 

Originally I had thought this to be related to something like forestry butterflies on the server updating leaf blocks and causing many chunks to require disk writes quite often, but recently we've changed the config for forestry to turn off butterfly spawns entirely to dismiss this possibility.  Logs are here gist.github - links below.  No crashes are caused by this issue, and no memory leaks seem to be occurring that I can detect after letting the server run for a few days continuously.

 

If there are any ideas what the cause of this could be, or how to continue to troubleshoot this, I'm all ears.

 

https://gist.github.com/thr33p10/e32035f514dabf9e72b7

https://gist.github.com/thr33p10/e20ece586916dcfd638d

 

[LexManos]

Sadly, with that much going on in your MC and with no pragmatic way to figure out what is holding a reference to what.

Your options are to attach a profiles, such as JProfiler {comes with your JRE} and dig into it.

One of the mods you have installed is not letting the worlds unload.

[thr33p10]

I have, in the past, tried a profiler, and will see if I can spot anything happening with specific classes when these tick skips are occurring.  I'm pretty sure we can find by elimination which mod(s) may be causing world load/unload issues too.  I'll report my findings back once I try these ideas over the weekend.

[thr33p10]

So attaching a profiler to the java instance during runtime showed that there is one common thread that gets run at the same moment the warnings about "Can't keep up" get thrown.  The File I/O thread.  It seems that, after running for several hours from a clean restart, these tick skips start to happen concurrently with the Filer I/O thread (in the logs this is read with the output "[server thread/DEBUG] [FML/]: Gathering id map for writing to world save Answer") My observation on the profiler times that thread as waiting for approximately 45 seconds before being activated and then waiting again.

 

My concern is that the world data being saved at this point might just be large enough in size that it actually causes the only source of lag I can see on the server (nominal tick timing during observations was approximately 10.2 ms ea).  Since I have no mods or available settings that I can see controlling how often world data is saved, or how much of it gets saved at these intervals, I don't think there is anything I can do about this (short of trimming the map size down or putting strict caps on chunkloading).

 

Does forge code that the map file be written every 45 seconds, or is this a vanilla "feature"? Is there any improvement that can be made to this process, such as writing smaller segments to disk per save operation and doing it more often (e.g. tag areas that require a disk write, but hold off on some of them until write time becomes less intrusive on the world tick)?

 

Latest log (snipped early startup stuff):

https://gist.github.com/thr33p10/a74c6f30f4959cd93474

Latest log from "latest.log" showing when "tick skipping" begins relative to fml-server-latest.log:

https://gist.github.com/thr33p10/60d83e5d6543d71c372f

 

ALSO

 

We found the mod that was forcefully trying to unload the overworld (only chunkloaders were keeping it from suceeding): Too Much Time.

Unfortunately, running a second instance of the server map with identical setup (minus too much time) still had these tick skips happening concurrently with the disk writes after the same time passed since startup.