Test performance regression between 4.8 and 4.9.2, still there in 4.10

[TymurGubayev]

Version Used: 4.8, 4.9.2

Steps to Reproduce:

1. Write lots of tests (using MSTest) that are creating Roslyn workspaces from sln files (for some code transformations using Roslyn)
2. Run them with Roslyn 4.8
3. Run them with Roslyn 4.9.2 (or 4.10)

Notice they now run

Expected Behavior: For about 300 tests, about a minute.

Actual Behavior: Same code, no other changes, about 8 minutes.

Some context I'm doing some code transformations in VB.NET code; it's a stand-alone tool (run from command line, not an IDE extension or anything like that). All the tests look like following:

var workspace = MSBuildWorkspace.Create();
var solution = await workspace.OpenSolutionAsync(slnPath, new ConsoleProgressReporter()).ConfigureAwait(false);
var testee = new ThingIAmTesting(); //which is derived from VisualBasicSyntaxRewriter
var newSolution = await testee.ProcessSolutionAsync(workspace.CurrentSolution, includeFiles: new[] { f }).ConfigureAwait(false);

where ProcessSolutionAsync is basically

foreach (var projectId in solution.ProjectIds)
{
    var project = solution.GetProject(projectId)!;
    foreach (var docId in project.DocumentIds)
    {
        var doc = project.GetDocument(docId);

        var tree = await document.GetSyntaxTreeAsync().ConfigureAwait(false);
        var root = await tree.GetRootAsync().ConfigureAwait(false);

        var newRoot = base.Visit(root);
        // code to update everything is skipped here, it's stored in a `newSolution` object
    }
}

workspace.TryApplyChanges(newSolution);

[ToddGrun]

Hi Tymur, This is odd, from the code you've displayed, I would have expected some performance improvements between the 4.8.0 release and the 4.10.0 release. Just so I'm clear, you saw this take about 1 minute when using 4.8.0, and it jumped to about 8 minutes in 4.9.2 and 4.10.0 releases? If that is so, that is horrible. Would it be possible for you to gather etl traces of the before/after so we can take a look at exactly what area has regressed? Thanks!

How to collect performance profiles https://github.com/dotnet/roslyn/blob/main/docs/wiki/Recording-performance-traces-with-PerfView.md

[TymurGubayev]

Just so I'm clear, you saw this take about 1 minute when using 4.8.0, and it jumped to about 8 minutes in 4.9.2 and 4.10.0 releases?

yes, 4.8.0 takes 1 minute, and both 4.9.2 and 4.10.0 take 8 minutes.

Would it be possible for you to gather etl traces of the before/after so we can take a look at exactly what area has regressed?

I'll try.

[TymurGubayev]

Would it be possible for you to gather etl traces of the before/after so we can take a look at exactly what area has regressed?

I'll try.

So, got the perfview results for 4.8.0 and 4.9.2, the zip files are 407Mb and 1.2Gb, respectively. Where can I upload them to?

[TymurGubayev]

Uploaded to https://filetransfer.io/data-package/Qnfruhzv#link but the link has an expiration date: 7/4/2024, 2:19 PM

[ToddGrun]

@dibarbet -- Looks like there is a bunch of new time being spent in the build host.

@TymurGubayev -- To clarify, is the following line being run in a loop for multiple solutions?

await workspace.OpenSolutionAsync(slnPath, new ConsoleProgressReporter()).ConfigureAwait(false);

[ToddGrun]

@dibarbet -- per our offline conversation, it looks like about 75% of CPU time in the build host is jitting:

[dibarbet]

When await workspace.OpenSolutionAsync is called, we now launch a separate process to run the MSBuild design time build. This is an intentional change to fix correctness issues around loading projects.

Generally, when loading a solution, we attempt to only create 1 process to load all the projects in the solution. From the trace it looks like we're creating a ton of build host processes - I assume this is multiple tests running and each loading solutions?

As Todd mentions above, it looks like we're spending a lot of time in JIT - each process that launches is running JIT. From the trace a total of 204 sec of CPU time is just spent there. @jasonmalinowski we might want to consider shipping platform specific binaries with R2R for the build host here.

