Log/Emit memory consumed during task run

[JanKrivanek]

Motivation

This is inspired by investigation with @pavelsavara on why there are OOMs during build - dotnet/runtime#111662
It is currently nontrivial to attribute the memory hitter (especially if notrivial amount of native allocations or pinning are involved as well). It would be nice if we could get some initial rough direction from binlog. But this might be interesting data for telemetry as well.

Idea

System.Diagnostics.Process and System.GC can be queried for a consumed memry before and after task execution - the diffs can then be attached to TaskExecutedEventArgs.

[pavelsavara]

We are running out of memory on AzDO agent, linux container with 4 CPU and 16GB ram. The container doesn't have swap file.

As a consequence our agent would be killed and wholeCI leg needs human attention. It happens too often to be ignored.

It seems msbuild/tasks is wasting memory, so it would be good to find root cause rather than throw money on the problem by using larger SKU.

Context

• when building dotnet runtime repo
• we already disabled MSBuild node reuse, but this CI leg is single long running msbuild, which runs hundred C# projects.
• specifically the memory consumption grows for all MSBuild nodes when the build reaches libs.tests subset of the runtime build
  • apparently there are some msbuild tasks specific to that phase of the build which use lot of memory
  • for the WASM target, we use memory hungry LLVM/c-lang compiler toochain.
  • Note, LLVM is not contributing to the memory footprint of the MSBuild nodes. It is native sub-process.
• we already isolated some of the suspect custom tasks into separate process via TaskFactory="TaskHostFactory" in [browser] reduce msbuild memory footprint runtime#111751

Further investigation hints

• each out of 4 msbuild nodes is using whole 16GB as the expectation of the available memory (DOTNET_GCHeapHardLimitPercent could change that).
• It has the default DOTNET_GCHighMemPercent of 90% out of 16GB. This is probably when it would consider running GC on Gen2.
• at the peak, each of them would have private set around 2.5 sometimes 4 GB. Together with running LLVM this is too much for the VM total RAM.

private working set vs GC heap

below is dump from bigger windows machine, but I think it maps the problem well
it shows private working set of 1.5GB and managed GC heap including dead object just 652MB

1. I tried to force GCSettings.LargeObjectHeapCompactionMode = GCLargeObjectHeapCompactionMode.CompactOnce; GC.Collect(); but it didn't help.
2. I suspected this is leaked memory mapped files, but VMMap tool doesn't confirm this

At the moment I think this is LOH fragmentation in long running process. I suspected ZipDirectory task, but I was not able to catch it red handed.

[pavelsavara]

This is captured in the actual CI agent after trying GCSettings.LargeObjectHeapCompactionMode = GCLargeObjectHeapCompactionMode.CompactOnce; GC.Collect();

USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
cloudte+     747 22.0 16.5 275206272 2707788 ?   Sl   14:02   9:06 /__w/1/s/.dotnet/dotnet msbuild /m /clp:Summary
cloudte+     914 15.0 13.5 275184076 2226660 ?   Sl   14:03   6:00 /__w/1/s/.dotnet/dotnet MSBuild.dll /nodemode:1
cloudte+     915 18.0 13.2 275270036 2166988 ?   Sl   14:03   7:11 /__w/1/s/.dotnet/dotnet MSBuild.dll /nodemode:1
cloudte+     916 13.9 14.2 275206464 2326168 ?   Sl   14:03   5:34 /__w/1/s/.dotnet/dotnet MSBuild.dll /nodemode:1
cloudte+   16935 75.3  9.5 275371688 1559320 ?   Sl   14:15  21:29 /__w/1/s/.dotnet/dotnet exec VBCSCompiler.dll
cloudte+   17004  1.5  5.5 274419428 908412 ?    Sl   14:15   0:26 /__w/1/s/.dotnet/dotnet MSBuild.dll /nodemode:2
cloudte+   31868  1.8  2.3 274239292 377944 ?    Sl   14:26   0:19 /__w/1/s/.dotnet/dotnet MSBuild.dll /nodemode:2
cloudte+   31913  1.3  0.5 274164876 87300 ?     Sl   14:26   0:14 /__w/1/s/.dotnet/dotnet MSBuild.dll /nodemode:2
cloudte+   31975  3.0  0.5 274173072 91856 ?     Sl   14:26   0:32 /__w/1/s/.dotnet/dotnet MSBuild.dll /nodemode:2

