Performance Issues

[Kleptine]

Environment

• Version of Malimbe (Github release number) (Github branch and commit hash)
  v9.4.2

• Version of the Unity software (e.g. Unity 2018.3)
  2019.1.1f1

Steps to reproduce

Open the attached profiler session.

I'm pretty excited to use Fody and Malimbe, specifically for the XML documentation weaver, but I'm seeing some pretty drastic compilation performance issues on what is really a fairly simple project.

Compilation time before Malimbe: 8-10 seconds
Compilation time after Malimbe: 18-20 seconds

Most of the time is spent in the OnCompilationFinished callback. Some of the time seems to be spent traversing files and another good portion is waiting for an unclear Async task. I've attached a Unity profile session so you can look through it yourself.

Link to profiler session: https://drive.google.com/file/d/1s7df-o4q4h4GWwxODncBMvqlFBnKf3TG/view?usp=sharing

The attached profiler session expands to 4Gb, just a heads up.

Additionally, here is my FodyWeavers.xml

<?xml version="1.0" encoding="utf-8"?>

<Weavers>
  <Malimbe.FodyRunner>
    <LogLevel>Error, Warning</LogLevel>
    <AssemblyNameRegex>^Zinnia</AssemblyNameRegex>
    <AssemblyNameRegex>^Assembly-CSharp</AssemblyNameRegex>
  </Malimbe.FodyRunner>
  <Malimbe.XmlDocumentationAttribute/>
</Weavers>

[bddckr]

