[Bug]: msbuild binary logger generating excessive memory spike at end of build

[MarkOsborneMS]

Issue Description

When running msbuild /t:restore /bl on a large repo we are running out of memory at the end of the build on a 64GB machine. We see a large spike in memory after the console output shows the build as complete, before the process terminates with an out of memory exception.

This is a regression for as we started seeing this behavior in 17.6 preview, but we did not see this behavior in VS 17.5.

Steps to Reproduce

We have a large repo.

Expected Behavior

Expect that we can complete restore build with less than 64GB of memory, we do not see a memory spike with VS 17.5.

MSBuild version 17.5.1+f6fdcf537 for .NET Framework

Actual Behavior

We are seeing a huge 30GB memory spike after the build completes and an out of memory exception.

MSBuild version 17.6.0-preview-23164-01+18fe51042 for .NET Framework

Build succeeded.
    0 Warning(s)
    0 Error(s)

Time Elapsed 00:09:43.47
MSBUILD : error MSB1025: An internal failure occurred while running MSBuild.
Microsoft.Build.Framework.InternalErrorException: MSB0001: Internal MSBuild Error: Throwing from logger shutdown
=============
System.OutOfMemoryException: Exception of type 'System.OutOfMemoryException' was thrown.
   at System.IO.MemoryStream.set_Capacity(Int32 value)
   at System.IO.MemoryStream.EnsureCapacity(Int32 value)
   at System.IO.MemoryStream.Write(Byte[] buffer, Int32 offset, Int32 count)
   at System.IO.Compression.ZipArchiveEntry.WriteCentralDirectoryFileHeader()
   at System.IO.Compression.ZipArchive.WriteFile()
   at System.IO.Compression.ZipArchive.Dispose(Boolean disposing)
   at Microsoft.Build.Logging.ProjectImportsCollector.Close(Boolean closeStream)
   at Microsoft.Build.Logging.ProjectImportsCollector.GetAllBytes()
   at Microsoft.Build.Logging.BinaryLogger.Shutdown()
   at Microsoft.Build.BackEnd.Logging.LoggingService.ShutdownLogger(ILogger logger)
   at Microsoft.Build.BackEnd.Logging.LoggingService.ShutdownComponent()
   at Microsoft.Build.Evaluation.ProjectCollection.ShutDownLoggingService()

 ---> System.OutOfMemoryException: Exception of type 'System.OutOfMemoryException' was thrown.
   at System.IO.MemoryStream.set_Capacity(Int32 value)
   at System.IO.MemoryStream.EnsureCapacity(Int32 value)
   at System.IO.MemoryStream.Write(Byte[] buffer, Int32 offset, Int32 count)
   at System.IO.Compression.ZipArchiveEntry.WriteCentralDirectoryFileHeader()
   at System.IO.Compression.ZipArchive.WriteFile()
   at System.IO.Compression.ZipArchive.Dispose(Boolean disposing)
   at Microsoft.Build.Logging.ProjectImportsCollector.Close(Boolean closeStream)
   at Microsoft.Build.Logging.ProjectImportsCollector.GetAllBytes()
   at Microsoft.Build.Logging.BinaryLogger.Shutdown()
   at Microsoft.Build.BackEnd.Logging.LoggingService.ShutdownLogger(ILogger logger)
   at Microsoft.Build.BackEnd.Logging.LoggingService.ShutdownComponent()
   at Microsoft.Build.Evaluation.ProjectCollection.ShutDownLoggingService()
   --- End of inner exception stack trace ---
   at Microsoft.Build.Shared.ErrorUtilities.ThrowInternalError(String message, Exception innerException, Object[] args)
   at Microsoft.Build.Evaluation.ProjectCollection.ShutDownLoggingService()
   at Microsoft.Build.Evaluation.ProjectCollection.Dispose(Boolean disposing)
   at Microsoft.Build.CommandLine.MSBuildApp.BuildProject(String projectFile, String[] targets, String toolsVersion, Dictionary`2 globalProperties, Dictionary`2 restoreProperties, ILogger[] loggers, LoggerVerbosity verbosity, DistributedLoggerRecord[] distributedLoggerRecords, Boolean needToValidateProject, String schemaFile, Int32 cpuCount, Boolean enableNodeReuse, TextWriter preprocessWriter, TextWriter targetsWriter, Boolean detailedSummary, ISet`1 warningsAsErrors, ISet`1 warningsNotAsErrors, ISet`1 warningsAsMessages, Boolean enableRestore, ProfilerLogger profilerLogger, Boolean enableProfiler, Boolean interactive, ProjectIsolationMode isolateProjects, GraphBuildOptions graphBuildOptions, Boolean lowPriority, String[] inputResultsCaches, String outputResultsCache, String commandLine)
   at Microsoft.Build.CommandLine.MSBuildApp.Execute(String commandLine)

Unhandled Exception: Microsoft.Build.Framework.InternalErrorException: MSB0001: Internal MSBuild Error: Throwing from logger shutdown
=============
System.OutOfMemoryException: Exception of type 'System.OutOfMemoryException' was thrown.
   at System.IO.MemoryStream.set_Capacity(Int32 value)
   at System.IO.MemoryStream.EnsureCapacity(Int32 value)
   at System.IO.MemoryStream.Write(Byte[] buffer, Int32 offset, Int32 count)
   at System.IO.Compression.ZipArchiveEntry.WriteCentralDirectoryFileHeader()
   at System.IO.Compression.ZipArchive.WriteFile()
   at System.IO.Compression.ZipArchive.Dispose(Boolean disposing)
   at Microsoft.Build.Logging.ProjectImportsCollector.Close(Boolean closeStream)
   at Microsoft.Build.Logging.ProjectImportsCollector.GetAllBytes()
   at Microsoft.Build.Logging.BinaryLogger.Shutdown()
   at Microsoft.Build.BackEnd.Logging.LoggingService.ShutdownLogger(ILogger logger)
   at Microsoft.Build.BackEnd.Logging.LoggingService.ShutdownComponent()
   at Microsoft.Build.Evaluation.ProjectCollection.ShutDownLoggingService()

 ---> System.OutOfMemoryException: Exception of type 'System.OutOfMemoryException' was thrown.
   at System.IO.MemoryStream.set_Capacity(Int32 value)
   at System.IO.MemoryStream.EnsureCapacity(Int32 value)
   at System.IO.MemoryStream.Write(Byte[] buffer, Int32 offset, Int32 count)
   at System.IO.Compression.ZipArchiveEntry.WriteCentralDirectoryFileHeader()
   at System.IO.Compression.ZipArchive.WriteFile()
   at System.IO.Compression.ZipArchive.Dispose(Boolean disposing)
   at Microsoft.Build.Logging.ProjectImportsCollector.Close(Boolean closeStream)
   at Microsoft.Build.Logging.ProjectImportsCollector.GetAllBytes()
   at Microsoft.Build.Logging.BinaryLogger.Shutdown()
   at Microsoft.Build.BackEnd.Logging.LoggingService.ShutdownLogger(ILogger logger)
   at Microsoft.Build.BackEnd.Logging.LoggingService.ShutdownComponent()
   at Microsoft.Build.Evaluation.ProjectCollection.ShutDownLoggingService()
   --- End of inner exception stack trace ---
   at Microsoft.Build.Shared.ErrorUtilities.ThrowInternalError(String message, Exception innerException, Object[] args)
   at Microsoft.Build.Evaluation.ProjectCollection.ShutDownLoggingService()
   at Microsoft.Build.Evaluation.ProjectCollection.Dispose(Boolean disposing)
   at Microsoft.Build.CommandLine.MSBuildApp.BuildProject(String projectFile, String[] targets, String toolsVersion, Dictionary`2 globalProperties, Dictionary`2 restoreProperties, ILogger[] loggers, LoggerVerbosity verbosity, DistributedLoggerRecord[] distributedLoggerRecords, Boolean needToValidateProject, String schemaFile, Int32 cpuCount, Boolean enableNodeReuse, TextWriter preprocessWriter, TextWriter targetsWriter, Boolean detailedSummary, ISet`1 warningsAsErrors, ISet`1 warningsNotAsErrors, ISet`1 warningsAsMessages, Boolean enableRestore, ProfilerLogger profilerLogger, Boolean enableProfiler, Boolean interactive, ProjectIsolationMode isolateProjects, GraphBuildOptions graphBuildOptions, Boolean lowPriority, String[] inputResultsCaches, String outputResultsCache, String commandLine)
   at Microsoft.Build.CommandLine.MSBuildApp.Execute(String commandLine)
   at Microsoft.Build.CommandLine.MSBuildApp.Main()

