Basic Profiling Support for KSP innards and Mods

[Lennartos]

While we do have a FPS view under the debug window we lack any kind of info on what exactly is affecting the speed.
This wastes a LOT of unneeded cpu cycles and end user performance, since modders dont have access to a proper profiling window and thus cannot estimate the CPU cost of their mod effectively. ( which in turn means un-optimized mods or worst case someone doing per frame calculations since they don't feel a drastic draw-down using only a few mods )
I heard you are using the default unity update loop logic and thus are not directly in control of calling the updates ( which could be a effective improvement if you take the amount of classes attached to each object in regard - see http://blogs.unity3d.com/2015/12/23/1k-update-calls/ ), So you cannot enforce profiling by yourself - however using a simple stopwatch list and dictionary with some public access functions you can allow both yourself and modders to add named entries into a list which allow a quick view of the innards of whats taking so long.
Often the cause of slowdowns can be incompability between mods or just issue with version updates like we just had with 1.1.2, and as a end user i at least had a very hard time figuring out exactly which mod was causing the issue (131 installed mods and counting)...

I'm thus proposing a simple piece of code like unitiy's profiler:
 

        KSPProfiler.BeginSample("MyPieceOfCode");
        KSPProfiler.EndSample("MyPieceOfCode");

Once EndSample is called you check the correct stopwatch and insert its elapsedtime into a dictionary with the name as key, and show under the default F12 FPS view as a list,
It would be up to SQUAD and the modders to add this to their code for now, but it would be a very helpful tool for everyone involced and allows us end users to get a idea of whats causing our < 100 part craft to snail along with low FPS and horrible simulationtime ratio.

[NathanKell]

 

[Lennartos]

Yes i tried that as a end user to track a slowdown i had, which made me create this post.
While this hack does allow one to test ones own mod, as a end user its not helpful at all.
1) because 99,9% of all lines are just mono.dll or unityengine.dll calls with no info since its not a full debug release with the necessary pdb files,
2) because there is no consensus that this has to be supported offiicially, mods dont release the pdb files with their mods either.
So i can only see that something is taking up time, but i can see the same info inside the simple FPS viewer.
What is missing is a way to see if its a MechJeb feature that is using 17ms per frame, or Remote Tech... or some SQUAD function, like calculating resources or the new wheels code - so you can report the issue to the correct person... which then can track it with debugging their own code.
Atm its just guesswork and many many hours spend uninstalling and reinstalling folders and mods to circle in what can be the cause.
Which means its really not useful for tracking real life situations ( bug only appears after long duration and in combination with x )  - only once a bug has already been confirmed and found a way to recreate it will this help to advance the tracking of whats wrong.

So either we need to promote debuggability, and provide pdb files as default for this ( which requires people to be power users with coding & profiling knowledge to report better error reports ) ...
or we need basic profiling support so its just a matter of reading a simple list box that anyone can do.

EDIT:
And as far as modders are concerned, there is simply no way to test a mod in all possible combinations with other mods / Real life situations.
"In game" profiling would allow to collect data from the actual users, beyond the developers controlled environment, and detect conflicts/issues by simply comparing data from multiple users,

Edited May 5, 2016 by Lennartos

[NathanKell]

All mods must release source with them, therefore you can recompile them with pdb files.

[Lennartos]

Yes, if the cause was a mod, and i already knew which mod was causing the issue i could debug that single mod and solve it.
But thats not really solving the issue, which is figuring out WHICH of the 130 mods i need to look at - or if its a mod at all.
We simply lack some very basic tools to get a overview over whats happening - WHY is FPS low - what part of the code/game is slowing down.
Anything i say more would essentially just be repeating the points above.

Finding a known issue, in a known filebase (which mod / part of the codebase) that is easely reproducable is a lot different from finding "random" slowdowns that only happen after playing a while.
The second DO happen, and my game still isn't that fluid atm and i simply have no chance of knowing whats causing it without recompiling 130 mods and hoping i will get lucky.
Dictionary with stopwatch would be a few hours / single day well spend for future patches.

[ShotgunNinja]

I think its not practical to assume most mods will use this feature if present, so that you can have a panoramic view of what's taking time. The unaccounted time will then be a problem in the analysis. Also profiling isn't cheap, the reason is for the time measurement you got only two choices at the end of the day: call QueryPerformanceCounter, or get the timestamp register value. The former is slow (in the realtime graphics sense of the term), the latter is faster but can't be interpreted as wall clock. If you get key methods (the most called, incidentally the ones you want t o profile) to open and close with a WINAPI call, or even rdtsc, you will just add a lot of overhead, I mean it, a lot. This is a common problem, many are just moving to external sample-based profilers for this. The best solution, in my opinion, is to make your own simple profiler and use it to profile your own mod, then disable it in release.

