dotnet-gcdump System.ApplicationException: ETL file shows the start of a heap dump but not its completion.

[InCerryGit]

Description

System.ApplicationException: ETL file shows the start of a heap dump but not its completion. when using dotnet-gcdump to dump a large managed heap。

.NET 5.0.403 Release

PS D:\> dotnet-gcdump collect -p 18796 -v
Writing gcdump to 'D:\20211125_171456_18796.gcdump'...
  0.0s: Creating type table flushing task
  0.0s: Flushing the type table
  0.2s: Done flushing the type table
  0.2s: Requesting a .NET Heap Dump
  7.8s: gcdump EventPipe Session started
  7.9s: Starting to process events
  7.9s: .NET Dump Started...
Found a Gen2 Induced non-background GC Start at 0.232 msec GC Count 1623
  8.0s: Making GC Heap Progress...
 30.0s: Timed out after 30 seconds
 30.0s: Shutting down gcdump EventPipe session
Found Module System.Private.CoreLib.dll ID 0x7ffdbb134020
Found Module PerformanceGC.dll ID 0x7ffdbb3127b8
Found Module System.Runtime.dll ID 0x7ffdbb314298
Found Module System.Linq.dll ID 0x7ffdbb343988
Found Module System.Console.dll ID 0x7ffdbb347278
Found Module System.Collections.dll ID 0x7ffdbb349068
Found Module System.Threading.dll ID 0x7ffdbb379748
Found Module System.Text.Encoding.Extensions.dll ID 0x7ffdbb37d9c8
 30.2s: EventPipe Listener dying
 31.0s: still reading...
 31.5s: gcdump EventPipe session shut down
 31.5s: gcdump EventPipe Session closed
 31.5s: [Error] Exception during gcdump: System.ApplicationException: ETL file shows the start of a heap dump but not its completion.
   at DotNetHeapDumpGraphReader.ConvertHeapDataToGraph() in /_/src/Tools/dotnet-gcdump/DotNetHeapDump/DotNetHeapDumpGraphReader.cs:line 711
   at Microsoft.Diagnostics.Tools.GCDump.EventPipeDotNetHeapDumper.DumpFromEventPipe(CancellationToken ct, Int32 processID, MemoryGraph memoryGraph, TextWriter log, Int32 timeout, DotNetHeapInfo dotNetInfo) in /_/src/Tools/dotnet-gcdump/DotNetHeapDump/EventPipeDotNetHeapDumper.cs:line 205
[ 31.5s: Done Dumping .NET heap success=False]
        Failed to collect gcdump. Try running with '-v' for more information.

Code

using System;
using System.Linq;

namespace PerformanceGC
{
    class Program
    {
        static void Main(string[] args)
        {
            var data = Enumerable.Range(0, 1000).Select(i => new ValueObject()).ToArray();
            Console.WriteLine(data.Length);
            Console.ReadLine();  // Keep console open. use dotnet-gcdump
            Console.WriteLine(data.Length);
        }
    }
    
    public class ValueObject
    {
        public Data[] Objectes { get; set; }
        public ValueObject()
        {
            Objectes = Enumerable.Range(0, 100).Select(i => new Data()).ToArray();
        }
    }
    
    public class Data
    {
        public int[] DataArray { get; set; }
        
        public string[] DataString { get; set; }
        
        public Data()
        {
            var length = 8500;
            DataArray = new int[length];
            DataString = new string[length];
            Array.Fill(DataArray, 1);
            Array.Fill(DataString, "1000");
        }
    }
}

Configuration

PS D:\> dotnet --info
.NET SDK (反映任何 global.json):
 Version:   6.0.100
 Commit:    9e8b04bbff

运行时环境:
 OS Name:     Windows
 OS Version:  10.0.22000
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Program Files\dotnet\sdk\6.0.100\

Host (useful for support):
  Version: 6.0.0
  Commit:  4822e3c3aa

.NET SDKs installed:
  2.1.818 [C:\Program Files\dotnet\sdk]
  3.1.404 [C:\Program Files\dotnet\sdk]
  5.0.102 [C:\Program Files\dotnet\sdk]
  5.0.403 [C:\Program Files\dotnet\sdk]
  6.0.100 [C:\Program Files\dotnet\sdk]

.NET runtimes installed:
  Microsoft.AspNetCore.All 2.1.23 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.1.30 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.1.23 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.1.30 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 3.1.10 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 5.0.12 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 6.0.0 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 2.1.13 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.23 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.30 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 3.1.10 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 5.0.12 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 6.0.0 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.WindowsDesktop.App 3.1.10 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 5.0.12 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]
  Microsoft.WindowsDesktop.App 6.0.0 [C:\Program Files\dotnet\shared\Microsoft.WindowsDesktop.App]

To install additional .NET runtimes or SDKs:
  https://aka.ms/dotnet-download

PS D:\> dotnet tool list -g
包 ID                   版本              命令
--------------------------------------------------------
dotnet-cnblog          1.4.1           dotnet-cnblog
dotnet-counters        5.0.152202      dotnet-counters
dotnet-dump            5.0.152202      dotnet-dump
dotnet-gcdump          5.0.251802      dotnet-gcdump
dotnet-sos             5.0.160202      dotnet-sos
dotnet-trace           5.0.152202      dotnet-trace
powershell             7.1.3           pwsh
upgrade-assistant      0.2.227701      upgrade-assistant

[noahfalk]

I reproduced this issue and tracked it down to dropped events from EventPipe. Fixing this should be doable, but may not be trivial. For those running into it and needing a more immediate solution my best suggestion would be to use dotnet-dump instead. dotnet-dump uses a different mechanism to collect the memory which doesn't have this lossiness problem.

As best I can tell this is long-existing problem in how the feature is designed rather than any simple error in the implementation. Back when the heap dump feature was first created (10 years ago?) it streamed the GC heap data via ETW events. Both ETW and later EventPipe have a buffer between the producer and consumer of the events, but if the producer outpaces the consumer too much the buffer overflows and events are dropped. For most applications the GC heap isn't so large as to overflow the buffer. However for GC heaps with a huge number of objects like the one in this example the number of events exceeds what the buffer can hold and heap data is lost.

An ideal fix would be to add a loss-less transport mode to EventPipe where the producer blocks if buffer space isn't available.

[dennis-yemelyanov]

Also hit the exact same issue. Was able to fix this by increasing the buffer size by setting the COMPlus_EventPipeCircularMB var to a larger value. In my case setting it to “7D0” (2000 MB) was enough and allowed all events to be captured without any issues.

Looks like if the resulting trace file is about the same size as this buffer (default is 1000 MB), it’s a good sign that the buffer needs to be increased (for example, can be doubled).

Credit for helping me on this and suggesting this setting goes to @Maoni0 😀