Analysis

Passing the additional parameter /bl:ProjectImports=None is a workaround for the issue, but not ideal as we prefer to collect complete binlogs from our build agents.

Versions & Configurations

MSBuild version 17.6.0-preview-23164-01+18fe51042 for .NET Framework
17.6.0.16401

[KirillOsenkov]

GetAllBytes() grows a large memory stream in memory.

This was introduced in ec61b6f

cc @asklar

[KirillOsenkov]

@MarkOsborneMS after that build is done (crashed), there should still be the msbuild.binlog file on disk. Could you share it with me privately please.

[KirillOsenkov]

also if you could please share a successful binlog from the same large repo

[MarkOsborneMS]

@KirillOsenkov I have shared both binlogs with you privately.

[KirillOsenkov]

stats from the smaller (working) binlog:

The size of the blob archive is 78 MB, I'm guessing using MemoryStream to write 78 MB pushes it over the limit due to array reallocations.

[KirillOsenkov]

In the smaller binlog, there are 600MB of files embedded:

[KirillOsenkov]

you can save files from a binlog to a folder on disk using:

dotnet tool install -g binlogtool
binlogtool savefiles msbuildrestore175.binlog OutputFolder

[KirillOsenkov]

I took a look at the files and it's mostly 450 MB worth of project.assets.json files:

[KirillOsenkov]

As a workaround, you can turn off embedding files into the binlog via:
msbuild /bl:msbuild.binlog;ProjectImports=None

[jeffkl]

I took a look at the files and it's mostly 450 MB worth of project.assets.json files:

Does that seem like its the cause? Or do you think that should be okay and something else needs to be fixed? I would expect the assets files to be highly compressible.

[KirillOsenkov]

Stats from the 770 MB binlog:

Again, mostly huge project.assets.json files, p2p.targets:

[KirillOsenkov]

No, it's fine to embed the files.

This logic starts breaking at this volume of data:
ec61b6f#diff-0864a6f2e10a87d935fbf19d81370f534e67f33931642dec1f30023b108e2cdcR180

We need to stream the ProjectImports.zip into the binlog writer, instead of using File.ReadAllBytes(). It just chokes reallocating byte arrays growing the underlying memory stream.

I was just looking at the binlogs to understand if there are any abnormally large files that shouldn't have been included, but it just seems that the repo is huge, so nothing abnormal. It just crossed some threshold recently where the size became so big that it started OOMing.