Potentially erroneous gcdump metrics

[josalem]

Hi @josalem,

(sorry for the late response)
I've been playing with this in the meantime, and I've been confused by the results I'm getting. So here is a concrete example. I've recorded a gcdump for my process at 11:05, and 11:38. You can see the memory usage graph of the application (this is rendered based on the memory usage of the whole Docker container, but the container has nothing else running besides the ASP.NET process, so it should correspond pretty closely to the memory usage of the actual ASP.NET Core application).

The memory usage is gradually increasing, and there are two spikes at 11:05 and 11:38, which exactly corresponds to the time when the dump was recorded, so I assume those two spikes are caused by dotnet-gcdump itself.
The memory usage before recording the dump at 11:04 was around 3.194 GB, and at 11:37 was around 3.470 GB. (This is just what the Prometheus metric is showing at those times, so probably not accurate down to the byte, but it should be roughly correct.)

The first bit of confusion comes when I open the first dump in PerfView. I'd expect the "Total Metric" field at the top to show the total memory usage in bytes, so I'm expecting to see a number like 3,194,xxx,xxx. Instead of that, it shows 13,362,950, which as far as I understand corresponds to 13MB?

And if I open the second dump, it shows 6,574,561:

If I display the diff between the two, that accordingly shows -6,788,384 in total, and it mostly shows decrease in the instance counts:

And much less increase

I've uploaded the two dumps: at 11:05 and at 11:38

So something seems to be very off. If you have any ideas about what I'm doing wrong, it'd be greatly appreciated. (Sorry if I'm missing something trivial, or if I'm using PerfView completely wrong.)

Originally posted by @markvincze in #586 (comment)

[josalem]

I moved this into its own issue.

This is quite interesting. I'm curious, if you take a third gcdump, do you see a result similar to the second? Additionally, if you take a regular memory dump of the process, what do you see when you run !dumpheap -stat on that? Let me open these in Visual Studio and compare the counts in there since it renders the data slightly differently.

The thing that strikes me is that the delta is almost exactly half of the first's inclusive count.

[josalem]

I opened these up and removed all filtering on the data in PerfView to see this:

I'm seeing the total inclusive count on everything go up by ~16,000,000 which still doesn't match what you are saying you would expect. The thing that stands out to me more is that the count seems to be the exact same value for both at 10,000,000.00. This tells me there might some kind of sampling being done on the data during either the encoding or the opening of the file. I'll take a peek under the hood on the TraceEvent side of things to see if it is sampling the incoming events in some capacity during collection.

[markvincze]

@josalem I didn't notice the filters before. The one that affects the stats is ExcPats, if I change it from [not reachable from roots] to empty, then on the second dump the total increases from 6,788,384 to 544,591,700 for me as well.
The default [not reachable from roots] filter means that it doesn't show objects which can't be accessed (so the ones which are supposed to be cleaned up by the next GC), right? That would also be very weird, that out of 544MB the amount of dead objects is 538MB, and only 6MB is alive. (Particularly because I'm doing a GC.Collect() on every request to my service.)
And yeah, indeed the exact 10,000,000.00 value is very suspicious.

This instance is long gone, so I can't collect a third dump, but I'll collect one on a new instance, and I'll do the !dumpheap -stat afterwards.

[markvincze]

I tested !dumpheap -stat, and it shows a different total object count than the gcdump.
This time the memory usage of the app was at ~3.14GB. The gcdump with the filter removed shows 506,869,500 as Total, and the Count shows 10,000,000 again.

If I collect a regular dump, and do dumpheap -stat, it prints 22,327,898 as the total number of objects.

...
Total 22327898 objects

Is it possible that the total number of objects dotnet-gcdump can discover is somehow capped at 10,000,000?

[josalem]

It is quite possible. Could you try one more thing? PerfView has the ability to create a gcdump from a memory dump. Please try creating a gcdump from your memory dump. This might give us some insight before I dig into the TraceEvent code.

[markvincze]

@josalem,

This is what I'm supposed to be able to do with "Memory->Take Heap Snapshot From Dump" menu option in Perfview?
I tried it, but it fails, with this error in the log

Exec: "C:\Users\mvincze\AppData\Roaming\PerfView\VER.2019-10-25.02.13.43.832\amd64\HeapDump.exe" /processDump  /MaxDumpCountK=25327 "C:\Workspaces\Local\RulesApiDumps\core_20191108_205853" "C:\Workspaces\Local\RulesApiDumps\converted.gcdump"
Creating heap dump C:\Workspaces\Local\RulesApiDumps\converted.gcdump from process dump C:\Workspaces\Local\RulesApiDumps\core_20191108_205853.
HeapDump Error: Microsoft.Diagnostics.Runtime.ClrDiagnosticsException: Could not load crash dump, HRESULT: 0x80070057
   at Microsoft.Diagnostics.Runtime.DbgEngDataReader..ctor(String dumpFile)
   at Microsoft.Diagnostics.Runtime.DataTarget.LoadCrashDump(String fileName)
   at GCHeapDumper.InitializeClrRuntime(String processDumpFile, DataTarget& target, ClrRuntime& runtime)
   at GCHeapDumper.DumpHeapFromProcessDump(String processDumpFile)
   at Program.MainWorker(String[] args)

I tried it both with the default "Max Dump Objs" option (100K), and also with setting it to 25 million, but both resulted in the same error.

Do you know what might cause this?

[josalem]

I don't know, but it looks like a failure in whatever mechanism is being used to load .NET crashdumps. @brianrob any ideas?

On a related note, the MaxDumpObjK option makes me think that there is some limitation in the processing on how many objects get used to compute the graph. I'll take a look into TraceEvent/PerfView to see if this is the issue and, if so, is there a programmatically configurable option on the logic.

[brianrob]

This failure is because it looks like the crash dump being loaded is a Linux core file (C:\Workspaces\Local\RulesApiDumps\core_20191108_205853), which is not supported. This mechanism only works with Windows crash dumps.

[josalem]

Thanks @brianrob.

Took a quick look through the parsing logic, and it looks like the code from PerfView has a hard coded cap of 10,000,000 nodes in the graph, and when that gets hit, this if statement triggers:

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

Lines 700 to 705 in 7d343ee

	if (m_graph.NodeCount >= maxNodeCount)
	{
	doCompletionCheck = false;
	var userMessage = string.Format("Exceeded max node count {0}", maxNodeCount);
	m_log.WriteLine("[WARNING: ]", userMessage);
	break;

This should be fairly easy to make a configurable option. I want to do some more reading/research to make sure that this is actually the lever we want to pull, but it looks that might be the limiter here.

[markvincze]

@josalem nice find! 👍
Thanks a lot for helping with this issue this quickly, it's really appreciated!

(Btw. I see in the code you linked that the "Exceeded max node count {0}" warning is added to the output, but dotnet-gcdump didn't print this for me, even with the -v flag.)

[markvincze]

@josalem do you know if it would be easy for me to create an experimental build with that limit increased to a larger value? Is it as simple as just changing that constant?