Kerbal Inventory System (KIS)

Kerbal Inventory System (KIS)

Mods
1M Downloads

KIS causes SEVERE FPS drops when interacting with Mystery Goo

Alexsys opened this issue · 15 comments

commented

After long testing and removing every single mod, I figured out that KIS causes incredible performance loss when interacting with mystery goo, you'll see extreme fps drops, than from then and onwards as the time goes, your game will continue to experience performance loss reaching stutters every few seconds.

it all begins with an interaction with the mystery goo.

removing this mod fixes it, 100% KIS issue after long testing.
ksp version 1.12.2

https://gist.github.com/5c647e5df73afd519a49f5a660ecf570 Module manager log

https://www.dropbox.com/s/a83oo341kjt6pvo/KSP.log?dl=0 KSP.LOG (quite a beefy file lol, had a decent sesson but it should have a lot of info about KIS' interactions)

commented

I notice that you have a lot of other mods in the game. So, the issue can easily be a result of the mods conflict. By a chance, did you try testing on a pristine game? How can I trigger the issue and measure the stutters?

Checked the log briefly. Alas, it's too huge and spammed with unrelated errors. In fact, I haven't even found any interaction with KIS or the mystery goo.

The [DistantObject] seems to kick in occasionally in the flight scenes, and it spends from tens of milliseconds up to several seconds to report the warnings. In one scene it reported more than 2000 warnings at once, and spent 5 seconds to that (indeed, it resulted in a well noticeable freeze). On my machine I can feel even 30ms freezes (180 FPS), and in your case this mod takes more time pretty frequently.

[LOG 05:51:21.009] [DistantObject] WARNING: Failed to load model Squad/Parts/Structural/trussGirderXL/model for part trussPiece3x from vessel Unfinished Minmus Seeker MD65M! Vessel will not be rendered as expected!
...2,000 similar records....
[LOG 05:51:55.363] [DistantObject] WARNING: Failed to load model Squad/Parts/Aero/basicFin/basicFin for part basicFin from vessel Sattelite Mark III - Multiplanet Scanner Debris! Vessel will not be rendered as expected!

Long story short, at this point I have nothing to start with. Ideally, the problem should be reproducible on a pristine game with a pre-determined list of steps.

commented

Hi. DOE maintainer here. Please keep me in the loop.

I will give this a look on the WeekEnd!

commented

I've decided to remove Contract Configurator entirely, less bloat for the game, less bloat for the logs.
thus I've uploaded fresher newer logs for your ease gents, if that will be of any help.

KSP definitely seems to become slower and slower with the time, something is off. Or maybe I just remember it wrong, cant say. but it def feels slow with its pauses mid gameplay and load times of saves.

https://www.dropbox.com/s/a83oo341kjt6pvo/KSP.log?dl=0
https://www.dropbox.com/s/0whexowvqv4816i/ModuleManager.log?dl=0

https://www.dropbox.com/s/8v1q8zxvevecg2i/KSPDev-LOG.211127T110833.ERROR.txt?dl=0
https://www.dropbox.com/s/arhsx9chz6df0bo/KSPDev-LOG.211127T110833.INFO.txt?dl=0
https://www.dropbox.com/s/rrckyebowxw1xae/KSPDev-LOG.211127T110833.WARNING.txt?dl=0

commented

I've uploaded all the KSP DEV LOGs here just incase

I need the raw, untouched KSP.log, without any pre or post-processing.

here's one bit that caught my eye when I opened the console loading the game today https://i.imgur.com/fsKRiZz.png

Looks like you need to update the TSCo-KIS to the latest version, but I'm guessing. I need the full KSP.log to be sure.

commented

I've uploaded all the KSP DEV LOGs here just incase

I need the raw, untouched KSP.log, without any pre or post-processing.

here's one bit that caught my eye when I opened the console loading the game today https://i.imgur.com/fsKRiZz.png

Looks like you need to update the TSCo-KIS to the latest version, but I'm guessing. I need the full KSP.log to be sure.

The KSP.log in its freshness should be it:
https://www.dropbox.com/s/a83oo341kjt6pvo/KSP.log?dl=0

Its supposedly the same one I've posted in the Tweakscale issue post I made yesterday, but contains the same, all up to date, current state of my KSP.

Also my Tweakscale companions are up to date as well, I've take care to update every single bit of modification I have on KSP to the latest most modernized versions, so all should be at its tip top finest.

commented

The KSP.log in its freshness should be it: https://www.dropbox.com/s/a83oo341kjt6pvo/KSP.log?dl=0

