Direwolf20 server performance issues / low tps

[Boundary]

Hi all,

I have had this problem on-going for some time now, initially posted something here.
At that point I suspected it had to do with player profiles, but since we tried a few 'fixes' in this regard & the problem not only persisted but has become worse - I am once again at the limit of my technical ability here & would really appreciate some help or direction on solving this one?

The server:
Intel E2180
2gb ram (was 4gb long story)
100gb hdd
win7 64bit - clean install for this
java - build 1.7.0_07-b10

serverstart.bat:
java -Xms1G -Xmx3G -jar ftbserver.jar

Direwolf20 5.3.2 - no other mods added or removed, only adjustment to cfg's was 15min added to cc clean orphan chunks.

There is a recurring error on my server, which I can't seem to pin down either (this error arrived after performance went down, so I am not sure if it's a side symptom or cause:

2013-06-19 09:16:40 [WARNING] [Minecraft] Can't keep up! Did the system time cha
nge, or is the server overloaded?
2013-06-19 09:16:48 [INFO] [STDERR] java.util.ConcurrentModificationException
2013-06-19 09:16:48 [INFO] [STDERR]    at java.util.HashMap$HashIterator.nextEn
try(Unknown Source)
2013-06-19 09:16:48 [INFO] [STDERR]    at java.util.HashMap$ValueIterator.next(
Unknown Source)
2013-06-19 09:16:48 [INFO] [STDERR]    at bq.a(SourceFile:24)
2013-06-19 09:16:48 [INFO] [STDERR]    at cd.a(SourceFile:114)
2013-06-19 09:16:48 [INFO] [STDERR]    at bq.a(SourceFile:25)
2013-06-19 09:16:48 [INFO] [STDERR]    at cd.a(SourceFile:114)
2013-06-19 09:16:48 [INFO] [STDERR]    at bq.a(SourceFile:25)
2013-06-19 09:16:48 [INFO] [STDERR]    at by.a(SourceFile:26)
2013-06-19 09:16:48 [INFO] [STDERR]    at cd.a(SourceFile:114)
2013-06-19 09:16:48 [INFO] [STDERR]    at bq.a(SourceFile:25)
2013-06-19 09:16:48 [INFO] [STDERR]    at cd.a(SourceFile:114)
2013-06-19 09:16:48 [INFO] [STDERR]    at bq.a(SourceFile:25)
2013-06-19 09:16:48 [INFO] [STDERR]    at cd.a(SourceFile:114)
2013-06-19 09:16:48 [INFO] [STDERR]    at ca.a(CompressedStreamTools.java:140)
2013-06-19 09:16:48 [INFO] [STDERR]    at aam.a(AnvilChunkLoader.java:198)
2013-06-19 09:16:48 [INFO] [STDERR]    at aam.c(AnvilChunkLoader.java:184)
2013-06-19 09:16:48 [INFO] [STDERR]    at aiw.b(SourceFile:29)
2013-06-19 09:16:48 [INFO] [STDERR]    at aiw.run(SourceFile:22)
2013-06-19 09:16:48 [INFO] [STDERR]    at java.lang.Thread.run(Unknown Source)
2013-06-19 09:17:39 [WARNING] [Minecraft] Can't keep up! Did the system time cha
nge, or is the server overloaded?

The error used to pop up every 2-5 mins, with changing the cc orphan chunks clean-up to 15mins gap between errors has gone to like 30mins-2hrs.

I have removed every chunkloader & replaced only the necessary ones & used mini loaders where possible & removed portals where possible as well. In the screenshots below you don't see a mystcraft age with 11 chunks loaded (9 alviaries & some xycraft tanks) & the nether with 6 loaded (4x lava pumps). Overworld has on avg. 400-450 chunks loaded. I am wondering if my tired old E2180 is actually just not enough here, CPU usage is 100% 24/7?

I can provide the full FML log if needed (it exceeds the 500kb limit on pastebin).

Thanks

Here are some screenshots if they help at all?

Server:


Client:

 

[Boundary]

TPS problem has been solved... Hardware was waaaay out of spec, gotta love our optimism though

I still can't find a way around the error spamming console, if anyone has seen that before I would appreciate some input - thanks again.

 

[DZCreeper]

Use this for your startup file: java -server -Xms1G -Xmx1G -jar ftbserver.jar nogui

Using the server GUI is known to cause a decent bit of lag, nogui removes it. Using -server results in longer startups but slightly improves perfomance. Using the same amount of memory for Xms and Xmx prevents lag spikes when the server memory usage spikes somewhat.

 

[Boundary]

Use this for your startup file: java -server -Xms1G -Xmx1G -jar ftbserver.jar nogui

Using the server GUI is known to cause a decent bit of lag, nogui removes it. Using -server results in longer startups but slightly improves perfomance. Using the same amount of memory for Xms and Xmx prevents lag spikes when the server memory usage spikes somewhat.