Maybe we could collaborate to make one and share it with the community, to avoid reinventing the wheel? I like the API you proposed, I created and used something very similar for a long time. Regards.

[Lennartos]

10 hours ago, ShotgunNinja said:

I think its not practical to assume most mods will use this feature if present, so that you can have a panoramic view of what's taking time. The unaccounted time will then be a problem in the analysis. Also profiling isn't cheap, the reason is for the time measurement you got only two choices at the end of the day: call QueryPerformanceCounter, or get the timestamp register value. The former is slow (in the realtime graphics sense of the term), the latter is faster but can't be interpreted as wall clock. If you get key methods (the most called, incidentally the ones you want t o profile) to open and close with a WINAPI call, or even rdtsc, you will just add a lot of overhead, I mean it, a lot. This is a common problem, many are just moving to external sample-based profilers for this. The best solution, in my opinion, is to make your own simple profiler and use it to profile your own mod, then disable it in release.

Maybe we could collaborate to make one and share it with the community, to avoid reinventing the wheel? I like the API you proposed, I created and used something very similar for a long time. Regards.

Well only if it would be official from SQUAD would modders likely integrate into all, but yeah - making our own solution might be a first step to general acceptance.
I have never made GUI inside KSP - im thinking we will need something to simulate a treeview to hide away internal "inclusive" nodes until wanted.
So + button to expand a node - do you have the necessary knowledge to do that atm?

[Lennartos]

As for performance i got a few ideas:
1) its disabled per default, once activated we sum all times together until deactivated again ( we then show accumulated performance statistics or measurement window)
2) we already know that its single threaded, so there is actually no need for more complexity than a single stopwatch and then just get the elapsed time on each sample start /end.
The speed cost during those few seconds is neglible and easely acceptable since it doesnt affect runtime performance for end users

The only real cost is checking/detecting if the mod is installed and then skip the code.
Whats the best way to solve that?

Edited May 6, 2016 by Lennartos

[ShotgunNinja]

I have messed around with GUILayout stuff and it should't be hard to make an UI for this.

I was thinking more about a self-contained class that one would just include in its sources, instead of a mod.

I believe C# has some facilities to disable functions using compiler flags (so no code is emitted, and the dev don't need to comment / uncomment the profiler calls). That can be used for the profiling calls.

Detecting if a mod is installed is 'relatively' costly, but can be done just once (then we just evaluate a bool for each profiling call). I we use the 'include in your source'  approach we don't even need to do this.

Do you have any experience with writing hierarchical profilers? Myself I always wrote and use 'flat' ones. Sure it may be desiderable to have the hierarchy.

We should make a 'frame-based' profiler, were each entry has:

- average function time
- number of calls
- total function time

all relative to the last frame.

What you think?

 

[NathanKell]

OnGUI is not a good choice. It chucks garbage and is itself slow.

Also IIRC from Sarbian you will at least get toplines without pdbs. I highly suggest you try the method described before baldly dismissing it.

[Padishar]

1 hour ago, NathanKell said:

OnGUI is not a good choice. It chucks garbage and is itself slow.

Indeed it is.  Try installing this mod and then, once at the main menu, hit Mod-F2 to display the log window.  When I did this earlier I was getting ~28 KB/s sat at the main menu but nearly 5 MB/s when the log dialog was open...

I've also written a simple profiler for the internals of KSP that graphs the percentage of time the main thread spends in various functions.  A mod can easily be profiled by inserting the start and stop calls directly in the mod source or the PatchAsm part could be extended to support patching of different assemblies.

[Lennartos]

very interesting Padishar, will test immidiatly.
But sounds to me like you almost solved it all already.

If PatchAsm could also auto insert your profile code automatically in all the assemblies with assembly name + class name filled in ( attaching to basic entries like updpate etc ), then we would already be golden for a quick overview.
And again: we dont need another profile method for code we created ourselves, thats what serbians hack is for - the point is to oveview ALL code paths and detect anomalies ( something broke / is incompatible )  or general resource usage ( so we know cost of specific mods )

Even better: we would have memory + profiling in one tool.

[Lennartos]

Just tried serbians profile hack again, and this time installed 5.2.4 instead of using the 5.3.1 i already use for a project.
Now i actually get correct profile data, and a basic overview.

Its not something that the average user can do, but at a glance i can now see that a really big sinner is ampyear, consuming an entire 4ms + allocating 358KB each frame.