OOM when running microbenchmarks

[adamsitnik]

I was running all the benchmarks for net6.0 and net7.0 over the night on my Ubuntu machine and both runs have failed. I've run exact same benchmarks night before on the same machine using Windows (dual boot PC) and everything was fine.

Since the issue reproducible on both .NET 6 and 7 it's most likely a leak in BenchmarkDotNet itself, unless we have back ported same bug to both .NET 6 and 7 which I really doubt.

[2022/11/16 02:06:51][INFO] // ** Remained 2638 (57.4%) benchmark(s) to run. Estimated finish 2022-11-16 7:19 (5h 12m from now) **
[2022/11/16 02:06:51][INFO] // **************************
[2022/11/16 02:06:51][INFO] // Benchmark: Perf_StreamWriter.WritePartialCharArray: Job-JFLJKI(PowerPlanMode=00000000-0000-0000-0000-000000000000, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1) [writeLength=100]
[2022/11/16 02:06:51][INFO] // *** Execute ***
[2022/11/16 02:06:51][INFO] // Launch: 1 / 1
[2022/11/16 02:06:51][INFO] // Execute: dotnet 127ae2a3-5939-4aa3-b282-e33fe7b4210c.dll --anonymousPipes 4092 4093 --benchmarkName "System.IO.Tests.Perf_StreamWriter.WritePartialCharArray(writeLength: 100)" --job "PowerPlanMode=00000000-0000-0000-0000-000000000000, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1" --benchmarkId 1954 in /home/adam/projects/performance/artifacts/bin/MicroBenchmarks/Release/net6.0/127ae2a3-5939-4aa3-b282-e33fe7b4210c/bin/Release/net6.0
[2022/11/16 02:06:51][INFO] Out of memory.
[2022/11/16 02:06:52][INFO] $ popd
[2022/11/16 02:06:52][ERROR] Process exited with status 134
[2022/11/16 02:06:52][INFO] Run failure registered
[2022/11/16 02:06:52][INFO] benchmarks_ci exited with non zero exit code, please check the log and report benchmark failure

[2022/11/16 05:57:39][INFO] // ** Remained 3360 (63.5%) benchmark(s) to run. Estimated finish 2022-11-16 12:35 (6h 37m from now) **
[2022/11/16 05:57:39][INFO] // **************************
[2022/11/16 05:57:39][INFO] // Benchmark: Perf_RandomAccess.WriteGather: Job-NHNJOJ(PowerPlanMode=00000000-0000-0000-0000-000000000000, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1) [fileSize=1048576, buffersSize=16384, options=None]
[2022/11/16 05:57:39][INFO] // *** Execute ***
[2022/11/16 05:57:39][INFO] // Launch: 1 / 1
[2022/11/16 05:57:39][INFO] // Execute: dotnet 4c3deb6a-6c7b-4925-9912-f111992a0ce4.dll --anonymousPipes 4092 4093 --benchmarkName "System.IO.Tests.Perf_RandomAccess.WriteGather(fileSize: 1048576, buffersSize: 16384, options: None)" --job "PowerPlanMode=00000000-0000-0000-0000-000000000000, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1" --benchmarkId 1930 in /home/adam/projects/performance/artifacts/bin/MicroBenchmarks/Release/net7.0/4c3deb6a-6c7b-4925-9912-f111992a0ce4/bin/Release/net7.0
[2022/11/16 05:57:39][INFO] Out of memory.
[2022/11/16 05:57:39][INFO] $ popd
[2022/11/16 05:57:39][ERROR] Process exited with status 134
[2022/11/16 05:57:39][INFO] Run failure registered
[2022/11/16 05:57:39][INFO] benchmarks_ci exited with non zero exit code, please check the log and report benchmark failure

.NET 6 BenchmarkRun-20221115-221428.log

.NET 7 BenchmarkRun-20221116-020748.log

[adamsitnik]

I've tried to investigate this "leak" by following these instructions.

The overall memory consumption was OK, both GC Heap Size and Working Set were low (less than 300 MB on a 32 GB machine).

The last values reported by dotnet-counters monitor were:

[System.Runtime]
    % Time in GC since last GC (%)                                         0    
    Allocation Rate (B / 1 sec)                                        8,168    
    CPU Usage (%)                                                          0    
    Exception Count (Count / 1 sec)                                        0    
    GC Committed Bytes (MB)                                              166    
    GC Fragmentation (%)                                                  60.288
    GC Heap Size (MB)                                                     65    
    Gen 0 GC Count (Count / 1 sec)                                         0    
    Gen 0 Size (B)                                                        24    
    Gen 1 GC Count (Count / 1 sec)                                         0    
    Gen 1 Size (B)                                                 1,510,704    
    Gen 2 GC Count (Count / 1 sec)                                         0    
    Gen 2 Size (B)                                                51,475,720       
    IL Bytes Jitted (B)                                              548,570    
    LOH Size (B)                                                      1.0594e+08   
    Monitor Lock Contention Count (Count / 1 sec)                          0    
    Number of Active Timers                                                0    
    Number of Assemblies Loaded                                          108    
    Number of Methods Jitted                                           9,218    
    POH (Pinned Object Heap) Size (B)                                178,912    
    ThreadPool Completed Work Item Count (Count / 1 sec)                   0    
    ThreadPool Queue Length                                                0    
    ThreadPool Thread Count                                                4    
    Time spent in JIT (ms / 1 sec)                                         0    
    Working Set (MB)                                                     265  

Consumed memory was not growing (the benchmarks run for a few hours), but the app failed with "Out of memory." anyway.

@Maoni0 @noahfalk @janvorli Do you have any idea what could be going on here? What next steps should I take in this investigation? Can I somehow configure Linux to capture a dump when process dies with OOM?

[janvorli]

@adamsitnik getting a dump at the time of crash may reveal the culprit. I would use the following before running the benchmarks:

echo 0x3f > /proc/self/coredump_filter
echo "core.%p" | sudo tee /proc/sys/kernel/core_pattern
ulimit -c unlimited

Then run the benchmark and after it fails, you should find a core.{PID} file somewhere in the artifacts (find . -name "core.*" )

[Maoni0]

@noahfalk would probably be a good idea to add instructions on how to take a core dump on linux on our diag page?

@adamsitnik when you have a dump, you could do an !ao sos command to start with, which will tell you if there were any managed memory leaks.

[noahfalk]

@noahfalk would probably be a good idea to add instructions on how to take a core dump on linux on our diag page?

You mean this? https://learn.microsoft.com/en-us/dotnet/core/diagnostics/dumps#collect-dumps-on-crash

[Maoni0]

You mean this? https://learn.microsoft.com/en-us/dotnet/core/diagnostics/dumps#collect-dumps-on-crash

yes, maybe put a link to it on the mem leak diag page (in the generate memory dump section)?

[adamsitnik]

@janvorli @Maoni0 @noahfalk thank you all for your help! it turned out to be a resource leak (dotnet/BenchmarkDotNet#2200)

Do you have any idea why we print "Out of memory." when we run out file descriptors? Why not "Out of resources"?

[noahfalk]

Do you have any idea why we print "Out of memory." when we run out file descriptors? Why not "Out of resources"?

Just a guess without knowing anything specific about the scenario: Some OS API returned an 'out_of_memory' error code to mean out of resources because people like reusing error codes for some reason :)

[janvorli]

There were a couple of places in the runtime where failure that is caused by not enough resources is reported as OOM. It should have been fixed by #74374 that updated the "Out of memory" message to mention it could be resources too, but somehow the PR was closed by the MSFT bot without merging the change. @eduardo-vp was this closing accidental?