Sign in to follow this  
masaykh

Causes of Lag

Recommended Posts

My server sometimes have "lag".

version 1.0.0.6 , 3.19.0-49-generic 14.04.1-Ubuntu x86_64
Network Checked - medium latency 200-250 ms - i think it is good. no packet loss.
Memory : 3gb max heap, 2-2.2 gb used from heap. no heap \ memory errors warnings.

Cpu at most used 35 percents no other heavy tasks running.

maybe some code not working good ?

i collected warrings and errors from logs so maye someone know how to fix it or at least workaround to their influence on robustness.
 

[01:11:17 PM] WARNING com.wurmonline.server.players.PermissionsHistories: Failed to add permissions history for object (4336326710788)
java.sql.SQLException: [SQLITE_CONSTRAINT]  Abort due to constraint violation (NOT NULL constraint failed: PERMISSIONSHISTORY.PK)
        at org.sqlite.core.DB.newSQLException(DB.java:890)
        at org.sqlite.core.DB.newSQLException(DB.java:901)
        at org.sqlite.core.DB.execute(DB.java:810)
        at org.sqlite.core.DB.executeUpdate(DB.java:847)
        at org.sqlite.jdbc3.JDBC3PreparedStatement.executeUpdate(JDBC3PreparedStatement.java:86)
        at com.wurmonline.server.players.PermissionsHistories.dbAddHistoryEvent(PermissionsHistories.java:205)
        at com.wurmonline.server.players.PermissionsHistories.addHistoryEntry(PermissionsHistories.java:183)
        at com.wurmonline.server.questions.ManagePermissions.answer(ManagePermissions.java:508)
        at com.wurmonline.server.creatures.Communicator.reallyHandle_CMD_PERMISSIONS(Communicator.java:2960)
        at com.wurmonline.server.creatures.Communicator.reallyHandle(Communicator.java:2527)
        at com.wurmonline.communication.SocketConnection.tick(SocketConnection.java:615)
        at com.wurmonline.communication.SocketServer.tick(SocketServer.java:172)
        at com.wurmonline.server.Server.run(Server.java:2422)
        at java.util.TimerThread.mainLoop(Timer.java:555)
        at java.util.TimerThread.run(Timer.java:505)

As i understand here is a need of some "pre check" so it will not abort while execution but will be stoped from execution?
 

[01:11:35 PM] WARNING com.wurmonline.server.behaviours.Terraforming: No template for flowers!
com.wurmonline.server.items.NoSuchTemplateException: No item template with id -1
        at com.wurmonline.server.items.ItemTemplateFactory.getTemplate(ItemTemplateFactory.java:81)
        at com.wurmonline.server.items.ItemFactory.createItem(ItemFactory.java:110)
        at com.wurmonline.server.items.ItemFactory.createItem(ItemFactory.java:88)
        at com.wurmonline.server.items.ItemFactory.createItem(ItemFactory.java:173)
        at com.wurmonline.server.behaviours.Terraforming.pickFlower(Terraforming.java:4526)
        at com.wurmonline.server.behaviours.TileGrassBehaviour.action(TileGrassBehaviour.java:784)
        at com.wurmonline.server.behaviours.Action.poll(Action.java:2854)
        at com.wurmonline.server.behaviours.ActionStack.poll(ActionStack.java:237)
        at com.wurmonline.server.players.Player.pollActions(Player.java:6708)
        at com.wurmonline.server.Players.pollPlayers(Players.java:4353)

template cant have -1 number , correct? so somehow it got such id... i dont think it working as expected

 

