Diagnostics: dotnet-dump is incredibly slow in dumpheap scenario

[Pzixel]

I'm trying to detect a memory leak in the application. Here is what tool says:

> dumpheap -stat -min 5000
Statistics:
              MT    Count    TotalSize Class Name
00007fa6a019a818        1        22080 System.Collections.Generic.Dictionary`2+Entry[[System.Type, System.Private.CoreLib],[System.Collections.Generic.List`1[[System.Type, System.Private.CoreLib]], System.Private.CoreLib]][]
00007fa6985150a0        1        23020 System.UInt16[]
00007fa6a01a39e0        1        32792 MS.Internal.Xml.Cache.XPathNode[]
00007fa69db666e0        1        32792 System.Collections.Concurrent.ConcurrentQueue`1+Segment+Slot[[System.Buffers.MemoryPoolBlock, Microsoft.AspNetCore.Server.Kestrel.Transport.Abstractions]][]
00007fa69ccd1778        1        35840 System.Collections.Concurrent.ConcurrentDictionary`2+Node[[System.Int64, System.Private.CoreLib],[Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure.HttpConnectionReference, Microsoft.AspNetCore.Server.Kestrel.Core]][]
00007fa69cbb5ad0        1        35840 UNKNOWN
00007fa6986f9328        1       194312 System.Collections.Generic.HashSet`1+Slot[[System.String, System.Private.CoreLib]][]
00007fa69cbb4ff0        1       196632 UNKNOWN
00007fa696067b40        4       261344 System.Object[]
00007fa69611d910        8       353816 System.Int32[]
00007fa69cbd6be8        1       420480 UNKNOWN
00007fa69611f500        1       420480 System.Collections.Generic.Dictionary`2+Entry[[System.String, System.Private.CoreLib],[System.Object, System.Private.CoreLib]][]
00007fa69810a440        1       524312 System.Collections.Concurrent.ConcurrentQueue`1+Segment+Slot[[System.Threading.IThreadPoolWorkItem, System.Private.CoreLib]][]
00007fa696104d68        1       524312 System.String[]
00007fa6a1b19580       21       688296 UNKNOWN
00007fa6a2244840       36       999264 UNKNOWN
00007fa69fff73d8       14      1182224 UNKNOWN
00007fa69fc2f4e0       25      1940280 UNKNOWN
00007fa69dda3ab0       54      2950416 System.Int16[]
00007fa69632cb10        7      4161704 UNKNOWN
00007fa6961050a0      335     29103136 System.Char[]
00007fa6961014b8     1064     91757068 System.Byte[]
00007fa696100fa0    15422   1358062600 System.String
0000000000c59fa0     8267   1559225242      Free
Total 25269 objects

Not great, but at least I can see that there is a lots of string. Okay, now I'm running

dumpheap -type System.String -min 100

I was awaiting for response for 11 (!) hours and it didn't print a single line. I had to "cancel command at the user's request".
So I actually have at least two problems:

1. dump created with createdump has lots of UNKNOWN types in dump. I've managed to investigate it with dumpobj and I understood some of them, but the others are just "value type array" and I don't know what to do with it: there is nothing like da from a windbg. But maybe it's ok because of symbols since I didn't use --full flag so I don't include it in subject and merely point that this problem exists. Creating full dump solves the problem but dump is very large (21gb vs 1.7gb)
2. I just cannot find what eats the memory. Requests don't get to the end. I'm patient and when I didn't get result immediately I've just left it for the whole night. Now it still didn't print a single line. On 32gb ram modern CPU hardware.

Configuration

• Is this related to a specific tool?
  I'm not sure, container is running 2.1 and I cannot change it due to incompatibilities between aspnetcore 2.1 and 3.1
• What OS and version, and what distro if applicable?
  mcr.microsoft.com/dotnet/core/aspnet:2.1-stretch-slim
• Are you running in any particular type of environment? (e.g. Containers, a cloud scenario, app you are trying to target is a different user)
  Docker
• Is it a self-contained published application?
  no

P.S. I wonder if there is an IM to discuss this kind of matter instead of creating issues since I've got absolutely no reaction in https://gitter.im/dotnet/csharplang and I don't know other places.

[tommcdon]

@mikem8361

[mikem8361]

I've been on vacation and will get back to you on Monday.

[mikem8361]

The UNKNOWN types are because the SOS needs to find/download the managed assemblies to get to the metadata that is missing from the dumps. You can use the setsymbolserver -ms -directory <path> to point the application's assemblies and to enable downloading the system assemblies like System.Private.CoreLib.dll (the -ms part).

[Pzixel]

I don't see UNKNOWN when I'm creating a --full dump. Is it intended to be this way?

And there is still the question about performance issue. I'm not sure how to use a tool which couldn't complete a query in 11 hours. I probably could find a workaround but I find this behavior quite concerning.

[mikem8361]

Yes full dumps should have all the modules but it does make them a lot larger usually.

I can't explain why the dumpheap command took so long to print anything. I'll have to investigate. Is there anyway to upload your coredump?

[Pzixel]

I think I could upload it somewhere, but I'm a bit concerned about privacy issues. If you could suggest a good option I would like to do it.

[Pzixel]

Surprisingly, I cannot reproduce this now. It printed 4 lines of addresses. Now it halted for like 15 minutes, but still, it's something. I'd like to suspend this until I gather more info on the question.

I mean, it's still slow but at least it shows something

---

I can confirm that dumpheap -type System.String -min 100 works more than 1 hour on a 1.7GB dump. If it's enough to affirm that problem exists I can share a dump somehow (Although idk how yet. If I can file a private link in PM somewhere I would like to do it)

[Pzixel]

So yeah. You can see that I started the query in 00:53 at my local time. Now it's 12:14 and query is still executing.

[hoyosjs]

Can you upload the dump to something like OneDrive? If so, feel free to send to juan.hoyos at microsoft.com. If not, we'd need to open a ticket in VS Developer Community, and in a separate message in the thread attach the files with "microsoft only" visibility.

[mikem8361]

One experiment you could try for us is to load this core dump under lldb (see getting-lldb) and run dumpheap. This would narrow down the perf problem to the dumpheap command itself or the dotnet-dump infrastructure.

[mikem8361]

also see: https://github.com/dotnet/diagnostics/blob/master/documentation/debugging-coredump.md

[Pzixel]

@hoyosjs I think I'l take your option. Going to upload and submit it soon.

Best regards guys

[hoyosjs]

I've tried this. It was extremely slow, both LLDB and dotnet-dump. I believe the problem is in the algorithm itself. A quarter of the time was spent getting a metadata provider + building type strings. I will try to take a look if we are properly marking visited objects as well.

[Pzixel]

Hello. Any news about the issue?

[mikem8361]

I haven't had a chance to investigate this. @hoyosjs did you?

[hoyosjs]

@Pzixel I did take a short look at this. It's in part a slow path that the type flag takes. You have a 1.2 GB GC heap (server, over 4 cores). There's a huge amount of 24 byte objects there. I can't see what they are, they seem to be UNKNOWN even though there are plenty of them I have symbols and modules for locally. I can see their tokens and module from their method table, yet SOS can't resolve their symbolic name. @mikem8361 is this expected? Otherwise I'll queue this as something I need to debug.

Anyway, as dumpheap needs to go through every element in the heap and the type flag checks if the type is a substring of the object's type then you get a string comparison per object in the heap. This is extremely expensive as you've seen... I might try building a cache to alleviate this, but I am warry that this might be very memory consuming for large heaps with a lot of different types on the heap - maybe having it behind a flag could help here.

Also quick workaround for this type of scenario where you have a particular type in mind and you don't care for the substring-like behavior of the type flag is this:

• Get the method table for the type from name2ee System.Private.CoreLib.dll System.String. For string in the dump you provided it is 00007f76095406c0
• dumpheap -min 100 -mt 00007f76095406c0. This finishes in under 5 seconds for me.

From the dump you sent I can see a bit of fragmentation all over the place:

• The most frequent object is the FREE object ~215 mb of the heap.
• After that it's a type in atlas models that takes ~94Mb
• After that we have string at ~93 MB. However, your query would've missed these. About ~2mb worth of them are longer that 100 bytes. Of these about ~80 are alive. Most of them are rooted somewhere in Akka.dll

[Pzixel]

You have a 1.2 GB GC heap (server, over 4 cores). There's a huge amount of 24 byte objects there.

I see, although I would never expect 1.2GB heap is huge. I have some colleagues working with Java apps with 1TB+ heap.

Also quick workaround for this type of scenario where you have a particular type in mind and you don't care for the substring-like behavior of the type flag is this

That would defenitely help. Thanks!

From the dump you sent I can see a bit of fragmentation all over the place

I actually found the problem I was looking for in this dump, but thanks for analysis anyway :) I wonder why there is fragmentation, I would expect GC to compact objects.

Anyway, as dumpheap needs to go through every element in the heap and the type flag checks if the type is a substring of the object's type then you get a string comparison per object in the heap. This is extremely expensive as you've seen... I might try building a cache to alleviate this, but I am warry that this might be very memory consuming for large heaps with a lot of different types on the heap - maybe having it behind a flag could help here.

What's about implementing it internally via name2ee or some hack like this? Then it would works really fast. And for type substring you could create another command with caution that it may be slow.

[hoyosjs]

I see, although I would never expect 1.2GB heap is huge. I have some colleagues working with Java apps with 1TB+ heap.

1.2 GB is pretty small but if have a bunch of items that are ~30 bytes, that's ~43 million objects. For each one of those we will need to get metadata. Since it's a minidump, this means 43 million times that we might look for metadata un the modules (I don't believe there's a cache in that code path), build a string, and compare it to the type you provided. Those 43 million will cause that many allocations, and a bunch of string operations and such. As a rule of thumb it's better to use the method tables rather than the type string because of that. The problem is not the size, but rather the number of queries.

That would defenitely help. Thanks!

Glad to hear 😄

I actually found the problem I was looking for in this dump, but thanks for analysis anyway :) I wonder why there is fragmentation, I would expect GC to compact objects.

The GC is pretty lazy. Server GC is particularly careful about pause times, so it will avoid compaction until it starts to experience memory pressure. Most likely 1.2 Gb is far from that unless you are creating pressure with control groups or something similar.

What's about implementing it internally via name2ee or some hack like this? Then it would works really fast. And for type substring you could create another command with caution that it may be slow.

I could definitely add a "Precise name" path, as long as it's fully qualified. It can't be the type flag as it's used, but it's still worth looking at a couple of things here.

[Pzixel]

The GC is pretty lazy. Server GC is particularly careful about pause times, so it will avoid compaction until it starts to experience memory pressure. Most likely 1.2 Gb is far from that unless you are creating pressure with control groups or something similar.

The problem that we experienced OOM with this app. Maybe Linux doesn't inform application about cgroups limits very well.

I could definitely add a "Precise name" path, as long as it's fully qualified. It can't be the type flag as it's used, but it's still worth looking at a couple of things here.

❤️ Since users want to use exact name from dumpheap -stat in most cases it would make perfect sense.

[hoyosjs]

dumpheap -stat gives you the method table too (first column). This tends to be better for name collisions (including same assembly loaded into different contexts). But I'll definitely consider the 'exact type' command.

As for the cgroups, it does respect limits to some extent. A lot of those settings were tuned in netcoreapp3.1 as part of the effort to improved the overall experience in containers (cc: @Maoni0)

[Pzixel]

Yeah, it's a netcoreapp2.1 so this is why it failed. Thanks, I think I'm gonna write a temporary GC.Collect() timer until we migrate to 3.1(5.0?) then :)