Thanks for the info DZCreeper, I will give that a try at some point as well. We fixed most of our problems by moving to a proper host & ditching the old hardware:


Funny thing though is that our memory use is almost double, that error still exists but then again I never thought it would dissapear but was kind of hopeful I did however get some new leaking world issues I will have to look into.

 

[DZCreeper]

Leaking worlds is a likely cause of increased memory usage. A well known remedy is to have a chunk loader in dimension. Keep in mind using my script if you set both Xms and Xmx to the same number, it is possible the server will always show that much memory being used.

 

[Boundary]

Thanks again DZCreeper!

I have had to split my testing due to some logistical reason (ie terrible upload download speeds from my location)

Locally I have installed tickthreading onto a test server to try isolate the questionable area's which where part of the original error spamming console, it does a good job of reporting area's but I can't find anything unusual at the reported x,y values & I have cleaned out large areas - maybe it relates to the entire chunk? Testing with tickthreading locally has shown some oddities in our multiblock farms (I will post this up in the tickthreading thread & see if anyone can chime in):

[FINE] Failed to harvest crop: forestry.farming.logic.CropFruit@609d02c1
[FINE] Failed to harvest crop: forestry.farming.logic.CropFruit@42eff3d2
[FINE] Failed to harvest crop: forestry.farming.logic.CropFruit@2f7368ef
[FINE] Failed to harvest crop: forestry.farming.logic.CropFruit@8090988
[FINE] Failed to harvest crop: forestry.farming.logic.CropFruit@3b5ef49e
[FINE] Failed to harvest crop: forestry.farming.logic.CropFruit@3e72e0cb
[FINE] Failed to harvest crop: forestry.farming.logic.CropFruit@aa3f945
[SEVERE] Failed to write chunk data to disk 6, 10
[FINE] Failed to harvest crop: forestry.farming.logic.CropFruit@40e6a8a9
[INFO] 19, 68, , 135 set to flower.
[FINE] Failed to harvest crop: forestry.farming.logic.CropFruit@7aea639d
[FINE] Failed to harvest crop: forestry.farming.logic.CropFruit@5ac343ac
[FINE] Removing MultiBlock: 376, server
[FINE] Failed to harvest crop: forestry.farming.logic.CropFruit@10540692
[FINE] Failed to harvest crop: forestry.farming.logic.CropFruit@52067e1
[FINE] Failed to harvest crop: forestry.farming.logic.CropFruit@779a9a3f
[FINE] Failed to harvest crop: forestry.farming.logic.CropFruit@19ca0e8e
[FINE] Failed to harvest crop: forestry.farming.logic.CropFruit@420434a7
[FINE] Failed to harvest crop: forestry.farming.logic.CropFruit@37fcb949
[INFO] 1NewMinah lost connection: disconnect.quitting
[INFO] 1NewMinah lost connection: disconnect.quitting
[INFO] Unloading Player: 1NewMinah
[FINE] Deferring MultiBlock: 375, server
[FINE] Unloading MultiBlock: 372, server
[FINE] Deferring MultiBlock: 373, server
[FINE] Unloading MultiBlock: 373, server
[FINE] Unloading MultiBlock: 374, server
[FINE] Unloading MultiBlock: 375, server

I think the leaking worlds may have been something I broke when I migrated to the new host. I deleted unused mystcraft ages by DIM_MYST* & *.dat files & ended up with the leaking world errors (not entirely sure what causes that, I double checked I was deleting the correct items, I thought maybe as I still have corresponding linking books to no-existant ages now). I am rewinding things & looking for the problem. Using MCPC+ on the hosted server side has fixed the leaking worlds & the error reported in the OP, but I have an issue with only one player account being able to stay logged in for more than 10s, always the same account can stay on? I have tried deleting player profiles which did not help, all players where in the same area (within 5 blocks) when the error occurs, including the one account which does not get kicked.

My how deep this rabbit hole is, to be honest I am just taking a lead & running with it to see where I end up it's mostly the blind leading the blind (referring to myself lol) but I am getting there, if not in solving at least in getting a better understanding.

 

[Boundary]

DZCreeper, I forgot to mention the high mem usage was a mis-report by multicraft, it was using the 'correct' amount of 500mb +-

 

[DZCreeper]

No problem, I enjoy helping. Can you just do a 1 paragraph max summary of what problems are remaining?

 

[Boundary]

After several hours we managed to fix almost all error reported issues & pruning down some suspicious low tps area's, thanks to tickthreading testing locally & mcpc+ running at the host end. So now all we are left with is some odd connection issues - there is no real error reported in the log (aside from what I pasted below), we are a VERY small community (4 players on a busy day ) & at the moment only 1 of us gets a consistently good connection, the other 3 acc's fall victim to this on an intermittent basis.

