Mod Timing

[lperkins2]

So, I've been having a bit of lag in a heavily modded colony, and decided to try to investigate.  Unfortunately, rimworld doesn't expose any sort of timing data to help figure out what the issue is, so I decided to add some.  Unfortunately, I've run out of time to get it working, but maybe someone more talented can figure it out.

I started by making Hugslib report when a mod's OnTick, or OnUpdate takes more than 0.2 ms to run.  It works fine, but none of the mods seem to be taking too long on global updates. 

There are two other areas I wanted to add timing info, as they seem most likely to be causing lag with badly written mods.  The first is the job system: jobgivers, workgivers, and jobdrivers.  Lots of time lag spikes are from pawns getting assigned jobs which immediately get invalidated, causing an AI loop of picking new jobs.  My thinking was to catch when that happens and log what the failed job was and anything possible about why it failed.

The second is diverted code.  Harmony can give a list of methods that have been patched, and the patches attached to them.  My thinking was to patch the patch methods, noting down the start time and then tabulating how much time is spent in each method.  While this seems to work in a test project, I can't get Harmony to let me patch anything in rimworld, I think because I managed to break mono. 

As I said, I've run out of time to work on it, especially since I can't get even the basic demo for harmony to work.  If I get some spare time, and manage to fix that, I'll come back to this.  If anyone can see a better way to go about this, or a reason it won't work, I'm all ears.  If anyone with a fully working dev environment wants to implement this, that'd be great.

[Nightinggale]

DeepProfiler.Start(someString) and DeepProfiler.End() can be used for crude profiling. Whenever end is reached, someString will show up in the log with the amount of ms spend between those two lines. However it will only happen if verbose logging is enabled.

If you suspect a certain method is causing a slowdown, you can attach a Prefix and Postfix using Harmony to get profiling for it.

For instance if you suspect the job system of using a lot of time, then it could be interesting to profile how long a tick last as well as one or more methods related to jobs. This will create a lot of numbers in the log, which you can then gather using a script. The collected numbers can then be used to count how many %of each tick is used on jobs and basically count how much many calls use 1 ms, 2 ms etc and get a graph of the distribution. It will likely reveal a somewhat close group and then a few calls, which use way more time than that.

Now that I think about this issue, it could be interesting to take it one step further and use Transpillar to inject code to get the time spend on each job. Release this as a mod together with a script to calculate time statistics from the log and people will be able to figure out if there is a single job, which is responsible for the visible slowdown.

While it could be interesting to make right away, I got other stuff to do. If anybody wants to actually do it, don't hold back, but please tell. We don't want double work 

[lperkins2]

Harmony's prefix and postfix system lets you track state, so __state = DateTime.Now.Ticks in the prefix and then calculating the time passed in the postfix is simple.  I don't know if DeepProfiler.Start works if it's already been started.  The hard part is profiling the patch methods.  You can apply a patch to the already patched methods, set to first priority and last priority to get the total time taken in the patched methods, but no good way to get the time taken per patch.  On the other hand, you can patch the patches themselves, but there doesn't seem to be a good way to track which patch is currently running.  In other languages, I'd use a closure, to note the name of the patch, and owning mod, in the profile patch's enclosing namespace, but Harmony requires static methods so I've not figured out how to do that.  Another option would be to do some magic with the stack to figure out which patch we're in, but once again I don't know how to do that.  Your idea of using the transpiler is probably the most robust, but I really don't have time at the moment to learn how that works. 

As for profiling jobs and job givers, they do seem to generally subclass the base implementation, but most mods don't super the job tick, so adding profiling to the base implementation doesn't do any good.  I don't know if there is a reflection option to get a list of subclasses which override the relevant methods, but applying the profiling patch to those would probably get the relevant information. 

If anyone wants to work on this and collaborate, we can see about setting up a repo on github or something.

[Nightinggale]

I don't know if DeepProfiler.Start works if it's already been started.  The hard part is profiling the patch methods.

It implements a stack, meaning you can safely start, call something and then end right after the call. If DeepProfiler is already working or is called somewhere in the call, it will just use the stack to still work as intended. The log entries will be indented to inform of the stack layout in case of nested calls.

Harmony Prioritiy annotations makes it look like it's possible to add two postfixes and by using [HarmonyBefore(string[])] and [HarmonyAfter(string[])], it should be possible to start DeepProfiler just before a specific Postfix starts and stop it when it ends. Profiling a Prefix, which returns false is more problematic as it will stop the execution of even the prefix, which will stop the profiling.

As for profiling jobs and job givers, they do seem to generally subclass the base implementation, but most mods don't super the job tick, so adding profiling to the base implementation doesn't do any good.  I don't know if there is a reflection option to get a list of subclasses which override the relevant methods, but applying the profiling patch to those would probably get the relevant information.

That's why I wrote about Transpillar. That will make it possible to inject start and stop code for DeepProfiler just before and after the call and then it doesn't matter which version of the virtual method is called.