[01:17:30 PM] INFO com.wurmonline.server.creatures.Communicator: Unable to find dragged item
com.wurmonline.server.NoSuchItemException: No item found with id 50730144011778
        at com.wurmonline.server.Items.getItem(Items.java:245)
        at com.wurmonline.server.creatures.Communicator.reallyHandle_CMD_MOVE_INVENTORY(Communicator.java:3632)
        at com.wurmonline.server.creatures.Communicator.reallyHandle(Communicator.java:2400)
        at com.wurmonline.communication.SocketConnection.tick(SocketConnection.java:615)
        at com.wurmonline.communication.SocketServer.tick(SocketServer.java:172)
        at com.wurmonline.server.Server.run(Server.java:2422)
        at java.util.TimerThread.mainLoop(Timer.java:555)
        at java.util.TimerThread.run(Timer.java:505)

Maybe here to can be inserted some sort of "pre check" ? or other way to make it work more ...stable

 

[01:23:26 PM] WARNING com.wurmonline.server.creatures.MovementScheme: PLAYER_NAME TOO FAR, input=0.10635372, expected=0.105382815 :  13292.792(13292.699); 4018.2546(4018.2026) bridge=-10
[01:23:26 PM] INFO com.wurmonline.server.players.Player: PLAYER_NAME intrateleport to 13292.699,4018.2026, 15.8499, layer 0 currentTile:null=false reason=Moved too far hasVisionArea=true, initialized=true vehicle=-10
java.lang.Exception
        at com.wurmonline.server.players.Player.intraTeleport(Player.java:5059)
        at com.wurmonline.server.creatures.MovementScheme.handleMoveTooFar(MovementScheme.java:780)
        at com.wurmonline.shared.util.MovementChecker.movestep(MovementChecker.java:271)
        at com.wurmonline.server.creatures.Communicator.pollNextMove(Communicator.java:1125)
        at com.wurmonline.server.Server.pollComms(Server.java:2559)
        at com.wurmonline.server.Server.run(Server.java:2437)
        at java.util.TimerThread.mainLoop(Timer.java:555)
        at java.util.TimerThread.run(Timer.java:505)

This happen then player connection become high latency (from 200-250 to 400-600 ms), can  there be some sort of workaround applied?

 

[01:25:55 PM] SEVERE org.gotti.wurmunlimited.mods.serverpacks.PackServer: Connection timed out
java.io.IOException: Connection timed out
        at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
        at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
        at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
        at sun.nio.ch.IOUtil.write(IOUtil.java:65)
        at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471)
        at sun.net.httpserver.Request$WriteStream.write(Request.java:391)
        at sun.net.httpserver.ChunkedOutputStream.writeChunk(ChunkedOutputStream.java:125)
        at sun.net.httpserver.ChunkedOutputStream.write(ChunkedOutputStream.java:95)
        at sun.net.httpserver.PlaceholderOutputStream.write(ExchangeImpl.java:444)
        at org.gotti.wurmunlimited.mods.serverpacks.PackServer$1.handle(PackServer.java:60)
        at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)
        at sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:83)
        at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:82)
        at sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:675)
        at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)
        at sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:647)
        at sun.net.httpserver.ServerImpl$DefaultExecutor.execute(ServerImpl.java:158)
        at sun.net.httpserver.ServerImpl$Dispatcher.handle(ServerImpl.java:431)
        at sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:396)
        at java.lang.Thread.run(Thread.java:745)
        Suppressed: java.io.IOException: Broken pipe
                at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
                at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
                at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
                at sun.nio.ch.IOUtil.write(IOUtil.java:65)
                at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471)
                at sun.net.httpserver.Request$WriteStream.write(Request.java:391)
                at sun.net.httpserver.ChunkedOutputStream.writeChunk(ChunkedOutputStream.java:125)
                at sun.net.httpserver.ChunkedOutputStream.flush(ChunkedOutputStream.java:159)
                at sun.net.httpserver.ChunkedOutputStream.close(ChunkedOutputStream.java:134)
                at sun.net.httpserver.PlaceholderOutputStream.close(ExchangeImpl.java:454)
                at org.gotti.wurmunlimited.mods.serverpacks.PackServer$1.handle(PackServer.java:63)
                ... 10 more

i understand this is from mod (serverpacks) , but as i assume that this mod use almost everyone.. server behind nat port opened, and some times it even succed in 
delivering pakcs...but this should not happen, is it? 
 

