gcdump fails to collect dump under high load.

[iliamosko]

Description

When running dotnet-gcdump collect on a application that is using a large amount of memory the following exception occurs:

Exception:

63.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 512
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
[ 63.5s: Done Dumping .NET heap success=False]
Failed to collect gcdump. Try running with '-v' for more information.

I've looked into the source code and it seems like the exception gets thrown here:

diagnostics/src/Tools/dotnet-gcdump/DotNetHeapDump/DotNetHeapDumpGraphReader.cs

Lines 510 to 513 in a584d05

	if (!m_ignoreEvents)
	{
	throw new ApplicationException("ETL file shows the start of a heap dump but not its completion.");
	}

I have created a repo to try and reproduce this issue:
Repo

This application creates objects and loads the memory. Collecting a gcdump when the application is around 200-800mb in memory usage, gcdump completes successfully. However, when the application reaches to about 1300mb the above exception occurs.

There are 2 other exceptions that I have come across while trying to reproduce the issue but I am not sure how relevant they are to the initial problem:

Exception 1:

and

Exception 2:

Any information as to why these exceptions are occurring would be a huge help.

Configuration

Tool: dotnet-gcdump
OS: LINUX and Win10
Environment: Issue happens either when containerized or as a standalone application.

[tommcdon]

@josalem

[josalem]

I'll try running the repro.

The logs in your screenshots imply that you aren't receiving all the data from the runtime. In the first case, the gc end event, and edge data in the second. Do you have a full log output from these failures with the -v flag?

I noticed your repro is shelling out to run dotnet gcdump every 3 seconds. Is this happening on the first execution or only later ones? Every time you run dotnet-gcdump you incur a full gen2 GC which can get expensive if you're running it every 3 seconds. I'm assuming that is just for the repro, correct?

I also noticed you are explicitly setting a long timeout (45 seconds). Does varying this change the behavior you observed?

If you collect a gcdump using PerfView under the same conditions, do you see similar errors?

[iliamosko]

The 3 second timeout is just a pause in between successive dotnet gcdump commands. There will be only one instance of dotnet gcdump running. The next dotnet gcdump will run 3 seconds after the deletion of the .gcdump file it has collected. The whole point of the repro is to see when dotnet gcdump fails to collect a dump when the applications memory becomes to high.

Either using the default timeout or setting a custom timeout for dotnet gcdump, the outcome is still the same. I set a timeout of 45 seconds to see if maybe giving gcdump a bit more time that it will successfully collect a dump.

I've tried collect a gcdump using Perfview, but it ran succesffully with no errors even when the applications memory usage exceeded 1200Mb.

Logs

I have 2 of the 3 output logs.
Log for 'Exception 1':

0.0s: Creating type table flushing task
0.5s: Flushing the type table
0.7s: Done flushing the type table
0.7s: Requesting a .NET Heap Dump
4.3s: gcdump EventPipe Session started
4.5s: Starting to process events
4.6s: .NET Dump Started...
Found a Gen2 Induced non-background GC Start at 260.573 msec GC Count 1494
4.6s: Making GC Heap Progress...
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 3,678.713 but id 1495 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 3,680.622 but id 1496 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 3,778.439 but id 1501 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 3,839.957 but id 1502 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 3,900.338 but id 1503 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 4,011.757 but id 1504 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 4,110.471 but id 1505 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 4,137.714 but id 1506 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 4,142.876 but id 1507 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 4,186.384 but id 1508 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 4,205.241 but id 1509 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 4,298.152 but id 1510 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 4,346.654 but id 1511 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 4,456.644 but id 1512 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 4,493.054 but id 1513 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 4,552.423 but id 1514 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 4,568.309 but id 1515 != 1494 Target ID
...
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 43,080.986 but id 2377 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 43,216.320 but id 2378 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 43,222.359 but id 2379 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 43,228.623 but id 2380 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 43,237.524 but id 2381 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 43,296.100 but id 2382 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 43,301.296 but id 2383 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 43,405.777 but id 2384 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 43,442.758 but id 2385 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 43,454.153 but id 2386 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 43,533.384 but id 2387 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 43,548.619 but id 2388 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 43,724.231 but id 2389 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 43,732.283 but id 2390 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 43,851.560 but id 2391 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 44,006.055 but id 2392 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 44,059.569 but id 2394 != 1494 Target ID
Found a GC Stop at 44,183.607 but id 2395 != 1494 Target ID
45.1s: Timed out after 45 seconds
45.1s: Shutting down gcdump EventPipe session
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 44,245.803 but id 2396 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 44,255.851 but id 2397 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 44,308.097 but id 2398 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 44,310.410 but id 2399 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 44,313.071 but id 2400 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 44,341.315 but id 2401 != 1494 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 44,370.713 but id 2402 != 1494 Target ID
Found Module System.Private.CoreLib.dll ID 0x7ff9506b4020
Found Module TestApp.dll ID 0x7ff95088f7c0
Found Module System.Runtime.dll ID 0x7ff9508914e8
Found Module System.Threading.Thread.dll ID 0x7ff9508b3838
Found Module System.Console.dll ID 0x7ff9508b3e60
Found Module System.Runtime.Extensions.dll ID 0x7ff9508b51e8
Found Module System.Threading.dll ID 0x7ff9508b7be8
Found Module System.Text.Encoding.Extensions.dll ID 0x7ff9508be3b8
Found Module System.Collections.dll ID 0x7ff9508f0118
45.4s: EventPipe Listener dying
46.1s: still reading...
47.1s: still reading...
48.1s: still reading...
49.1s: still reading...
50.1s: still reading...
50.5s: gcdump EventPipe session shut down
50.5s: gcdump EventPipe Session closed
50.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
[ 50.8s: Done Dumping .NET heap success=False]
Failed to collect gcdump. Try running with '-v' for more information.

