Framerate issues while connected to KMP dev server

[JohannesMP]

While on the dev server yesterday I noticed a lot of framerate lag when trying to launch of a vessel that normally my computer would have no problem with. For a ~450 part launch stage+lander I was getting 1fps, compared to my normal +30fps.

I was also experiencing minor issues where about every 30 seconds I would see UDP connection lost. quickly followed by UDP connection established.

Interestingly enough, while my connection was down, my framerate would rocket back to my usual +30, and then back down again when connection was established.

This leads me to believe that the extreme framerate drop is directly related to KMP. Looking at my KSP.log and Player.log it seems that this might be the case: there were several errors occurring dozens of times per second which might be related to the low framerate I was receiving during connection.

You can find my Player.log file here: https://dl.dropboxusercontent.com/u/3718471/temp/stream_test_0.1.4.0/Player.log.zip And my KSP.log file here: https://dl.dropboxusercontent.com/u/3718471/temp/stream_test_0.1.4.0/KSP.log.zip

Below I'm listing the kinds of errors that occured most frequently during the general timeframe when I noticed the fps drop.

Error 1: addRemoteVessel() exception

About ~30 times per second:

[LOG 10:15:44.172] [Debug] : Exception thrown in addRemoteVessel(), catch 1, Exception: System.NullReferenceException: Object reference not set to an instance of an object at KMP.KMPManager.addRemoteVessel (.ProtoVessel protovessel, Guid vessel_id, KMP.KMPVessel kvessel, KMP.KMPVesselUpdate update, Double distance) [0x00000] in <filename unknown>:0 
[LOG 10:15:44.172] [Debug] : Exception thrown in addRemoteVessel(), catch 1, Exception: System.NullReferenceException: Object reference not set to an instance of an object at KMP.KMPManager.addRemoteVessel (.ProtoVessel protovessel, Guid vessel_id, KMP.KMPVessel kvessel, KMP.KMPVesselUpdate update, Double distance) [0x00000] in <filename unknown>:0 
[LOG 10:15:44.172] [Debug] : Exception thrown in addRemoteVessel(), catch 1, Exception: System.NullReferenceException: Object reference not set to an instance of an object at KMP.KMPManager.addRemoteVessel (.ProtoVessel protovessel, Guid vessel_id, KMP.KMPVessel kvessel, KMP.KMPVesselUpdate update, Double distance) [0x00000] in <filename unknown>:0 
[LOG 10:15:44.173] [Debug] : Exception thrown in addRemoteVessel(), catch 1, Exception: System.NullReferenceException: Object reference not set to an instance of an object at KMP.KMPManager.addRemoteVessel (.ProtoVessel protovessel, Guid vessel_id, KMP.KMPVessel kvessel, KMP.KMPVesselUpdate update, Double distance) [0x00000] in <filename unknown>:0 
[LOG 10:15:44.173] [Debug] : Exception thrown in addRemoteVessel(), catch 1, Exception: System.NullReferenceException: Object reference not set to an instance of an object at KMP.KMPManager.addRemoteVessel (.ProtoVessel protovessel, Guid vessel_id, KMP.KMPVessel kvessel, KMP.KMPVesselUpdate update, Double distance) [0x00000] in <filename unknown>:0 
[LOG 10:15:44.173] [Debug] : Exception thrown in addRemoteVessel(), catch 1, Exception: System.NullReferenceException: Object reference not set to an instance of an object at KMP.KMPManager.addRemoteVessel (.ProtoVessel protovessel, Guid vessel_id, KMP.KMPVessel kvessel, KMP.KMPVesselUpdate update, Double distance) [0x00000] in <filename unknown>:0 

Error 2: MechJebCore crash