[02:14:09 PM] WARNING com.wurmonline.server.webinterface.WebInterfaceImpl: Could not get ClientHost details due to not in a remote call
java.rmi.server.ServerNotActiveException: not in a remote call
        at sun.rmi.transport.tcp.TCPTransport.getClientHost(TCPTransport.java:613)
        at java.rmi.server.RemoteServer.getClientHost(RemoteServer.java:77)
        at com.wurmonline.server.webinterface.WebInterfaceImpl.getRemoteClientDetails(WebInterfaceImpl.java:201)
        at com.wurmonline.server.webinterface.WebInterfaceImpl.addMoneyToBank(WebInterfaceImpl.java:1845)
        at com.wurmonline.server.webinterface.WebInterfaceImpl.addMoneyToBank(WebInterfaceImpl.java:1773)
        at com.wurmonline.server.LoginServerWebConnection.addMoney(LoginServerWebConnection.java:240)
        at com.wurmonline.server.players.Player.poll(Player.java:2840)
        at com.wurmonline.server.creatures.Creatures.pollAllCreatures(Creatures.java:1706)
        at com.wurmonline.server.zones.Zones.pollNextZones(Zones.java:1543)
        at com.wurmonline.server.Server.run(Server.java:1812)
        at java.util.TimerThread.mainLoop(Timer.java:555)
        at java.util.TimerThread.run(Timer.java:505)

[02:14:09 PM] INFO com.wurmonline.server.webinterface.WebInterfaceImpl: Unknown Remote Client Add money to bank 2 , 10 for player name: PLAYER_NAME, wid -1