There's definitely things we can do on the Roslyn side to speed things up (as mentioned above), but it may take some time and I'm not sure we'll be able to entirely eliminate the new overhead - as running the design time build in a separate process is important for correctness (unless Jason has other ideas).

@TymurGubayev - One potential mitigation on your end is if you can re-use your loaded workspace instances across multiple tests if they're loading the same solution. Basically to ensure that we only run a design time build once per solution, instead of on every test. And then in your tests you grab the loaded solution and fork off of that. You can't apply that change to the workspace though without potentially breaking other tests though (since they're sharing a workspace).

[TymurGubayev]

@ToddGrun

To clarify, is the following line being run in a loop for multiple solutions?

await workspace.OpenSolutionAsync(slnPath, new ConsoleProgressReporter()).ConfigureAwait(false);

Not in a loop, but in each test. Many tests also look at just a single file from a solution, so for any given slnPath this line can be called from multiple tests. Also, the solutions might not be compilable.

[TymurGubayev]

@dibarbet

One potential mitigation on your end is if you can re-use your loaded workspace instances across multiple tests if they're loading the same solution. Basically to ensure that we only run a design time build once per solution, instead of on every test. And then in your tests you grab the loaded solution and fork off of that. You can't apply that change to the workspace though without potentially breaking other tests though (since they're sharing a workspace).

Fortunately for me, I'm usually only grabbing content of a single changed document to compare with expected result, so caching workspace instances is probably feasible.

[TymurGubayev]

Adding caching like follows has no impact on Roslyn 4.8.0 (still under a minute for all the tests), and not quite 50% improvement for Roslyn 4.10.0 (now 4.4 minutes instead of about 8) - i.e. the tests after upgrade are still slower by a factor of about 4.5.

private static readonly Dictionary<string, MSBuildWorkspace> _cache = new();
private static readonly Dictionary<string, object> _locks = new();
public static Workspace CreateWorkspaceFromSolution(string slnPath)
{
    string absolutePath;
    lock (_locks)
    {
        if (!MSBuildLocator.IsRegistered)
        {
            try
            {
                var instance = MSBuildLocator_RegisterLatest();

                Console.WriteLine($"Using MSBuild at '{instance.MSBuildPath}' to load projects.");
                Console.WriteLine($"    Name: {instance.Name}");
                Console.WriteLine($"    Version: {instance.Version}");
            }
            catch (InvalidOperationException ex)
            {
                //probably `MSBuild assemblies were already loaded.` for some reason
                Console.WriteLine(ex.Message);
            }
        }

        absolutePath = Path.GetFullPath(slnPath);
        if (!_locks.ContainsKey(absolutePath))
            _locks.Add(absolutePath, new object());
    }

    lock (_locks[absolutePath])
    {
        if (_cache.TryGetValue(absolutePath, out var workspace)) return workspace;

        workspace = MSBuildWorkspace.Create();
        workspace.WorkspaceFailed += Helper.DefaultWorkspaceFailedHandler;

        Console.WriteLine($"Loading solution '{slnPath}'");
        // Attach progress reporter so we print projects as they are loaded.
        var solution = workspace.OpenSolutionAsync(slnPath, new ConsoleProgressReporter()).GetAwaiter().GetResult();
        Console.WriteLine($"Finished loading solution '{slnPath}'");

        _cache.Add(absolutePath, workspace);

        return workspace;
    }
}

[dibarbet]

That sounds roughly inline with what I would expect. You might be able to improve the performance further if you can combine the different solutions you're loading into one larger one (e.g. create a solution that has multiple different projects for the various test cases) - so that you're only ever loading a solution once for all the tests.

Definitely we should improve the JIT issue here, but frankly with the amount of things on our plates at the moment I don't think we will get to it very shortly.

[TymurGubayev]

I guess I'll try combining test solutions. Unfortunately there are nuances to some tests making it a bit more compicated than just putting every project into a single solution.