(I'm aware that whitelisting of parts will be added in the next version(s), which should fix this) About 2-8 times per second:

[ERR 10:15:44.232] Cannot load Module MechJebCore because the associated module on the part doesn't match the saved module
[WRN 10:15:44.232] PartModule is null.
[WRN 10:15:44.232] Part Mark1-2Pod cannot load module #6. It only has 6 modules defined
[WRN 10:15:44.232] PartModule is null.
[ERR 10:15:44.386] Cannot load Module MechJebCore because the associated module on the part doesn't match the saved module
[WRN 10:15:44.386] PartModule is null.
[WRN 10:15:44.386] Part Mark1-2Pod cannot load module #6. It only has 6 modules defined
[WRN 10:15:44.386] PartModule is null.
[ERR 10:15:44.539] Cannot load Module MechJebCore because the associated module on the part doesn't match the saved module
[WRN 10:15:44.539] PartModule is null.
[WRN 10:15:44.539] Part Mark1-2Pod cannot load module #6. It only has 6 modules defined
[WRN 10:15:44.539] PartModule is null.
[LOG 10:15:44.733] Vessel Jupiter2 was on-rails at 41.4 atm pressure and was destroyed.
[WRN 10:15:44.733] Vessel Jupiter2 crashed through terrain on Kerbin
[LOG 10:15:44.733] [00:02:09]: Jupiter2 crashed into Kerbin.
[LOG 10:15:44.733] Mark1-2Pod (Jupiter2) Exploded!! - blast awesomeness: 0
[LOG 10:15:44.777] [Mark1-2Pod (Jupiter2)]: Deactivated
[LOG 10:15:44.777] [00:02:09]: Jebediah Kerman was killed.
[LOG 10:15:44.777] [00:02:09]: Bill Kerman was killed.
[LOG 10:15:44.777] [00:02:09]: Jenwise Kerman was killed.
[LOG 10:15:44.777] Vessel Jupiter2 was on-rails at 37.0 atm pressure and was destroyed.
[WRN 10:15:44.777] Vessel Jupiter2 crashed through terrain on Kerbin
[LOG 10:15:44.777] [00:02:09]: Jupiter2 crashed into Kerbin.
[LOG 10:15:44.777] Mark1-2Pod (Jupiter2) Exploded!! - blast awesomeness: 0
[LOG 10:15:44.825] [Mark1-2Pod (Jupiter2)]: Deactivated
[LOG 10:15:44.826] [00:02:09]: Jebediah Kerman was killed.
[LOG 10:15:44.826] [00:02:09]: Bill Kerman was killed.
[LOG 10:15:44.826] [00:02:09]: Jenwise Kerman was killed.
[LOG 10:15:44.826] Vessel Jupiter2 was on-rails at 32.8 atm pressure and was destroyed.
[WRN 10:15:44.826] Vessel Jupiter2 crashed through terrain on Kerbin
[LOG 10:15:44.826] [00:02:09]: Jupiter2 crashed into Kerbin.
[LOG 10:15:44.826] Mark1-2Pod (Jupiter2) Exploded!! - blast awesomeness: 0
[LOG 10:15:44.872] [Mark1-2Pod (Jupiter2)]: Deactivated
[LOG 10:15:44.873] [00:02:09]: Jebediah Kerman was killed.
[LOG 10:15:44.873] [00:02:09]: Bill Kerman was killed.
[LOG 10:15:44.873] [00:02:09]: Jenwise Kerman was killed.

---

Looking at the above errors, it seems I was receiving data for one or more vessels that was far outside my own visible reach, and really I shouldn't have gotten this data as often while in the flight view.

I really think that the amount of data that is sent to clients should be drastically limited depending on case.

For example:

• While in the normal flight view, you should ONLY ever receive data for ships that are close to you and could appear in your view.
• While in map view you should only frequently receive data for vessels whose orbits are changing, and even if they are in atmo the amount of times your client receives updates for their position should be proportional to their distance to you, or at least dependent on if they share your sphere of influence or not. if their orbits are not changing you should receive an update once every 5 seconds or so, at most.

[godarklight]

Looks like I have to clean up the dev server again, I noticed it yesterday too. I'll back up the database first incase someone wants to fix the root cause, I still haven't learnt the vessel update stuff.

KMP's tick is 30Hz, so it most likely was 30 times a second ;)

EDIT: Jupiter2 was repetitively crashing through the ground, I would expect this to cause more problems.

[TehGimp]

I doubt we'll snag it for 0.1.4 at this rate (maybe we will), but yeah these "repeated destruction" issues seem to be a major source of current performance issues. They're unusual as a vessel destruction event should prevent the vessel from being reloaded for a few seconds, but this may not be working correctly...

[godarklight]

I've also noticed the KMP client's tick is 1/30th of a second (KMPManager.cs updateStep).

On a server with 8 players, each sending a vessel update 30 times a second, can we apply 210 updates a second?

I might have misunderstood when vessel updates are sent, but a debug build of my KMPChatClient should show you each message as it comes in.

[TehGimp]

@godarklight KMP's original design included some as-yet unimplemented logic where the server would throttle the messages it sends from players that have a different SOI--in initial pre-release testing on smaller servers performance was adequate enough that I never implemented this, but the idea was that if the SOI is different than only some fraction of the updates should come through (probably including all full-protovessel updates though). Thankfully, the server has access to everything it needs to perform this throttling (namely each client's current celestial-body name) in Server.sendPluginUpdateToAll, so we can probably greatly improve performance for clients on high-traffic servers by only sending, say, every 5th non-protovessel update from a player with a different SOI than the recipient.

[godarklight]

I had an idea for a different approach, making the client's updatestep tickrate scale depending on how many clients there were, but that might cause more weirdness. I'd have to profile exactly what is holding KMP up before we change something like that - which also means learning vessel update code

[TehGimp]

@godarklight KMP already varies the per-player update rate based on load, but with strict bounds to preserve minimum performance levels (your guess that things look terrible with a too-low tickrate is spot on). Since those appearance problems are most apparent only for things that are nearby, I think throttling updates from other SOIs will do the job nicely.

[TehGimp]

This should be better in v0.1.4.2 due to KSP 0.23 including various major optimizations, but I'm still planning to do some performance profiling and look into SOI-based update throttling for 0.1.5.

[TehGimp]

Given https://github.com/TehGimp/KerbalMultiPlayer/commit/df6deb762b016a5cdde25232f67b7eeda777297a and the new mod controls, I think we can safely skip the SOI optimization for now--that really only provides a benefit when there are several players online, and I think the errors that have now been addressed were easily the main source of slowdown here, so the SOI optimization wouldn't bring us much further. I'm closing this since the errors are addressed, and we'll return to the SOI idea if needed later.