Its supposedly the same one I've posted in the Tweakscale issue post I made yesterday, but contains the same, all up to date, current state of my KSP.

Also my Tweakscale companions are up to date as well, I've take care to update every single bit of modification I have on KSP to the latest most modernized versions, so all should be at its tip top finest.

That's confusing. Your loading process is pristine, everything was loaded fine - not a single Exception on the process.

Your first Exception was on loading the game:

[LOG 07:36:38.197] [HighLogic]: =========================== Scene Change : From MAINMENU to SPACECENTER (Async) =====================
[EXC 07:36:39.506] NullReferenceException
        scatterer.SkySphereContainer.Cleanup () (at <36bf44bca099450cb9f22f4b65b82426>:0)
        scatterer.SkyNode.Cleanup () (at <36bf44bca099450cb9f22f4b65b82426>:0)
        scatterer.ProlandManager.OnDestroy () (at <36bf44bca099450cb9f22f4b65b82426>:0)
        scatterer.ScattererCelestialBodiesManager.Cleanup () (at <36bf44bca099450cb9f22f4b65b82426>:0)
        scatterer.Scatterer.OnDestroy () (at <36bf44bca099450cb9f22f4b65b82426>:0)
        UnityEngine.DebugLogHandler:LogException(Exception, Object)
        ModuleManager.UnityLogHandle.InterceptLogHandler:LogException(Exception, Object)
        UnityEngine.Debug:CallOverridenDebugHandler(Exception, Object)

I didn't found a link between this Exception and any other undesired collateral effect - but you should be aware of that in order to ask scatterer's maintainer about the status of this issue.

After that, I found the reason your FPS had plummeted:

[EXC 07:37:33.482] NullReferenceException: Object reference not set to an instance of an object
        KIS.KISAddonPickup.Update () (at <717f3fbf4619476fb8c8266ee8d73162>:0)
        UnityEngine.DebugLogHandler:LogException(Exception, Object)
        ModuleManager.UnityLogHandle.InterceptLogHandler:LogException(Exception, Object)
        UnityEngine.Debug:CallOverridenDebugHandler(Exception, Object)
[EXC 07:37:33.483] NullReferenceException: Object reference not set to an instance of an object
        Part.UpdateMouseOver () (at <cd473063d3a2482f8d93d388d0c95035>:0)
        Part.Update () (at <cd473063d3a2482f8d93d388d0c95035>:0)
        UnityEngine.DebugLogHandler:LogException(Exception, Object)
        ModuleManager.UnityLogHandle.InterceptLogHandler:LogException(Exception, Object)
        UnityEngine.Debug:CallOverridenDebugHandler(Exception, Object)

Your KSP.log has some entries with these Exceptions happening inside the Update() thingy - the second worst place to have an exception, second only to the FixedUpdate. But they are only a few, not enough to screw up your FPS.

This makes KIS involved in the incident for sure, but not necessarily the culprit - something else may be borking the delicate chain of events KSP needs to run. So I kept digging and found this:

[ERR 07:40:57.406] Exception handling event onPartJointBreak in class VesselNotDestroyed:System.NullReferenceException: Object reference not set to an inst
ance of an object
  at ContractConfigurator.Parameters.VesselNotDestroyed.OnPartJointBreak (PartJoint p, System.Single breakForce) [0x00014] in <ef0243a06f2841fe9bf57034a334
902e>:0
  at EventData`2[T,U].Fire (T data0, U data1) [0x000b0] in <cd473063d3a2482f8d93d388d0c95035>:0

[EXC 07:40:57.407] NullReferenceException: Object reference not set to an instance of an object
        ContractConfigurator.Parameters.VesselNotDestroyed.OnPartJointBreak (PartJoint p, System.Single breakForce) (at <ef0243a06f2841fe9bf57034a334902e>:
0)
        EventData`2[T,U].Fire (T data0, U data1) (at <cd473063d3a2482f8d93d388d0c95035>:0)
        UnityEngine.DebugLogHandler:LogException(Exception, Object)
        ModuleManager.UnityLogHandle.InterceptLogHandler:LogException(Exception, Object)
        UnityEngine.Debug:LogException(Exception)
        EventData`2:Fire(PartJoint, Single)
        PartJoint:DestroyJoint()
        Part:ReleaseAutoStruts()
        Part:onDetach(Boolean)
        Part:onDetach(Boolean)
        Part:onDetach(Boolean)
        Part:onDetach(Boolean)
        EditorLogic:detachPart(Part)
        EditorLogic:<SetupFSM>b__189_21()
        KerbalFSM:RunEvent(KFSMEvent)
        KerbalFSM:updateFSM(KFSMUpdateMode)
        KerbalFSM:UpdateFSM()
        EditorLogic:Update()
[ERR 07:40:57.408] Exception handling event onPartJointBreak in class VesselNotDestroyed:System.NullReferenceException: Object reference not set to an inst
ance of an object
  at ContractConfigurator.Parameters.VesselNotDestroyed.OnPartJointBreak (PartJoint p, System.Single breakForce) [0x00014] in <ef0243a06f2841fe9bf57034a334
902e>:0
  at EventData`2[T,U].Fire (T data0, U data1) [0x000b0] in <cd473063d3a2482f8d93d388d0c95035>:0