Unity crashes loading the profiler data :(

another good portion is waiting for an unclear Async task

That should be the actual weaving task. That taking the most time is expected, however a long wait is unexpected, especially once your project is compiled and weaved after the first time.

Is your project huge? If it is you could try utilizing assembly definition files to split up your codebase into smaller, separate chunks that can be compiled independently from another.

In general more information about the call stack that is taking so much time according to Unity would help - turning on the deep profile button in the profiler (as well as the editor one) should give the necessary data.

[Kleptine]

Oh boy, hmm. Let me do a profile pass on an empty project.

The project is rather simple, I created it a few weeks back. There's a handful of fairly large plugins, though, and that may be partially the cause, but it's not more than you might expect, really, and some of those already have assemblies broken out.

[Kleptine]

Here's a better profiling session. I created an empty project with the LWRP and VR Unity template. The compile times go from 3.5 seconds to 6.5 seconds, when installing Malimbe:

Based on this test, it seems like Malimbe is roughly doubling compile times? My understanding is that a significant portion of normal Unity build time is not compilation (which is ms for this project) but the assembly loading, analysis, and domain refresh. I wonder if something in Malimbe is also reloading assemblies in a duplicative way?

Does Fody have to actually boot up a fresh domain and load assemblies in order to weave it? Or can it just act on the IL as data?

Here's the profile session with a deep profile enabled. File attached below, and seems to load properly this time! It's still a ridiculous size, though, about 1.4Gb, but loads pretty quickly. See the screenshot below. The compilation is on frame 189 in the profile.

The full profile:

Quick analysis:

Malimbe adds 3 seconds to the work. Here's the first 1.5 seconds. It looks like it's sorting a large array and doing a directory traversal.

Zoomed in on the second 1.5 seconds. Similar work, it looks like? Maybe this could be optimized or at the least cached?

Here is the profiler session: https://drive.google.com/file/d/1hy1VGERHbGzUNWU1hIV7MiFyFtuypSpR/view?usp=sharing

Here is the empty project I created, wrapped up with Malimbe installed. The profiler session is in this one too.
https://drive.google.com/open?id=1MoEywiHJr-OPuKsjzNNswGydBUuqaNwI

[bddckr]

it seems like Malimbe is roughly doubling compile times?

I'd expect a constant time being added as part of Malimbe when the assemblies don't need to be weaved/are already weaved. The actual weaving process depends on the assembly size and the configured weavers/addins.

I wonder if something in Malimbe is also reloading assemblies in a duplicative way?

Malimbe is not doing any such thing - we hook into Unity's compilation pipeline, right after it itself is done compiling, but before it's using the resulting assembly files to load into the editor's memory. This way all we need to do (and actually do) is to work with the passed assembly files, then block in the callback of Unity's compilation pipeline so it doesn't already load those assembly files before we're done with them.

Does Fody have to actually boot up a fresh domain and load assemblies in order to weave it? Or can it just act on the IL as data?

This is done with Cecil. It doesn't load assemblies, instead all it does is parse the assembly files and act on the IL.

---

It's still a ridiculous size, though, about 1.4Gb

Thankfully it compresses nicely for sharing purposes at least 😄

Maybe this could be optimized or at the least cached

Caching properly is almost impossible as we don't know whether a package was installed in between (either by dropping the code into the assets folder, using UPM or importing). One could argue that by doing something like "if it just happened a few seconds ago it should be safe to not run Malimbe again", but that will end up with edge cases that run through without weaving. That in turn is really bad, as some weavers do things that directly interface with Unity's serialization. They need to run each time, otherwise you end up with bad state.

If we look closely this is what we see:

• ~1400ms are spent in the compilation callback.
• 409ms of those is us waiting for Unity's CompilationPipeline.GetAssemblies. Can we speed this up? No. It doesn't help that Unity sort the return values, but we can't do anything about it. Can we call this less often? Not without opening up cache issues, as I don't see a way for Unity to tell us when assemblies get added.
• 256ms are spent in WeaverPathsHelper.GetSearchPaths. All of that time is spent in Unity again, this time in Client.List(true). Can we speed this up? Well we're already telling it to use offlineMode which should speed things up by not hitting any remotes and there's nothing else we can do. Can we call this less often? Again I don't see any callbacks/events in UnityEditor.PackageManager, so we'd end up with cache issues in edge cases.
• The final 722ms in Runner.Configure is mainly doing file lookups, the rest is pretty much negligible. Can we speed this up? We could only look for the configuration file FodyWeavers.xml in the root level folder instead of all subfolders. This still doesn't help enough as we have as many directories to check as you have UPM packages installed. Can we call this less often? Caching the gained information after the first time we look in a specific folder and then utilizing FileWatchers would work. This obviously adds additional complexity, especially since that cached information needs to be persisted somehow, even across the domain reloads Unity does. We only call this method once as needed already, so we're good in that regard.

The actual weaving process is reported to take ~0.21ms for the single assembly that changed according to the OnComilationFinished callback. 20ms were spent for the 21 assemblies in the project when the assembly reload re-initialized the EditorWeaver again (OnEditorInitialization). I'd say the weaving process itself is fast enough when looking at these numbers. 😄

We could basically half the numbers by somehow knowing for sure that we don't have to WeaveAllAssemblies if that is just happening because OnEditorInitialization was called right after being done with compilations that Malimbe already handled.

The file lookups could be resolved by enforcing the use of a scriptable object asset that you have to manually reference all configuration files to use, but I like the fact that right now any third party asset can use Malimbe, too, and it just works for consumers (as long as Malimbe is part of the project through dependencies or directly).

I believe that's the only good optimization we can do without ending with unhandled cases resulting in non-weaved assemblies. Let me know if you have any ideas regarding caching things to call them less often, whether I missed some good ways to maintain knowledge about the state of the assemblies and project on disk or anything else that comes to mind.

[Kleptine]

Thanks for the detailed look! I'm betting the 'doubling' behavior that added 10 seconds was because the performance is linear with the number of files, and my bigger project just had more files and plugins in it.

If I'm understanding correctly:

409ms in CompilationPipeline.GetAssemblies():

• Perhaps we could file a bug report for this one, to at least allow disabling the sorting mechanism, when it's not needed? Here's the rogue sort line.
• Aggressively, this function could be lifted up out of the Unity dll and customized a bit. Although that could be a bit of a task, and bring some license questions.

256ms + 722ms to find FodyWeavers.xml (list packages, and search all paths):

• We could use the ScriptableObject asset idea, but have one asset for every FodyWeavers.xml file. So rather than searching for the xml files directly, we have Malimbe.weavers files for each with a property pointing to the path (or paths) of the FodyWeavers.xml file for that plugin/library/folder. This way you could keep the same FodyWeaver.xml files in the sub folders, but the Unity importer would take care of locating them all, and it stays compatible with other tools. If you wanted to depend on a library that didn't include a Malimbe.weavers file, you could create a custom Malimbe.weavers file elsewhere in the project that pointed to that path.

We could basically half the numbers by somehow knowing for sure that we don't have to WeaveAllAssemblies if that is just happening because OnEditorInitialization was called right after being done with compilations that Malimbe already handled.

The OnEditorInitialization comes from needing to run weaving on Editor startup? Does it not trigger a compile hook then? Or is it because it's possible for the Assembly to be swapped out when the editor is closed (without triggering a recompile).

We could at least store the hashes of 'successfully woven' assemblies. Then, if we see an assembly with that hash we know it doesn't need to be done again. This could also be accomplished with a flag set in the assembly during the weave process, perhaps. If all assemblies are woven, no need to look for FodyWeaver.xml or do anything further.

The actual weaving process is reported to take ~0.21ms for the single assembly that changed according to the OnComilationFinished callback

This is great to hear! Glad it's mostly a Unity-interop issue!