RMI disabled..it`s looks like exploit ,, and until 1.0.0.6 version, i dont seen such warrnings..


Also if anyone have some strategy to "hunt down lag" share them please.

Share this post


Link to post
Share on other sites

The last snippet looks like bountymod. Bountymod puts a message like that one in my server console - see where it is adding money to bank?

Share this post


Link to post
Share on other sites
2 hours ago, masaykh said:

[01:11:17 PM] WARNING com.wurmonline.server.players.PermissionsHistories: Failed to add permissions history for object

 

This is a problem with the creative template database as shipped with WU.

 

See here for a fix: http://forum.wurmonline.com/index.php?/topic/138343-permission-histories-not-saving-how-to-fix/

 

2 hours ago, masaykh said:

[01:17:30 PM] INFO com.wurmonline.server.creatures.Communicator: Unable to find dragged item

 

Probably just someone dragging an item twice due to latency. If you are having latency and/or packet loss issues - that's just a manifestation of that, not something that can be directly fixed.

 

2 hours ago, masaykh said:

[01:23:26 PM] WARNING com.wurmonline.server.creatures.MovementScheme: PLAYER_NAME TOO FAR,

 

Again, stuff caused by latency / desync. Same as above.

 

2 hours ago, masaykh said:

[01:25:55 PM] SEVERE org.gotti.wurmunlimited.mods.serverpacks.PackServer: Connection timed out

 

Someone downloading a pack and their connection is timing out. Not much the mod can do about that.

 

2 hours ago, masaykh said:

[02:14:09 PM] WARNING com.wurmonline.server.webinterface.WebInterfaceImpl: Could not get ClientHost details due to not in a remote call

 

That's a WU bug, generally harmless except for the log spam. Discussed in this thread if you want more info: http://forum.wurmonline.com/index.php?/topic/141931-lag-detect-loops/

 

  • Like 1

Share this post


Link to post
Share on other sites

Bdew can you elaborate about this :
 

[07:25:24 PM] SEVERE org.gotti.wurmunlimited.mods.serverpacks.PackServer: Connection reset by peer
java.io.IOException: Connection reset by peer
        at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
        at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
        at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
        at sun.nio.ch.IOUtil.write(IOUtil.java:65)
        at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471)
        at sun.net.httpserver.Request$WriteStream.write(Request.java:391)
        at sun.net.httpserver.ChunkedOutputStream.writeChunk(ChunkedOutputStream.java:125)
        at sun.net.httpserver.ChunkedOutputStream.write(ChunkedOutputStream.java:95)
        at sun.net.httpserver.PlaceholderOutputStream.write(ExchangeImpl.java:444)
        at org.gotti.wurmunlimited.mods.serverpacks.PackServer$1.handle(PackServer.java:60)
        at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)
        at sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:83)
        at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:82)
        at sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:675)
        at com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:79)
        at sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:647)
        at sun.net.httpserver.ServerImpl$DefaultExecutor.execute(ServerImpl.java:158)
        at sun.net.httpserver.ServerImpl$Dispatcher.handle(ServerImpl.java:431)
        at sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:396)
        at java.lang.Thread.run(Thread.java:745)
        Suppressed: java.io.IOException: Broken pipe
                at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
                at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
                at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
                at sun.nio.ch.IOUtil.write(IOUtil.java:65)
                at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471)
                at sun.net.httpserver.Request$WriteStream.write(Request.java:391)
                at sun.net.httpserver.ChunkedOutputStream.writeChunk(ChunkedOutputStream.java:125)
                at sun.net.httpserver.ChunkedOutputStream.flush(ChunkedOutputStream.java:159)
                at sun.net.httpserver.ChunkedOutputStream.close(ChunkedOutputStream.java:134)
                at sun.net.httpserver.PlaceholderOutputStream.close(ExchangeImpl.java:454)
                at org.gotti.wurmunlimited.mods.serverpacks.PackServer$1.handle(PackServer.java:63)
                ... 10 more

 

Share this post


Link to post
Share on other sites

"Connection reset by peer" means the other side force-closed the connection. Possibly because the client was closed or crashed.

Share this post


Link to post
Share on other sites

this happen once player connected, player after this error not disconected, and keep playing fine..so you wrong here...

Share this post


Link to post
Share on other sites

I said "possibly". The message means your server received an RST packet, it's not possible to know why (or even by who) that packet was sent, i just gave some possible causes.

 

Is there anything logged on the clients when this happens?

 

Also is that server in a datacenter or a home broadband connection?

Edited by bdew

Share this post


Link to post
Share on other sites

datacenter, nothing logged on playerside

 

as i and players found :

when server do this 
[07:35:22 PM] INFO com.wurmonline.server.zones.Zone: Zone at 2112, 896 polled 131 tiles. That took 642.14386 millis.
[07:35:32 PM] INFO com.wurmonline.server.zones.Zone: Zone at 3008, 3392 polled 81 tiles. That took 467.0646 millis.
[07:35:41 PM] INFO com.wurmonline.server.zones.Zone: Zone at 2048, 896 polled 198 tiles. That took 714.64514 millis.
[07:35:50 PM] INFO com.wurmonline.server.zones.Zone: Zone at 3008, 640 polled 184 tiles. That took 628.92535 millis.

players got lag that end when polling end

what can be done?

 

one more :

 

[12:38:32 PM] WARNING com.wurmonline.server.behaviours.Action: Array index out of bounds while polling an action PLAYER_NAME due to null
java.lang.ArrayIndexOutOfBoundsException
 

Edited by masaykh

Share this post


Link to post
Share on other sites

How bad is the lag, is it frequent, or just a big spike every few hours, when did this start, what size is your map, how many players do you have, how many items in your database?

Share this post


Link to post
Share on other sites

medium off badnesses
every few hours - then i investigated further - it led me to ZonePolling.

lags started then player base grow beyond 40 players or so currently 55-75 players online.
map size - 4096

size of wurmitems.db = 720kb

Share this post


Link to post
Share on other sites

Create an account or sign in to comment

You need to be a member in order to leave a comment

Create an account

Sign up for a new account in our community. It's easy!

Register a new account

Sign in

Already have an account? Sign in here.

Sign In Now
Sign in to follow this