MSBuild crashes with an out-of-memory exception when updating GitVersionTask from 4.0.0-beta0013 to 4.0.0

[ruhullahshah]

Problem:

MSBuild.exe crashes with an out-of-memory exception frequently when we try to upgrade GitVersionTask from 4.0.0-beta0013 to 4.0.0.

Preconditions:

• The Git repository should be large in terms of number of commits, our repo has > 80k commits.
• MSBuild.exe runs as a 32-bit process. We use the MSBuild supplied with VS2015.

Observations:

• We observed that GitVersionTask-4.0.0 consumes about 1.2GB of memory, whereas GitVersionTask-4.0.0-beta-0013 consumes 200MB.
• GitVersion.CommandLine continues to consume the same amount of memory in both the versions. So we believe that updates to GitVersionTask between these two versions causes the problem.
• GitVersionTask-4.0.0 relies on UtilPack.NuGet.MSBuild, could this cause the problem somehow?

This issue is preventing us from upgrading GitVersion and we would really appreciate some feedback or workarounds for this issue.

[arturcic]

adding @stazz, @dazinator

[dazinator]

I know @stazz has an ongoing PR which will change the way gitversiontask works. Once his PR is stable it would be good to try that version to see if memory consumption remains an issue

[stazz]

Hi,

the UtilPack currently used by GitVersion invokes the GitVersion directly in-process. It also uses some additional caching and other things, which might not be cleaned up on continuously running MSBuild instances like in VS. If this happens also when building normally from commandline, then it is quite weird.

In any case, as @dazinator mentioned, there is PR going on which will affect this issue dramatically. I've changed UtilPack to invoke the target package (e.g. GitVersionTask) in a separate process, which hopefully will help to mitigate any possible memory leaks. The PR currently is going on in #1634 .

[ruhullahshah]

@stazz Thanks for the feedback. It sounds good. I cloned your fork and wanted to test the resulting GitVersionTask nuget package from #1634 in our own CI pipeline. However, I am not able to create nupkg by running nuget.exe pack under GitVersionTask\NugetAssets. Any idea how GitVersion creates nugets?

[stazz]

@ruhullahshah I tested by running dotnet pack -c Release <path to cloned repo>/src/GitVersionTask. I guess for nuget.exe you might need to first build the GitVersionTask.csproj using dotnet build, and then run nuget.exe on the GitVersionTask.nuspec file in the NugetAssets directory.

With the dotnet pack command, without specifying any more properties or parameters, it creates version 0.0.1-alpha-0001 package. Hope this helps!

[ruhullahshah]

@stazz Thanks, I took the dotnet route and it helped me to create the nupkg. I updated the version number of the resulting nuget package to use in our CI server. However, I get the following compilation errors:

MSBUILD : Task factory error NMSBT001: Exception in initialization: System.Exception: Errors occurred during package inspection: An error occurred: Could not find package "GitVersionTask" at version "4.0.0-custom0009" with path "GitVersionTask.dll".. [myproj.csproj]
BUILD : Task factory error NMSBT001: .\r [myproj.csproj]
BUILD : Task factory error NMSBT001:    at NuGetUtils.MSBuild.Exec.NuGetExecutionCache.<>c__DisplayClass7_0.<<InspectPackageAsync>b__1>d.MoveNext()\r 
[myproj.csproj]
MSBUILD : Task factory error NMSBT001: --- End of stack trace from previous location where exception was thrown ---\r [myproj.csproj]
MSBUILD : Task factory error NMSBT001:    at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)\r [myproj.csproj]
MSBUILD : Task factory error NMSBT001:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r [myproj.csproj]
MSBUILD : Task factory error NMSBT001:    at NuGetUtils.MSBuild.Exec.NuGetExecutionCache.<InspectPackageAsync>d__7.MoveNext()\r [myproj.csproj]
MSBUILD : Task factory error NMSBT001: --- End of stack trace from previous location where exception was thrown ---\r [myproj.csproj]
MSBUILD : Task factory error NMSBT001:    at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)\r [myproj.csproj]
MSBUILD : Task factory error NMSBT001:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r [myproj.csproj]
MSBUILD : Task factory error NMSBT001:    at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task)\r [myproj.csproj]
MSBUILD : Task factory error NMSBT001:    at NuGetUtils.MSBuild.Exec.NuGetExecutionTaskFactory.<InitializeAsync>d__23.MoveNext()\r [myproj.csproj]
MSBUILD : Task factory error NMSBT001: --- End of stack trace from previous location where exception was thrown ---\r [myproj.csproj]
MSBUILD : Task factory error NMSBT001:    at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)\r [myproj.csproj]
MSBUILD : Task factory error NMSBT001:    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r [myproj.csproj]
MSBUILD : Task factory error NMSBT001:    at System.Runtime.CompilerServices.TaskAwaiter.ValidateEnd(Task task)\r [myproj.csproj]
MSBUILD : Task factory error NMSBT001:    at NuGetUtils.MSBuild.Exec.NuGetExecutionTaskFactory.Initialize(String taskName, IDictionary`2 parameterGroup, String taskBody, IBuildEngine taskFactoryLoggingHost) [myproj.csproj]
<path-to-packages>\packages\GitVersionTask\build\functionality\GitVersionBuild.targets(6,5): error MSB4036: The "WriteVersionInfoToBuildLog" task was not found. Check the following: 1.) The name of the task in the project file is the same as the name of the task class. 2.) The task class is "public" and implements the Microsoft.Build.Framework.ITask interface. 3.) The task is correctly declared with <UsingTask> in the project file, or in the *.tasks files located in the "C:\Program Files (x86)\MSBuild\14.0\bin" directory. [myproj.csproj]

[stazz]

Hmm, if you put your verbosity to detailed (/v:detailed), what does it say then? Do you use dotnet or MSBuild.exe when this error happens?

[ruhullahshah]

@stazz It fails with the same exception. The output obtained with /v:detailed hinders me from deciding the relevant information. We use MSBuild.exe. Have you tested your changes with it?

[stazz]

Yeah I was hoping for included log files, since they would show some additional output (i.e. full paths for task factory DLL, and other useful information). If you can't provide the detailed log output, maybe a minimal files for repro case?

The error message looks familiar, and I've fixed one thing related to that before 2.0.1 release, so I'm wondering if the fix was complete. It was related to auto-detecting .NET Desktop framework version.

Edit: And yes, I've tested with both dotnet and MSBuild.exe.

[ruhullahshah]

So, after some further investigation, I have the following findings:

• Changing the version of the resulting GitVersionTask to 4.0.0-custom0009 manually, seemed to cause the problem, and on keeping the original version(0.0.1-alpha.0001) generated by dotnet pack seems to work. So we assume this should not be a problem, because an official release will have the correct version number anyway.
• However, now we face the following MSBuild.exe error:
  MSBUILD : error : An error occurred: Error converting value "File0.cs;File1.cs;File2.cs;File2.cs;File4.cs;File5.cs;c:\temp\.NETFramework,Version=v4.5.2.AssemblyAttributes.cs" to type 'System.String[]'. Path 'CompileFiles', line 1, position 260.. [<path>\myproj.csproj]

We use net452 and explicitly list out the files to include using the <Compile Include="..."/> tag in our csprojs. Any idea as to why this might happen? Are there assumptions on the csproj files or the .NET framework used?

[stazz]

Interesting, I had to explicitly set property UpdateAssemblyInfo to true to reproduce this. But - now I have a repro and will work on it, stay tuned! This seems to be related to how ITaskItems are used in generated task type.

[ruhullahshah]

@stazz Thank you. Waiting to hear from you.

[stazz]

I've published version 2.0.2 of NuGetUtils.MSBuild.Exec and updated GitVersionTask to use that version. The UpdateAssemblyInfo task now executes successfully.

[ruhullahshah]

@stazz Thanks for the fix. I tried it out and do not observe the OOM issue anymore. The peak memory consumption of the msbuild process went up to 160MB and that is fine.
However, I have an observation on the average compilation time. It has gone up from 13 minutes to 26 minutes. In my opinion, this is due to the spawning of child processes by your package during the compilation. For small projects, this might not be an issue or even observable, but for large systems, such as ours, the increase is apparent.

I am not sure if this can be improved in the future releases of your package, but for now I think your PR should be merged so that this fix becomes available.

[stazz]

I am sure this is something that can be improved. The NuGetUtils.MSBuild.Exec spawns 3 processes on first run of any task it uses, and 1 process per subsequent run of the similar tasks within the same MSBuild process. If you invoke MSBuild process many times during the build, the NuGetUtils.MSBuild.Exec loses the cached information and ends up spawning more processes than required. So that one way to improve build times is to minimize the amount of MSBuild invocations.

I will also add some diagnostic output for all situations NuGetUtils.MSBuild.Exec invokes processes, so that this behaviour can be better tracked, and improved in the future. The current work is only first iteration of the idea of using processes to invoke dynamic tasks in NuGet packages and I am sure there is still plenty of room for improvement.

[stazz]

Hey - sorry on commenting on closed issue, but I've updated the GitVersionTask in my PR to use newer 2.0.3 version of NuGetUtils.MSBuild.Exec, which has some diagnostic output about process invocations and their durations. When setting verbosity to detailed (or other level, which shows MessageImportance.Normal messages), look for strings like these:

Invoking process NuGetUtils.MSBuild.Exec.Discover.
Process NuGetUtils.MSBuild.Exec.Discover exited, duration 00:00:00.9316946.
Detected current NuGet framework to be ".NETCoreApp,Version=v2.2", with RID "linux-x64".
Invoking process NuGetUtils.MSBuild.Exec.Inspect.
Process NuGetUtils.MSBuild.Exec.Inspect exited, duration 00:00:02.9323168.
Invoking process NuGetUtils.MSBuild.Exec.Perform.
Found restorable packages within disk cache.
Process NuGetUtils.MSBuild.Exec.Perform exited, duration 00:00:01.2288357.

Using this information, I hope it will be easier to analyze what exactly is going on and taking time in the build.

I also noticed that actually the NuGetUtils.MSBuild.Exec.Inspect process gets invoked once per new task instead of once per package. So that is one easy target to start optimizing from. :)

EDIT: I've made the amount of invocations of the NuGetUtils.MSBuild.Exec.Inspect process much lesser now in version 2.0.4 of NuGetUtils.MSBuild.Exec. The PR of GitVersion has been updated to the newest version.

[jbaehr]

I'm sorry too to comment in this closed issue, but the slowdown may also be caused by #1636.
(although the figures presented in the above reply suggest 5 additional seconds per csproj; that sums up easily to 10 Minutes when building a solution with 200 projects...)
In any case, doubling the build times is a show stopper.