23.06 04:50:28 [Server] INFO Unloading Player: 1NewMinah
23.06 04:50:28 [Disconnect] User 1NewMinah has disconnected, reason: disconnect.overflow
23.06 04:50:28 [Server] INFO Connection reset
23.06 04:49:40 [Server] INFO [1.4.7v5] Recieved client info from 1NewMinah
23.06 04:49:40 [Server] INFO [1.4.7v2] Recieved client info from 1NewMinah
23.06 04:49:37 [Server] INFO Sending serverside check to: 1NewMinah
23.06 04:49:37 [Server] INFO Loading Player: 1NewMinah
23.06 04:49:37 [Multicraft] 1NewMinah ran command Message of the Day
23.06 04:49:37 [Connect] User 1NewMinah, IP (some.awesome.numbers.here)

Literally everything above & below of those lines are just the auto-save notices & the odd '23.06 05:02:27 [Server] INFO 64, 64, , 127 set to flower' every now & then, if you would like to see more of the log no problem

Client side:

2013-06-23 11:53:21 [INFO] [STDOUT] Connecting to (some.awesome.numbers.here)
2013-06-23 11:53:26 [INFO] [GraviGun] [1.4.7v2] Sending client info to server
2013-06-23 11:53:26 [INFO] [PortalGun] [1.4.7v5] Sending client info to server
2013-06-23 11:53:26 [INFO] [ForgeModLoader] [THAUMCRAFT] Client received server config settings.
2013-06-23 11:53:26 [INFO] [STDOUT] Loading World: remote/(some.awesome.numbers.here)/world
2013-06-23 11:54:03 [INFO] [GraviGun] [1.4.7v2] Received world props from server.
2013-06-23 11:54:03 [INFO] [PortalGun] [1.4.7v5] Received world props from server.
2013-06-23 11:54:44 [INFO] [STDERR] java.net.SocketTimeoutException: Read timed out
2013-06-23 11:54:44 [INFO] [STDERR] at java.net.SocketInputStream.socketRead0(Native Method)
2013-06-23 11:54:44 [INFO] [STDERR] at java.net.SocketInputStream.read(Unknown Source)
2013-06-23 11:54:44 [INFO] [STDERR] at java.net.SocketInputStream.read(Unknown Source)
2013-06-23 11:54:44 [INFO] [STDERR] at java.io.FilterInputStream.read(Unknown Source)
2013-06-23 11:54:44 [INFO] [STDERR] at org.bouncycastle.crypto.io.CipherInputStream.nextChunk(Unknown Source)
2013-06-23 11:54:44 [INFO] [STDERR] at org.bouncycastle.crypto.io.CipherInputStream.read(Unknown Source)
2013-06-23 11:54:44 [INFO] [STDERR] at java.io.DataInputStream.readFully(Unknown Source)
2013-06-23 11:54:44 [INFO] [STDERR] at dt.a(Packet56MapChunks.java:107)
2013-06-23 11:54:44 [INFO] [STDERR] at ef.a(Packet.java:166)
2013-06-23 11:54:44 [INFO] [STDERR] at cg.i(TcpConnection.java:324)
2013-06-23 11:54:44 [INFO] [STDERR] at cg.c(TcpConnection.java:544)
2013-06-23 11:54:44 [INFO] [STDERR] at ch.run(SourceFile:93)
2013-06-23 11:54:44 [INFO] [STDERR] java.net.SocketException: Socket closed
2013-06-23 11:54:44 [INFO] [STDERR] at java.net.SocketOutputStream.socketWrite(Unknown Source)
2013-06-23 11:54:44 [INFO] [STDERR] at java.net.SocketOutputStream.write(Unknown Source)
2013-06-23 11:54:44 [INFO] [STDERR] at org.bouncycastle.crypto.io.CipherOutputStream.write(Unknown Source)
2013-06-23 11:54:44 [INFO] [STDERR] at java.io.BufferedOutputStream.flushBuffer(Unknown Source)
2013-06-23 11:54:44 [INFO] [STDERR] at java.io.BufferedOutputStream.flush(Unknown Source)
2013-06-23 11:54:44 [INFO] [STDERR] at java.io.DataOutputStream.flush(Unknown Source)
2013-06-23 11:54:44 [INFO] [STDERR] at ci.run(SourceFile:120)

Our host has been very helpful in that matter with several options running back & forth & good correspondence, but due to time zone differences & my need to get a better understanding I am on here as well asking

 

[cjm721]

if you have tickthreading do /profile p I am guessing there is an MFFS shield somewhere. If MFFS is over 1MB then do /profile e 7 <world everyone is overflowing from> and it should be on the list. Go to it and turn it off.

 

[Boundary]

Thanks cjm I will give that a try as well.