Very high memory consumption during build (4GB) with binary log enabled

[nguerrera]

From @rynowak on June 4, 2017 1:1

Apologies if this is not the right place. Please redirect me if you want me to put this info somewhere else.

/cc @rainersigwald

Repo Steps:

clone https://github.com/aspnet/Mvc
run build.cmd

dotnet --info

.NET Command Line Tools (2.0.0-preview2-006215)

Product Information:
 Version:            2.0.0-preview2-006215
 Commit SHA-1 hash:  e67962b0de

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.14393
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Users\rynowak\.dotnet\x64\sdk\2.0.0-preview2-006215\

Microsoft .NET Core Shared Framework Host

  Version  : 2.0.0-preview1-002111-00
  Build    : 1ff021936263d492539399688f46fd3827169983

Here's a dump

dotnet.zip

Copied from original issue: dotnet/sdk#1299

[nguerrera]

From @rynowak on June 4, 2017 1:5

Zooming in more specifically on the highest category, it looks like there's some truly large amounts of text that are being passed around as string in the messages. We're not doing anything exotic in our build that I know of.

strings > 100K

[nguerrera]

Yikes. Taking a look.

[nguerrera]

First observation: working set is about 4X better if I remove the binary logger from the command line args. cc @KirillOsenkov

[nguerrera]

From @KirillOsenkov on June 4, 2017 18:39

Ouch. Can you try and see if /bl:ProjectImports=None will make it better? Not sure which version of the binary logger you're using.

[nguerrera]

I believe this version does not have that feature:

> dotnet msbuild @D:\Src\Mvc/artifacts/msbuild/msbuild.rsp
C:\Users\nicholg\.dotnet\x64\sdk\2.0.0-preview2-006341\MSBuild.dll /nologo /bl:D:\Src\Mvc/artifacts/msbuild/msbuild.binlog;ProjectImports=None /clp:Summary /Logger:Microsoft.DotNet.Tools.MSBuild.MSBuildLogger,C:\Users\nicholg\.dotnet\x64\sdk\2.0.0-preview2-006341\dotnet.dll /m /m /p:RepositoryRoot=D:\Src\Mvc/ /v:m D:\Src\Mvc\.build/KoreBuild.proj
MSBUILD : Logger error MSB1029: The binary logger expects a single parameter (the output file name). 2 parameters were passed: "D:\Src\Mvc/artifacts/msbuild/msbuild.binlog;ProjectImports=None".
'dotnet msbuild @D:\Src\Mvc/artifacts/msbuild/msbuild.rsp' failed with exit code: 1
At D:\Src\Mvc\.build\KoreBuild.ps1:14 char:9


D:\Src\Mvc>C:\Users\nicholg\.dotnet\x64\dotnet.exe msbuild /version
Microsoft (R) Build Engine version 15.3.246.41955 for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

15.3.246.41955

[nguerrera]

Can't find symbols, but I was able to take a look at the huge strings using windbg:

0:047> .loadby sos coreclr

0:047> !DumpHeap -type System.String -min 100000
         Address               MT     Size
000002881177c340 00007ff8557f23e8  2212542 
<snip>

0:047> !DumpObj /d 000002881177c340
Name:        System.String
MethodTable: 00007ff8557f23e8
EEClass:     00007ff854f8a0d8
Size:        2212542(0x21c2be) bytes
File:        C:\Users\nicholg\.dotnet\x64\shared\Microsoft.NETCore.App\2.0.0-preview2-25402-02\System.Private.CoreLib.dll
String:      <String is invalid or too large to print>

Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
00007ff855810aa8  4000218        8         System.Int32  1 instance          1106258 m_stringLength
00007ff8557f2578  4000219        c          System.Char  1 instance               54 m_firstChar
00007ff8557f23e8  400021a       78        System.String  0   shared           static Empty

0:013> .writemem d:\temp\hugestring.txt 000002881177c340+c 000002881177c340+c+0n2068198
Writing 1f8ee7 bytes.................................................................

hugestring.txt:

Task Parameter:
    Inputs=
        55d01c43-1951-403d-86fa-a00cb72112c0
                AdditionalProperties=Configuration=Debug; Platform=AnyCPU;;Configuration=Debug;BuildNumber=t0048fd9dc;CommitHash=b1bc67e92e3d32e7a69072ebc2994f4d37a77743;GitBranch=dev
                Configuration=Debug
                MSBuildSourceProjectFile=D:\Src\Mvc\src\Microsoft.AspNetCore.Mvc\Microsoft.AspNetCore.Mvc.csproj
                MSBuildSourceTargetName=_GenerateRestoreProjectPathItemsPerFramework
                OriginalItemSpec=D:\Src\Mvc\src\Microsoft.AspNetCore.Mvc.Core\Microsoft.AspNetCore.Mvc.Core.csproj
                Platform=AnyCPU
                ProjectUniqueName=D:\Src\Mvc\src\Microsoft.AspNetCore.Mvc.Core\Microsoft.AspNetCore.Mvc.Core.csproj
                SkipNonexistentProjects=False
                ToolsVersion=
                Type=RestoreSpec
        21a14d29-6ff1-44a9-a8ec-d49a7ea0f128
                AdditionalProperties=Configuration=Debug; Platform=AnyCPU;;Configuration=Debug;BuildNumber=t0048fd9dc;CommitHash=b1bc67e92e3d32e7a69072ebc2994f4d37a77743;GitBranch=dev
                Configuration=Debug
                MSBuildSourceProjectFile=D:\Src\Mvc\src\Microsoft.AspNetCore.Mvc.ApiExplorer\Microsoft.AspNetCore.Mvc.ApiExplorer.csproj
                MSBuildSourceTargetName=_GenerateRestoreProjectPathItemsPerFramework
                OriginalItemSpec=D:\Src\Mvc\src\Microsoft.AspNetCore.Mvc.Abstractions\Microsoft.AspNetCore.Mvc.Abstractions.csproj
                Platform=AnyCPU
                ProjectUniqueName=D:\Src\Mvc\src\Microsoft.AspNetCore.Mvc.Abstractions\Microsoft.AspNetCore.Mvc.Abstractions.csproj
                SkipNonexistentProjects=False
                ToolsVersion=
                Type=RestoreSpec

<snip - continues for 2 MB!>

Looks like each task parameter is logged as single system.string and there is a huge set of items being passed to a NuGet restore target, which all get concatenated to log as a single parameter. There are a bunch of these on the LOH.

