Mac (Mono) perf in Expander (file system and matching)

[KirillOsenkov]

The VSMac build uses Mono MSBuild 16.6.0 from mono@db750f7

We're seeing a huge slowdown when preparing the NuGet restore graph for the solution, before the RestoreTask. Normally we'd expect this to take a few hundred milliseconds, but it takes over 6 minutes.

I've started describing the issue here:
#3835 (comment)
but it looks like that issue might be unrelated and fixed already.

I'm seeing that the VSMac build spends 6 minutes in _GetAllRestoreProjectPathItems calling _GenerateRestoreProjectPathWalk recursively, producing a total of 8300 items in _RestoreProjectPathItemsOutputs (a)

I can tell that it uses a single solution-level Restore task that runs later (b), so the problem in this bug might be fixed by now, but there's still something extremely fishy going on.

On windows an equivalent also produces the a huge number of items, but it takes like 300ms.

Randomly breaking in the debugger often results in this callstack:

[KirillOsenkov]

[KirillOsenkov]

Most of it is Directory.Exists checks during Evaluation:

This makes me think that maybe all calls to Directory.Exists during evaluation should be cached? Supposedly the file system shouldn't change during evaluation so it's safe to cache. Lots of these are called hundreds of times with same input.

[KirillOsenkov]

Well this at least explains why we're not seeing such insane slowdown on Windows:

msbuild/src/Shared/FileUtilities.cs

Line 469 in cd29721

if (NativeMethodsShared.IsWindows || string.IsNullOrEmpty(value)

[KirillOsenkov]

This PR removes a check that would short-circuit the method if the value didn't contains slashes: #3547

[KirillOsenkov]

FYI @ccastanedaucf evaluation on Mac is insanely slow because of this, over half of our build (6 min) is spent here.

[KirillOsenkov]

Naïve nooping of the MaybeAdjustFilePath() method on Mono reduces the time to build the _GenerateRestoreGraph from 29 to 19 seconds.

[KirillOsenkov]

just adding the || !value.Contains('\\') check reduces the time spent in this method to half, from 29 to 24 seconds.

[KirillOsenkov]

Aha, there is already a CachingFileSystemWrapper

[KirillOsenkov]

but it's not enabled:

[KirillOsenkov]

but the fileSystem is a CachingFileSystemWrapper so it does cache:

[Therzok]

@KirillOsenkov possibly not on topic, but shouldn't the ConcurrentDictionary receive an IEqualityComparer?

Also, you probably already did but can you check the catch block to see if anything throws?

[KirillOsenkov]

Yes, there are no relevant exceptions. This now feels like thread starvation, main node grows to 60-70 threadpool threads with none of them doing any work, worker node grows to 30-50 threads as well and it's unclear why nothing is progressing. Looks like a deadlock but it can randomly unlock and finish, which takes anywhere from 14 seconds to 4-5 minutes.

[KirillOsenkov]

Turns out that the slowdown mentioned here is primarily because of different reasons. It is 29 seconds vs. 19 seconds, but it doesn't explain the 6 minutes delay.

The 6 minutes delay happens on Mono, but not on Dotnet runtime. I am now suspecting a Mono bug.

Let's keep this issue for the optimization of Directory.Exists() and such, but I'll open a separate bug for the actual slowdown (deadlock?) in Mono. I am also seeing thread starvation and up to 70 threads starting and doing nothing for some reason.

[AR-May]

Team Triage: @KirillOsenkov, Could you please update the status of this bug? Is there anything in MSBuild to fix? Do you still intend to work on this issue?

[KirillOsenkov]

This is still a bug in MSBuild. At the minimum, we need to bring back the quick check for \ I mentioned in:
#5925 (comment)

However digging into MSBuild performance on Mac/Mono I have uncovered several more performance issues which I'll be filing separately.

If I have time I can try and fix this issue a bit later. But certainly a perf bug that doesn't manifest on Windows because it's ifdef'ed out.

The larger theme is that MSBuild performance on Mac hasn't been investigated as thoroughly as on Windows and is an area full of low-hanging fruit such as this issue. The more I dig the more I find.