And this one is virtually littering your KSP.log, and for sure is the cause of your FPS dropping.

I think you found some incompatibility between Contract Configurator and KIS - CC is borking on the onPartJointBreak that it's something I think it's called when you detach a part from the craft before storing it on an Inventory, and perhaps CC is not aware of this Use Case, and it's assuming perhaps a part being destroyed by impact - and then borking because nothing was destroyed as expected.

(on the bright side, TweakScale is not involved on this one! #hurray!! :) )

commented

After that, I found the reason your FPS had plummeted:

I'd really doubt it. The only instance of this error happens when switching from EDITOR to FLIGHT. And it's accompanied with about sixty of non-KIS related errors from the game's core. If any of these errors were happening on a regular basis, it could explain the FPS drop, but they they happen only once on the scene change. It could delay the scene switch,, but I don't see how it could introduce the "occasional freezes" pattern in the flight scene.

commented

I'll also add gents, I added Contract Configurator to my mod list only yesterday or two days ago, the Mystery Goo animation FPS destroy was prominent wayyyyy before back,

I am well aware that CC is junk food for KSP. But thats one ailment on the game to the aside for now, I don't mind it. (Although I did notice ingame longer duration stutters once I added CC, individual new stutters without any relation to anything, they became like 2 second stutters which I never had before, so I might throw it to the trash soon. Also considering the extra load time ingame, CC by itself is junky and not worth the hasstle unless improved some day.)

So in conclusion CC is a bit of a tumor on KSP as well now as I see, introduced new stutters, longer loading time ingame, but all that is individual. Unrelated to the Mystery Goo animation fps suicide which was way before I added any new mods aka 2 days ago with CC.

commented

Now we have NREs happening elsewhere. :(

[EXC 11:17:18.684] NullReferenceException: Object reference not set to an instance of an object
        Atmosphere.CloudsPQS+<DelayedCheckForSphereInactive>d__28.MoveNext () (at <55c642afbee74281902298847b0d4e84>:0)
        UnityEngine.SetupCoroutine.InvokeMoveNext (System.Collections.IEnumerator enumerator, System.IntPtr returnValueAddress) (at <12e76cd50cc64cf19e759e
981cb725af>:0)
        UnityEngine.DebugLogHandler:LogException(Exception, Object)
        ModuleManager.UnityLogHandle.InterceptLogHandler:LogException(Exception, Object)
        UnityEngine.Debug:CallOverridenDebugHandler(Exception, Object)

and

[EXC 11:22:43.361] NullReferenceException
        UnityEngine.MonoBehaviour.StartCoroutine (System.Collections.IEnumerator routine) (at <12e76cd50cc64cf19e759e981cb725af>:0)
        KRASH.SimulationPauseMenu.CallbackWillDestroy (Vessel evt) (at <433f585c92d34e5cb35a72f645a4dbbb>:0)
        EventData`1[T].Fire (T data) (at <cd473063d3a2482f8d93d388d0c95035>:0)
        UnityEngine.DebugLogHandler:LogException(Exception, Object)
        ModuleManager.UnityLogHandle.InterceptLogHandler:LogException(Exception, Object)
        UnityEngine.Debug:LogException(Exception)
        EventData`1:Fire(Vessel)
        Vessel:Die()
        Part:Die()
        Part:explode(Single)
        Part:explode()
        Part:HandleCollision(Collision)
        Part:CheckCollision(Collision)
        Part:OnCollisionEnter(Collision)

and

[ERR 17:32:11.164] Exception handling event onFlightReady in class EvaController:System.ArgumentException: An item with the same key has already been added
. Key: 38350f48-d5bf-4f62-83f7-e7d581beccd7
  at System.Collections.Generic.Dictionary`2[TKey,TValue].TryInsert (TKey key, TValue value, System.Collections.Generic.InsertionBehavior behavior) [0x000c
1] in <9577ac7a62ef43179789031239ba8798>:0
  at System.Collections.Generic.Dictionary`2[TKey,TValue].Add (TKey key, TValue value) [0x00000] in <9577ac7a62ef43179789031239ba8798>:0
  at MSD.EvaFollower.EvaSettings.LoadEva (System.String eva) [0x00007] in <d269c489a4a142f795c6945ec2197936>:0
  at MSD.EvaFollower.EvaSettings.LoadFile () [0x00069] in <d269c489a4a142f795c6945ec2197936>:0
  at MSD.EvaFollower.EvaSettings.LoadFunction () [0x00005] in <d269c489a4a142f795c6945ec2197936>:0
  at MSD.EvaFollower.EvaSettings.Load () [0x00034] in <d269c489a4a142f795c6945ec2197936>:0
  at MSD.EvaFollower.EvaController.onFlightReadyCallback () [0x0000a] in <d269c489a4a142f795c6945ec2197936>:0
  at EventVoid.Fire () [0x00127] in <cd473063d3a2482f8d93d388d0c95035>:0

[EXC 17:32:11.164] ArgumentException: An item with the same key has already been added. Key: 38350f48-d5bf-4f62-83f7-e7d581beccd7
        System.Collections.Generic.Dictionary`2[TKey,TValue].TryInsert (TKey key, TValue value, System.Collections.Generic.InsertionBehavior behavior) (at
<9577ac7a62ef43179789031239ba8798>:0)
        System.Collections.Generic.Dictionary`2[TKey,TValue].Add (TKey key, TValue value) (at <9577ac7a62ef43179789031239ba8798>:0)
        MSD.EvaFollower.EvaSettings.LoadEva (System.String eva) (at <d269c489a4a142f795c6945ec2197936>:0)
        MSD.EvaFollower.EvaSettings.LoadFile () (at <d269c489a4a142f795c6945ec2197936>:0)
        MSD.EvaFollower.EvaSettings.LoadFunction () (at <d269c489a4a142f795c6945ec2197936>:0)
        MSD.EvaFollower.EvaSettings.Load () (at <d269c489a4a142f795c6945ec2197936>:0)
        MSD.EvaFollower.EvaController.onFlightReadyCallback () (at <d269c489a4a142f795c6945ec2197936>:0)
        EventVoid.Fire () (at <cd473063d3a2482f8d93d388d0c95035>:0)
        UnityEngine.DebugLogHandler:LogException(Exception, Object)
        ModuleManager.UnityLogHandle.InterceptLogHandler:LogException(Exception, Object)
        UnityEngine.Debug:LogException(Exception)
        EventVoid:Fire()
        <PostInit>d__34:MoveNext()
        UnityEngine.SetupCoroutine:InvokeMoveNext(IEnumerator, IntPtr)

This suggests that something else was causing the problem, and Contract Configurator was only the first victim on the chain to be hit. With CC gone, the next victim from the chain is picked instead, so the problem persists.

Usually (but not always) the first Exception logged is related to the problem, because Exceptions breaks chains of execution, rendering a lot of initialisations undone - what, obviously, will break everybody that need that initialisations - potentially letting yet more code undone, with yet mode data uninitialised, in a nasty chain reaction pretty hard to diagnose.

Try to remove scatterer to see what happens. Rinse, repeat.

You will need to remove one add'on at time, otherwise you will not be able to diagnose exactly who is borking on you - and even by that, there still a chance that you only emptied that chain of victims and the culprit was left dormant until you install something that will trigger it again.

To fully diagnose the issue, we would need to reinstall the add'ons removed on a clean KSP installment, and monitor things to see what one of them triggers again the problem.

commented

I'd really doubt it. The only instance of this error happens when switching from EDITOR to FLIGHT. And it's accompanied with about sixty of non-KIS related errors from the game's core. If any of these errors were happening on a regular basis, it could explain the FPS drop, but they they happen only once on the scene change. It could delay the scene switch,, but I don't see how it could introduce the "occasional freezes" pattern in the flight scene.

Some exceptions are happening on the Part.Update, but these happens only a few times and stop.

Others are happening inside Co-Routines, and so they can cause freezes at any time - and we don't know when these co-routines are fired, only that they were fired.

Additionally, I found some interesting messages from TweakScale:

[LOG 17:31:06.785] [TweakScale] ERROR: Exception on rescale while ¬TSGenericUpdater: System.NullReferenceException: Object reference not set to an instanc
  at TweakScaleCompanion.KIS.Inventory.TweakScalerKISInventory.OnRescale (TweakScale.ScalingFactor factor) [0x0004a] in <42b57c759f324dc5a585d250c585fb00>
  at TweakScaleCompanion.KIS.Inventory.Scaler.OnRescale (TweakScale.ScalingFactor factor) [0x00000] in <42b57c759f324dc5a585d250c585fb00>:0
  at TweakScale.TweakScale.CallUpdaters () [0x000bb] in <938b4024d9a14732a373a3bc42d4afc3>:0  at error:0
[LOG 17:31:22.212] [smallClaw Restock.ModuleRestockConstraints] Loading 3 constraints
[LOG 17:31:22.213] [smallClaw Restock.ModuleRestockConstraints] Loaded 0 constraints
[LOG 17:31:30.671] [TweakScale] WARNING: No valid member found for mass in TweakScale for probeStackSmall

Last time I had seen these, it was happening due a B9PS bug that was not removing dead parts from a GameEvents, and so each time you killed a vessel, a new lot of parts were being left to that GameEvents - and that zombies lingering were responding to TweakScale remote calls for rescaling and, being zombies, didn't had the data needed to do the work - since these weird exceptions above.

With some Exceptions happening inside CoRoutines, it's reasonable to assume that whatever the CoRoutine was doing, was left incomplete - and my guess is that some of these things left incomplete were removing dead PartModules from some GameEvent.

As that GameEvent grows with lots of zombie objects eating up memory and heap, the Garbage Collector are triggered all the time - and this may be the cause of the freezes mid-game.

commented

Actually, when i've been doing my first amateur try and attempt to find out the root of this, I did remove all of them certain mods in batches, three by three.
None prevented this issue of the Goo lag, I took off scatterer + redux + planetshine + spectra, that was not it.

Scatterer may be pooping exceptions regardless of the case (taking a look at their issue page and their upcoming pre release) it seems like a very scatterer'y thing,

but not until I've taken off KIS and my whole mun base despawned yet no goo lag existed, only then I decided to write this post.

Starting a fresh install game would too be of an issue, considering I have so much dependent on it to recreate just to test it out, but with the yield we have right now, I got no idea if its even worth the hasstle, I doubt it will bring a result.
I may have zero experience in the whole technicallity of it,
but since i've already took a few hours to pull out one by one and mess around and see whats up (without the logs ofc since i am no code pro like you gents :) ).
Took ages, but yielded now apparently no result other than showing me that when I pulled KIS and my base vanished, no Goo issue existed.

So I legit am clueless.

Ironically, this is legit like human anatomy and medicine,
people get sick but most often it begins showing symptoms in the non root areas, eventually with one issue being removed or "stabilized" then it continues deeper and deeper until the main source is found. (That is of chronic and autoimmune diseases, the heavier more permanent long term type of stuff)

commented

Others are happening inside Co-Routines, and so they can cause freezes at any time

When a coroutine throws an exception, it dies. It cannot keep bugging the game anymore. So, the moment of the exception is the only moment of possible freeze. The coroutines that throw at the scene switch cannot affect the new scene - they simply don't exist there.

The cleanup thing you've suggested can be a reason though. However, I'd say it's very unusual to do any cleanup from the coroutine (it can die prematurely when the GameObject dies).

All in all, my point is that we first need to cleanup the log from the exceptions that are not directly related to KIS. Then there will be a possibility to start working specifically on this mod.

but not until I've taken off KIS and my whole mun base despawned

And that's the problem of troubleshooting by removing mods vs adding new. Your mun base disappeared because you've removed KIS. How you know it was KIS that caused troubles, but not the mun base? I'm not saying it wasn't KIS (no idea at this moment), it's just about the approach to detect the source of the problem.

However, it gave me an idea. Can you restore the old save where the base was existing, and then cut the base out from the save (or just blowing it up from EVA, KIS offers a nice tool for that)? Don't forget to reload the game after that to ensure any accumulated garbage is cleared up. If the problem gone, then the issue was in the base.

commented

Others are happening inside Co-Routines, and so they can cause freezes at any time

When a coroutine throws an exception, it dies. It cannot keep bugging the game anymore. So, the moment of the exception is the only moment of possible freeze. The coroutines that throw at the scene switch cannot affect the new scene - they simply don't exist there.

Exactly. And whatever it needed to be done is left undone. Including initialising data structures and removing objects from the GameEvents.

Uninitialised data structures triggers more exceptions later when someone else try to use that data.

Objects that should be dead left on GameEvents will waste CPU as they will be called nevertheless, and whatever data they relies would be probable garbage collected, leading to more exceptions.

commented

Pc burnt, just got it back fresh
Will take a bit to further test