0:013> !gcroot 000002881177c340
Thread 66f0:
    000000e1561fdf80 00007ff861a87cc5 Microsoft.Build.Execution.BuildSubmission.Execute()
        rsi: 
            ->  0000028800066968 Microsoft.Build.Execution.BuildSubmission
            ->  0000028800059258 Microsoft.Build.Execution.BuildManager
            ->  000002880005f9f8 Microsoft.Build.BackEnd.ConfigCache
            ->  0000028800060348 System.Collections.Generic.Dictionary`2[[System.Int32, System.Private.CoreLib],[Microsoft.Build.BackEnd.BuildRequestConfiguration, Microsoft.Build]]
            ->  000002887d1ac580 System.Collections.Generic.Dictionary`2+Entry[[System.Int32, System.Private.CoreLib],[Microsoft.Build.BackEnd.BuildRequestConfiguration, Microsoft.Build]][]
            ->  00000288000685f8 Microsoft.Build.BackEnd.BuildRequestConfiguration
            ->  0000028800076dd0 Microsoft.Build.Execution.ProjectInstance
            ->  0000028800052c68 Microsoft.Build.Evaluation.Toolset
            ->  0000028800213e68 Microsoft.Build.Execution.TaskRegistry
            ->  000002880023ac70 System.Collections.Generic.Dictionary`2[[System.String, System.Private.CoreLib],[Microsoft.Build.Collections.HybridDictionary`2[[Microsoft.Build.Execution.TaskRegistry+RegisteredTaskIdentity, Microsoft.Build],[Microsoft.Build.Execution.TaskRegistry+RegisteredTaskRecord, Microsoft.Build]], Microsoft.Build]]
            ->  00000288009cf710 System.Collections.Generic.Dictionary`2+Entry[[System.String, System.Private.CoreLib],[Microsoft.Build.Collections.HybridDictionary`2[[Microsoft.Build.Execution.TaskRegistry+RegisteredTaskIdentity, Microsoft.Build],[Microsoft.Build.Execution.TaskRegistry+RegisteredTaskRecord, Microsoft.Build]], Microsoft.Build]][]
            ->  000002880023acc0 Microsoft.Build.Collections.HybridDictionary`2[[Microsoft.Build.Execution.TaskRegistry+RegisteredTaskIdentity, Microsoft.Build],[Microsoft.Build.Execution.TaskRegistry+RegisteredTaskRecord, Microsoft.Build]]
            ->  000002880023ace0 System.Collections.Generic.KeyValuePair`2[[Microsoft.Build.Execution.TaskRegistry+RegisteredTaskIdentity, Microsoft.Build],[Microsoft.Build.Execution.TaskRegistry+RegisteredTaskRecord, Microsoft.Build]]
            ->  0000028800235510 Microsoft.Build.Execution.TaskRegistry+RegisteredTaskRecord
            ->  000002880023ab68 Microsoft.Build.Execution.TaskFactoryWrapper
            ->  000002880023a188 Microsoft.Build.BackEnd.AssemblyTaskFactory
            ->  00000288f8fc18f0 Microsoft.Build.BackEnd.Logging.TaskLoggingContext
            ->  00000288000604f8 Microsoft.Build.BackEnd.Logging.LoggingService
            ->  0000028800065328 System.Threading.Tasks.Dataflow.BufferBlock`1[[System.Object, System.Private.CoreLib]]
            ->  0000028800065a40 System.Threading.Tasks.Dataflow.Internal.SourceCore`1[[System.Object, System.Private.CoreLib]]
            ->  0000028800065c10 System.Threading.Tasks.SingleProducerSingleConsumerQueue`1[[System.Object, System.Private.CoreLib]]
            ->  000002887b750e48 System.Threading.Tasks.SingleProducerSingleConsumerQueue`1+Segment[[System.Object, System.Private.CoreLib]]
            ->  0000028887a71240 System.Threading.Tasks.SingleProducerSingleConsumerQueue`1+Segment[[System.Object, System.Private.CoreLib]]
            ->  000002881270a370 System.Object[]
            ->  00000288fba1d490 Microsoft.Build.Framework.BuildMessageEventArgs
            ->  000002881177c340 System.String

[nguerrera]

There are multiple layers of perf issues here. This pattern of giant item-sets being passed around to represent nuget data probably has to go at some point. But I think the high-order bit is to investigate why these huge strings appear to be leaking, which is why I've moved this to msbuild for the next look.

[KirillOsenkov]

Thanks so much for your analysis @nguerrera. This is because we enable MSBUILDLOGTASKINPUTS. Maybe we should add a switch to disable it. Definitely a binary logger problem :(

[nguerrera]

It's super useful to see task inputs in the viewer. Can you stream them to the log instead of making a big string for each of them?

[nguerrera]

Also, is this just the inefficiency of LOH GC or is msbuild holding on to these strings unnecessarily?

[KirillOsenkov]

A few questions that will help us investigate:
It seems that the build script is a series of commands, to restore, build and then run unit-tests.

Can we isolate a command line that calls MSBuild and exhibits this behavior? How do I turn unit-tests off? Are we already seeing the memory growth during NuGet restore? Before the actual build starts?

Is this all reusing a single builder for restore and then build? When and where is msbuild.rsp being regenerated? Thanks!

[rynowak]

This appears to be the contents of msbuild.rsp during the command with the radical memory growth.

/nologo
/m
/p:RepositoryRoot="D:\k\Mvc/"
/bl:"D:\k\Mvc/artifacts/msbuild/msbuild.binlog"
/clp:Summary
"D:\k\Mvc\.build/KoreBuild.proj"
""

[KirillOsenkov]

That's what I'm seeing too. If I wanted to turn off the /bl switch in there, how do I do that?

[KirillOsenkov]

Seeing weirdness in this area:
http://source.dot.net/#Microsoft.Build/BackEnd/Components/Logging/LoggingService.cs,1066

Looks like the _loggingQueue is holding onto a GB of stuff:
http://source.dot.net/#Microsoft.Build/BackEnd/Components/Logging/LoggingService.cs,c2da823e79bf8922,references

/cc @rainersigwald @AndyGerlicher

[rynowak]

You could turn off /bl by editing .build/KoreBuild.ps1 - that's where the .rsp is generated

[KirillOsenkov]

The event args instances are held by the SingleProducerSingleConsumerQueue which is in the _loggingQueue. Now to determine why is the queue so long - does it take too long for the logger to drain items?

[KirillOsenkov]

I'm seeing even worse memory problems if I use a diagnostic-level text log (5 GB commit size). So it's nothing specific to the binary logger.

[KirillOsenkov]

OK I have a change to the BinaryLogger that keeps memory consumption under 800 MB by processing the incoming events as quickly as possible and having a custom queue on the logger side.

How do I turn off the tests? Build.cmd doesn't accept any parameters?

[KirillOsenkov]

@rynowak @nguerrera can you guys do me a favor?

1. Download https://github.com/KirillOsenkov/MSBuildStructuredLog/releases/download/v1.1.68/StructuredLogger.dll
2. Change C:\Mvc\.build\KoreBuild.ps1 line 130 to: /logger:BinaryLogger,C:\Temp\StructuredLogger.dll;C:\temp\mvc.binlog

and see what kind of difference this makes for you. Note the build duration and peak working set/commit memory.

[KirillOsenkov]

So this is super weird. Even if you use the same binary logger that's in the .dll, it still is different for me:
/logger:BinaryLogger,C:\Users\kirillo\.dotnet\x64\sdk\2.0.0-preview2-006341\Microsoft.Build.dll;C:\temp\mvcbuiltin.binlog

Maybe I'm just not cleaning in between test runs?

[nguerrera]

I found that I had to delete the artifacts directory to get a fair test.

[KirillOsenkov]

OK I now know why passing
/logger:BinaryLogger,C:\Users\kirillo\.dotnet\x64\sdk\2.0.0-preview2-006341\Microsoft.Build.dll;C:\temp\mvcbuiltin.binlog
results in ~800 MB but passing
/bl:C:\temp\mvcbl.log results in 5 GB.

Here's the problem: when passing /bl we set the overall verbosity to Diagnostic here:
http://source.dot.net/#MSBuild/XMake.cs,2734

And here if the verbosity is Diagnostic, we enable logTaskInputs:
http://source.dot.net/#MSBuild/XMake.cs,959

That's why using the file logger with diag verbosity results in 5GB usage as well.

Without logging task inputs, the compressed binary log is ~25 MB (557 MB uncompressed). With logging task inputs, the compressed binary log is ~160 MB (3.5 GB uncompressed).

[smitpatel]

How do I turn off the tests? Build.cmd doesn't accept any parameters?

Run build.cmd /t:Package That will stop at producing package stage and will not run tests.
Is there a work-around apart from disabling BinaryLogger?
This caused #2164 to happen. i.e. If system does not have high amount of RAM available, it crashes during compilation. (specifically Ubuntu)

[KirillOsenkov]

Yes the workaround is to change this line:
https://github.com/aspnet/KoreBuild/blob/dev/build/KoreBuild.ps1#L130

from:

/bl:"$msbuildLogFilePath"

to:

/logger:BinaryLogger,C:\Users\kirillo\.dotnet\x64\sdk\2.0.0-preview2-006341\Microsoft.Build.dll;"$msbuildLogFilePath"

You'll need to replace the path to Microsoft.Build.dll on the build machine, I don't know how to do that from Powershell (what variable is available to find the location of MSBuild being used for the build?)

[smitpatel]

#2164 does not reproduce when logger is removed so root cause is logging only for those failure.
Using work-around provided by @KirillOsenkov above is good to use and gets successful build.

[KirillOsenkov]

To fix memory consumption here we need to fix the following issues:

• Add special BuildMessageEventArgs types for task inputs, outputs, add item and remove item #6007
• Use distributed loggers to improve perf KirillOsenkov/MSBuildStructuredLog#231
• Investigate Log Task Inputs performance #2200
• Consider logging ProjectStarted more sparingly #5316

[KirillOsenkov]

I think the memory consumption is fixed by #6155.

[nguerrera]

Awesome! Saw some tweets go by and decided to check if my bug was still open and if I could finally close it. 😀