Before GC 747 - PrivateMemorySize64: 3028312064 bytes
Before GC 747 - WorkingSet64: 2772774912 bytes
Before GC 747 - FragmentedBytes: 3464760 bytes
Before GC 747 - Compacted: True bytes
Before GC 747 - HighMemoryLoadThresholdBytes: 15090086707 bytes
Before GC 747 - TotalAvailableMemoryBytes: 16766763008 bytes
Before GC 747 - TotalCommittedBytes: 2659639296 bytes

After GC 747 - PeakWorkingSet64: 2793672704 bytes
After GC 747 - PrivateMemorySize64: 3028312064 bytes
After GC 747 - WorkingSet64: 2772774912 bytes
After GC 747 - FragmentedBytes: 3402512 bytes
After GC 747 - Compacted: True bytes
After GC 747 - HighMemoryLoadThresholdBytes: 15090086707 bytes
After GC 747 - TotalAvailableMemoryBytes: 16766763008 bytes
After GC 747 - TotalCommittedBytes: 2642333696 bytes

[pavelsavara]

This is example of the binlog, when the agent didn't get killed.

The target _RunWasmOptPostLink in Wasm.Advanced.Sample.csproj is typical victim of the OOM kill.

[mangod9]

If this looks like a managed memory issue, collecting a GCCollectOnly trace would be helpful in diagnosing: perfview /GCCollectOnly /nogui collect

[pavelsavara]

wasm-test-build-2025-02-19-PerfViewData.etl.zip
wasm-test-build-2025-02-19-PerfViewData.log.txt

@mangod9 I attached the trace.
The actual issue is happening on smaller linux machine, but perfview is windows only.
So, this is from larger windows machine.
To make it similar to CI agent I set $env:DOTNET_GCHeapHardLimitPercent="19" and /m:4 for MSBuild

The trace was collected for most of the duration of the build, about 60 minutes before the build stopped. The memory usage is creeping up whole time.

The processes with /nodemode:1 are the perpetrators here. For example PID 15740

Later I will try to collect it from the actual CI machine via dotnet-trace collect --profile gc-collect.
Downside is that I would only get trace from single process and there are multiple competing for the resources.

[pavelsavara]

In the meantime

Build
Binlog