Log for 'Exception 2':

0.0s: Creating type table flushing task
0.5s: Flushing the type table
0.7s: Done flushing the type table
0.7s: Requesting a .NET Heap Dump
5.7s: gcdump EventPipe Session started
5.9s: Starting to process events
6.0s: .NET Dump Started...
Found a Gen2 Induced non-background GC Start at 166.970 msec GC Count 1120
6.0s: Making GC Heap Progress...
11.2s: .NET GC Complete.
Found a GC Stop at 4,977.455 for GC 1120, ignoring events from now on.
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
11.3s: Shutting down gcdump EventPipe session
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
GC Start found but not a Foreground Gen 2 GC
Found Module System.Private.CoreLib.dll ID 0x7ff946984020
Found Module GCDumpTestApp.dll ID 0x7ff946b5f810
Found Module System.Runtime.dll ID 0x7ff946b614e8
Found Module System.Threading.Thread.dll ID 0x7ff946b83838
Found Module System.Console.dll ID 0x7ff946b83fb8
Found Module System.Threading.dll ID 0x7ff946b85c10
Found Module System.Runtime.Extensions.dll ID 0x7ff946b86618
Found Module System.Text.Encoding.Extensions.dll ID 0x7ff946b8c7a0
Found Module System.Collections.dll ID 0x7ff946bbd030
Found Module System.Diagnostics.Process.dll ID 0x7ff946be8c38
Found Module System.ComponentModel.Primitives.dll ID 0x7ff946be9770
Found Module System.IO.FileSystem.dll ID 0x7ff946beb9f0
Found Module System.Linq.dll ID 0x7ff946bec9a0
Found Module System.Memory.dll ID 0x7ff946c12bc8
Found Module Microsoft.Win32.Primitives.dll ID 0x7ff946c14a90
Found Module System.Runtime.InteropServices.dll ID 0x7ff946c1a410
12.1s: EventPipe Listener dying
12.3s: still reading...
13.3s: still reading...
14.3s: still reading...
15.4s: still reading...
16.4s: still reading...
17.4s: still reading...
18.4s: still reading...
19.4s: still reading...
20.4s: still reading...
20.4s: gcdump EventPipe session shut down
20.4s: gcdump EventPipe Session closed
Processing Heap Data, BulkTypeEventCount:5 BulkNodeEventCount:16381 BulkEdgeEventCount:0
20.5s: [Error] Exception during gcdump: System.ApplicationException: Error not enough edge data. Giving up on heap dump.
at DotNetHeapDumpGraphReader.GetNextEdge() in //src/Tools/dotnet-gcdump/DotNetHeapDump/DotNetHeapDumpGraphReader.cs:line 805
at DotNetHeapDumpGraphReader.ConvertHeapDataToGraph() in //src/Tools/dotnet-gcdump/DotNetHeapDump/DotNetHeapDumpGraphReader.cs:line 680
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
[ 20.5s: Done Dumping .NET heap success=True]
[ERROR] System.ApplicationException: RootIndex not set.
at Graphs.Graph.AllowReading() in //src/Tools/dotnet-gcdump/DotNetHeapDump/Graph.cs:line 236
at Microsoft.Diagnostics.Tools.GCDump.CollectCommandHandler.TryCollectMemoryGraph(CancellationToken ct, Int32 processId, Int32 timeout, Boolean verbose, MemoryGraph& memoryGraph) in //src/Tools/dotnet-gcdump/CommandLine/CollectCommandHandler.cs:line 128
at Microsoft.Diagnostics.Tools.GCDump.CollectCommandHandler.<>c__DisplayClass1_0.b__0() in //src/Tools/dotnet-gcdump/CommandLine/CollectCommandHandler.cs:line 79
at System.Threading.Tasks.Task`1.InnerInvoke()
at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location where exception was thrown ---
at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
--- End of stack trace from previous location where exception was thrown ---
at Microsoft.Diagnostics.Tools.GCDump.CollectCommandHandler.Collect(CancellationToken ct, IConsole console, Int32 processId, String output, Int32 timeout, Boolean verbose, String name) in /_/src/Tools/dotnet-gcdump/CommandLine/CollectCommandHandler.cs:line 88

[josalem]

Hmmm that is strange behavior indeed. The first log indicates that you didn't get a GC stop event for the GC you triggered (GC # 1494). The fact that it then observes a GC stop for GC # 1495 afterwards seems to indicate that the GC stop event either never was fired or the event itself was dropped. The second log indicates that it saw the Start/Stop event pair but is missing events in between.

Both logs show the tool observing many GCs besides the one that it triggered. I'm wondering if the number of GCs occurring is causing a high volume of events to be fired on the same keywords that dotnet-gcdump uses to collect dumps. If enough events are sent all at once, there's the possibility that the buffer size used by the tool is insufficient and there are enough dropped events to break dump collection functionality.

When you tested with PerfView, did you do the same "request every 3 seconds" behavior or did you perform a one-off gcdump at 1200MB?

I have been focused on runtime work, so I haven't had a chance to loop back on this and check your repro.

[iliamosko]

I just ran a one-off gcdump using PerfView. If I was to run a one-off dotnet-gcdump when the memory is 1200Mb, then it would show the same exception as 'Exception 1'.

I have the log from the gcdump command we ran on a production clone server. Right away we can see that the default timeout of the command is not being honored. The exception gets thrown at ~60s. Unlike the previous logs I have, there is no indicator that there is a problem with dotnet-gcdump.

Here is the log that we have received when running dotnet-gcdump on our production clone server:

./dotnet-gcdump collect -p 1 -v
0.0s: Creating type table flushing task
0.1s: Flushing the type table
0.4s: Done flushing the type table
0.4s: Requesting a .NET Heap Dump
< Found Modules Redacted >
62.1s: EventPipe Listener dying
62.8s: still reading...
63.5s: gcdump EventPipe session shut down
63.5s: gcdump EventPipe Session closed
63.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 512
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
[ 63.5s: Done Dumping .NET heap success=False]
Failed to collect gcdump. Try running with '-v' for more information.

[liorss18]

What's the status of this issue, as I suffer from the same thing as well.
Our process is 60gb.
We took the dump while the process was doing almost 0 work (i.e: almost 0 rps and 0 cpu).
It looks from the logs that gcdump misses the GCStop event with the relevant ID:

Writing gcdump to '/app/20211222_135843_1.gcdump'...
  0.0s: Creating type table flushing task
  0.1s: Flushing the type table
  0.3s: Done flushing the type table
  0.3s: Requesting a .NET Heap Dump
112.7s: gcdump EventPipe Session started
112.8s: Starting to process events
112.8s: .NET Dump Started...
Found a Gen2 Induced non-background GC Start at 1.869 msec GC Count 172
112.8s: Making GC Heap Progress...
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 571,016.558 but id 173 != 172 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 710,015.748 but id 174 != 172 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 721,807.140 but id 175 != 172 Target ID
GC Start found but not a Foreground Gen 2 GC
Found a GC Stop at 729,784.572 but id 176 != 172 Target ID
..This just keeps going until timed out (timeout was set to a few hours)

[tommcdon]

@iliamosko @liorss18 we apologize for the delay. EventPipe through the diagnostics IPC channel is designed to be non-intrusive to program execution. Today gcdump uses the IPC channel to collect the events which means we could be dropping the GCEnd events even though we are sending the GCStart one. Large address spaces may cause the event pipe buffer to overflow with too many GC events. Couple ideas:

1. Increasing the buffer size may help resolve this issue. Add dotnet-trace's --buffersize command-line argument to dotnet-gcdump. The current size looks like it is currently set to 1024 and is non-configurable

   diagnostics/src/Tools/dotnet-gcdump/DotNetHeapDump/EventPipeDotNetHeapDumper.cs

   Line 235 in 88b248d

   _session = _client.StartEventPipeSession(providers, requestRundown, 1024);

2. EventPipe v2 supports a SequenceNumber which can be used if we are dropping events. Perhaps we should use that to warn the user and suggest increasing the buffer size.
3. We could implement blocking events using ICorProfiler EventPipe callbacks which are synchronous to runtime execution and therefore we would not drop events.
4. As an alternative to the above, investigate making certain events "required" - meaning the runtime would be paused rather than dropping the event. For example, we could add an EventPipe mode which pauses the runtime to prevent us from dropping "important" events.

Adding @noahfalk @josalem for thoughts.

[noahfalk]

We did add a known issue to the docs about the overflow on large heaps. However short of implementing an EventPipe non-lossy mode (3 or 4) this issue is going to persist. I think the best solution for now on apps with very large heaps is to use dotnet-dump instead.