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

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 Memory2

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

Memory1

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

About this issue

  • Original URL
  • State: closed
  • Created a year ago
  • Reactions: 1
  • Comments: 23 (20 by maintainers)

Commits related to this issue

Most upvoted comments

yeah, agree that a low-risk fix would be to revert the original change, store the zip in a temp location, and then only if we’re not embedding it, move the temp file to the source directory (to preserve prior behavior). if we are embedding it, just read it via streams (not byte[]), then delete the temporary zip.

Yup, we were just getting lucky. Not blaming your change, it was a good fix. Just started seeing some really huge builds and it became a problem. I think if we can get a safe temp file location, unique per process, we should write to that instead of the memory stream. Definitely shouldn’t be creating any files in the source directory.