MSBUILD : error MSB4166: Child node "2" exited prematurely. Shutting down. Diagnostic information may be found in files in "C:\Users\cloudtest\AppData\Local\Temp\MSBuildTemp\" and will be named MSBuild_*.failure.txt. This location can be changed by setting the MSBUILDDEBUGPATH environment variable to a different directory.
MSBUILD : error MSB4166: C:\Users\cloudtest\AppData\Local\Temp\MSBuildTemp\MSBuild_pid-7920_5106df0b5bae4e1aaa8f14d10b36dee9.failure.txt:
MSBUILD : error MSB4166: UNHANDLED EXCEPTIONS FROM PROCESS 7920:
MSBUILD : error MSB4166: =====================
MSBUILD : error MSB4166: 2/26/2025 2:03:00 PM
MSBUILD : error MSB4166: Microsoft.Build.Framework.CriticalTaskException
MSBUILD : error MSB4166:  ---> System.OutOfMemoryException: Exception of type 'System.OutOfMemoryException' was thrown.
MSBUILD : error MSB4166:    at System.Buffers.ProbabilisticMap..ctor(ReadOnlySpan`1 values)
MSBUILD : error MSB4166:    at System.String.MakeSeparatorListAny(ReadOnlySpan`1 source, ReadOnlySpan`1 separators, ValueListBuilder`1& sepListBuilder)
MSBUILD : error MSB4166:    at System.String.SplitInternal(ReadOnlySpan`1 separators, Int32 count, StringSplitOptions options)
MSBUILD : error MSB4166:    at Microsoft.NET.Build.Tasks.ConflictResolution.PackageOverride.CreateOverriddenPackages(String overriddenPackagesString)+MoveNext()
MSBUILD : error MSB4166:    at Microsoft.NET.Build.Tasks.ConflictResolution.PackageOverride..ctor(String packageName, IEnumerable`1 overriddenPackages)
MSBUILD : error MSB4166:    at Microsoft.NET.Build.Tasks.ConflictResolution.PackageOverride.Create(ITaskItem packageOverrideItem)
MSBUILD : error MSB4166:    at Microsoft.NET.Build.Tasks.ConflictResolution.PackageOverrideResolver`1.BuildPackageOverrides()
MSBUILD : error MSB4166:    at System.Lazy`1.ViaFactory(LazyThreadSafetyMode mode)
MSBUILD : error MSB4166:    at System.Lazy`1.ExecutionAndPublication(LazyHelper executionAndPublication, Boolean useDefaultConstructor)
MSBUILD : error MSB4166:    at System.Lazy`1.CreateValue()
MSBUILD : error MSB4166:    at Microsoft.NET.Build.Tasks.ConflictResolution.PackageOverrideResolver`1.Resolve(TConflictItem item1, TConflictItem item2)
MSBUILD : error MSB4166:    at Microsoft.NET.Build.Tasks.ConflictResolution.ConflictResolver`1.ResolveConflict(TConflictItem item1, TConflictItem item2, Boolean logUnresolvedConflicts)
MSBUILD : error MSB4166:    at Microsoft.NET.Build.Tasks.ConflictResolution.ConflictResolver`1.ResolveConflicts(IEnumerable`1 conflictItems, Func`2 getItemKey, ConflictCallback`1 foundConflict, Boolean commitWinner)
MSBUILD : error MSB4166:    at Microsoft.NET.Build.Tasks.ConflictResolution.ResolvePackageFileConflicts.ExecuteCore()
MSBUILD : error MSB4166:    at Microsoft.NET.Build.Tasks.TaskBase.Execute()
MSBUILD : error MSB4166:    at Microsoft.Build.BackEnd.TaskExecutionHost.Execute()
MSBUILD : error MSB4166:    at Microsoft.Build.BackEnd.TaskBuilder.ExecuteInstantiatedTask(TaskExecutionHost taskExecutionHost, TaskLoggingContext taskLoggingContext, TaskHost taskHost, ItemBucket bucket, TaskExecutionMode howToExecuteTask)
MSBUILD : error MSB4166:    --- End of inner exception stack trace ---
MSBUILD : error MSB4166:    at Microsoft.Build.BackEnd.TaskBuilder.ExecuteInstantiatedTask(TaskExecutionHost taskExecutionHost, TaskLoggingContext taskLoggingContext, TaskHost taskHost, ItemBucket bucket, TaskExecutionMode howToExecuteTask)
MSBUILD : error MSB4166:    at Microsoft.Build.BackEnd.TaskBuilder.InitializeAndExecuteTask(TaskLoggingContext taskLoggingContext, ItemBucket bucket, IDictionary`2 taskIdentityParameters, TaskHost taskHost, TaskExecutionMode howToExecuteTask)
MSBUILD : error MSB4166:    at Microsoft.Build.BackEnd.TaskBuilder.ExecuteBucket(TaskHost taskHost, ItemBucket bucket, TaskExecutionMode howToExecuteTask, Dictionary`2 lookupHash)
MSBUILD : error MSB4166:    at Microsoft.Build.BackEnd.TaskBuilder.ExecuteTask(TaskExecutionMode mode, Lookup lookup)
MSBUILD : error MSB4166:    at Microsoft.Build.BackEnd.TaskBuilder.ExecuteTask(TargetLoggingContext loggingContext, BuildRequestEntry requestEntry, ITargetBuilderCallback targetBuilderCallback, ProjectTargetInstanceChild taskInstance, TaskExecutionMode mode, Lookup inferLookup, Lookup executeLookup, CancellationToken cancellationToken)
MSBUILD : error MSB4166:    at Microsoft.Build.BackEnd.TargetEntry.ProcessBucket(ITaskBuilder taskBuilder, TargetLoggingContext targetLoggingContext, TaskExecutionMode mode, Lookup lookupForInference, Lookup lookupForExecution)
MSBUILD : error MSB4166:    at Microsoft.Build.BackEnd.TargetEntry.ExecuteTarget(ITaskBuilder taskBuilder, BuildRequestEntry requestEntry, ProjectLoggingContext projectLoggingContext, CancellationToken cancellationToken)
MSBUILD : error MSB4166:    at Microsoft.Build.BackEnd.TargetBuilder.ProcessTargetStack(ITaskBuilder taskBuilder)
MSBUILD : error MSB4166:    at Microsoft.Build.BackEnd.TargetBuilder.BuildTargets(ProjectLoggingContext loggingContext, BuildRequestEntry entry, IRequestBuilderCallback callback, ValueTuple`2[] targetNames, Lookup baseLookup, CancellationToken cancellationToken)
MSBUILD : error MSB4166:    at Microsoft.Build.BackEnd.RequestBuilder.BuildProject()
MSBUILD : error MSB4166:    at Microsoft.Build.BackEnd.RequestBuilder.RequestThreadProc(Boolean setThreadParameters)
MSBUILD : error MSB4166: ===================

[pavelsavara]

@mangod9 here is net trace you asked for

• 30 minutes of dotnet-trace collect --profile gc-collect in the actual linux CI agent.
• This is just one of 8 MSBuild processes fighting over the same 16GB of RAM without a swap file.

trace.1740594036.zip

Build

2025-02-26T18:50:42.9241424Z --------disk---------
2025-02-26T18:50:42.9275595Z Filesystem      Size  Used Avail Use% Mounted on
2025-02-26T18:50:42.9277585Z overlay          98G   36G   58G  39% /
2025-02-26T18:50:42.9278400Z tmpfs            64M     0   64M   0% /dev
2025-02-26T18:50:42.9278692Z shm              64M     0   64M   0% /dev/shm
2025-02-26T18:50:42.9278963Z /dev/root       248G   12G  237G   5% /__t
2025-02-26T18:50:42.9279234Z /dev/sdb1        98G   36G   58G  39% /__w/1
2025-02-26T18:50:42.9279528Z tmpfs           3.2G  1.3M  3.2G   1% /run/docker.sock
2025-02-26T18:50:42.9279873Z tmpfs           7.9G     0  7.9G   0% /proc/acpi
2025-02-26T18:50:42.9280163Z tmpfs           7.9G     0  7.9G   0% /proc/scsi
2025-02-26T18:50:42.9280609Z tmpfs           7.9G     0  7.9G   0% /sys/firmware
2025-02-26T18:50:42.9282433Z --------memory-------
2025-02-26T18:50:42.9322080Z                total        used        free      shared  buff/cache   available
2025-02-26T18:50:42.9322581Z Mem:            15Gi        14Gi       391Mi       662Mi       2.1Gi       1.5Gi
2025-02-26T18:50:42.9322957Z Swap:             0B          0B          0B
2025-02-26T18:50:42.9323232Z --------processes----
2025-02-26T18:50:42.9406620Z USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
2025-02-26T18:50:42.9407635Z root           1  0.0  0.0   4664  3200 ?        Ss   18:07   0:00 bash -c '/__a/externals/node20_1/bin/node' --version && echo 'container-startup-using-node-20' && '/__a/externals/node20_1/bin/node' -e 'setInterval(function(){}, 24 * 60 * 60 * 1000);' || '/__a/externals/node16/bin/node' --version && echo 'container-startup-using-node-16' && '/__a/externals/node16/bin/node' -e 'setInterval(function(){}, 24 * 60 * 60 * 1000);' || echo 'container-startup-failed'
2025-02-26T18:50:42.9408537Z root           8  0.0  0.0 725932 10368 ?        Sl   18:07   0:00 /__a/externals/node20_1/bin/node -e setInterval(function(){}, 24 * 60 * 60 * 1000);
2025-02-26T18:50:42.9409118Z cloudte+     103  0.0  0.0 858284 12160 ?        Ssl  18:10   0:00 /__a/externals/node20_1/bin/node /__w/_temp/containerHandlerInvoker.js
2025-02-26T18:50:42.9409653Z cloudte+     115  0.0  0.0 991740 15144 ?        Sl   18:10   0:00 /__a/externals/node20_1/bin/node /__w/_tasks/CmdLine_d9bafed4-0b18-4f58-968d-86655b4d2ce9/2.250.1/cmdline.js
2025-02-26T18:50:42.9410316Z cloudte+     122  0.0  0.0   4804  3072 ?        S    18:10   0:00 /usr/bin/bash --noprofile --norc /__w/_temp/e787c1c4-5fc8-4899-9452-6fcf1359313f.sh
2025-02-26T18:50:42.9411061Z cloudte+     123  0.0  0.0   4804  3456 ?        S    18:10   0:00 bash /__w/1/s/build.sh -ci -arch wasm -os browser -s mono+libs+host+packs+libs.tests -c Release /p:ArchiveTests=true /p:MonoEnableAssertMessages=true /p:BrowserHost=linux /p:RunSmokeTestsOnly=False /p:InstallChromeForTests=true /p:InstallFirefoxForTests=true /p:AotHostArchitecture=x64 /p:AotHostOS=linux
2025-02-26T18:50:42.9412279Z cloudte+     127  0.0  0.0   4936  3584 ?        S    18:10   0:00 bash /__w/1/s/eng/build.sh -ci -arch wasm -os browser -s mono+libs+host+packs+libs.tests -c Release /p:ArchiveTests=true /p:MonoEnableAssertMessages=true /p:BrowserHost=linux /p:RunSmokeTestsOnly=False /p:InstallChromeForTests=true /p:InstallFirefoxForTests=true /p:AotHostArchitecture=x64 /p:AotHostOS=linux
2025-02-26T18:50:42.9413127Z cloudte+     161  0.0  0.0   4804  3456 ?        S    18:10   0:00 bash /__w/1/s/eng/stats.sh
2025-02-26T18:50:42.9413884Z cloudte+     242  0.0  0.0   5332  3712 ?        S    18:10   0:00 bash /__w/1/s/eng/common/build.sh -restore -build /p:TargetOS=browser /p:Subset=mono+libs+host+packs+libs.tests -configuration Release -tl:false /p:TargetArchitecture=wasm /p:BuildArchitecture=x64 /p:CMakeArgs="" -ci /p:ArchiveTests=true /p:MonoEnableAssertMessages=true /p:BrowserHost=linux /p:RunSmokeTestsOnly=False /p:InstallChromeForTests=true /p:InstallFirefoxForTests=true /p:AotHostArchitecture=x64 /p:AotHostOS=linux
2025-02-26T18:50:42.9415851Z cloudte+     773 23.7 16.4 275254876 2692952 ?   Sl   18:10   9:31 /__w/1/s/.dotnet/dotnet msbuild /m /nologo /clp:Summary /v:minimal /nr:false /warnaserror /p:TreatWarningsAsErrors=true /p:ContinuousIntegrationBuild=true /__w/1/s/.packages/microsoft.dotnet.arcade.sdk/10.0.0-beta.25113.2/tools/Build.proj /bl:"/__w/1/s/artifacts/log/Release/Build.binlog" /p:Configuration=Release /p:RepoRoot=/__w/1/s/ /p:Restore=true /p:Build=true /p:DotNetBuildRepo=false /p:DotNetBuildSourceOnly=false /p:Rebuild=false /p:Test=false /p:Pack=false /p:IntegrationTest=false /p:PerformanceTest=false /p:Sign=false /p:Publish=false /p:TargetOS=browser /p:Subset=mono+libs+host+packs+libs.tests -tl:false /p:TargetArchitecture=wasm /p:BuildArchitecture=x64 /p:CMakeArgs="" /p:ArchiveTests=true /p:MonoEnableAssertMessages=true /p:BrowserHost=linux /p:RunSmokeTestsOnly=False /p:InstallChromeForTests=true /p:InstallFirefoxForTests=true /p:AotHostArchitecture=x64 /p:AotHostOS=linux -logger:/__w/1/s/.packages/microsoft.dotnet.arcade.sdk/10.0.0-beta.25113.2/tools/net/Microsoft.DotNet.ArcadeLogging.dll
2025-02-26T18:50:42.9417507Z cloudte+     974 14.8 13.4 275253448 2200400 ?   Sl   18:12   5:44 /__w/1/s/.dotnet/dotnet /__w/1/s/.dotnet/sdk/10.0.100-alpha.1.25077.2/MSBuild.dll /noautoresponse /nologo /nodemode:1 /nodeReuse:false /low:false
2025-02-26T18:50:42.9418218Z cloudte+     975 13.2 14.2 275202588 2329352 ?   Sl   18:12   5:06 /__w/1/s/.dotnet/dotnet /__w/1/s/.dotnet/sdk/10.0.100-alpha.1.25077.2/MSBuild.dll /noautoresponse /nologo /nodemode:1 /nodeReuse:false /low:false
2025-02-26T18:50:42.9418955Z cloudte+     976 14.2 13.1 275236036 2150800 ?   Sl   18:12   5:29 /__w/1/s/.dotnet/dotnet /__w/1/s/.dotnet/sdk/10.0.100-alpha.1.25077.2/MSBuild.dll /noautoresponse /nologo /nodemode:1 /nodeReuse:false /low:false
2025-02-26T18:50:42.9420095Z cloudte+   16965 78.0  7.7 275362648 1261096 ?   Sl   18:23  21:26 /__w/1/s/.dotnet/dotnet exec /__w/1/s/.packages/microsoft.net.compilers.toolset/4.14.0-2.25121.3/tasks/netcore/bincore/VBCSCompiler.dll -pipename:rG_xkd4PaK+xrT4f+KHnVh9jL_pAFV5AB14Vguq2OYM
2025-02-26T18:50:42.9420759Z cloudte+   17021  1.5  2.1 274427724 353520 ?    Sl   18:23   0:25 /__w/1/s/.dotnet/dotnet /__w/1/s/.dotnet/sdk/10.0.100-alpha.1.25077.2/MSBuild.dll /nologo /nodemode:2 /nodereuse:False /low:False
2025-02-26T18:50:42.9421338Z cloudte+   31225  2.5  4.2 274558792 698476 ?    Sl   18:33   0:25 /__w/1/s/.dotnet/dotnet /__w/1/s/.dotnet/sdk/10.0.100-alpha.1.25077.2/MSBuild.dll /nologo /nodemode:2 /nodereuse:False /low:False
2025-02-26T18:50:42.9422032Z cloudte+   31309  2.3  0.7 274296196 116396 ?    Sl   18:34   0:23 /__w/1/s/.dotnet/dotnet /__w/1/s/.dotnet/sdk/10.0.100-alpha.1.25077.2/MSBuild.dll /nologo /nodemode:2 /nodereuse:False /low:False
2025-02-26T18:50:42.9422601Z cloudte+   31370  1.5  0.6 274222264 100584 ?    Sl   18:34   0:15 /__w/1/s/.dotnet/dotnet /__w/1/s/.dotnet/sdk/10.0.100-alpha.1.25077.2/MSBuild.dll /nologo /nodemode:2 /nodereuse:False /low:False
2025-02-26T18:50:42.9423036Z cloudte+   38074  0.0  0.0   4724  3072 ?        R    18:50   0:00 ps -aux

[lewing]

@mangod9 has anyone had time to look at the trace/

[baronfel]

Tracing idea: the MSBuild central node could piggyback on the built-in runtime metrics over the existing eventpipe connection that the runtime supports, and aggregate those into the logs.

[JanProvaznik]

As a part of our telemetry effort, we exposed memory consumed by task runs (aggregated by task type, computed by subtracting GC.GetTotalMemory(false) before and after). @pavelsavara @pragmanomos

The feature requires MSBuild VS 17.14 Preview 2+/.NET 10 Preview 2/3 and can be enabled with env vars as follows:
$env:MSBUILD_TELEMETRY_SAMPLE_RATE=1.0; $env:MSBUILDOUTPUTNODESTELEMETRY="1" ; dotnet.exe build project.csproj in case of MSBuild.exe coming from VS it would also send this data to VS Kusto

though we refactored it later so in 17.15+ MSBUILDFLUSHNODESTELEMETRYINTOCONSOLE will be the variable for outputting to console