Remember a memory leak analysis of a fire Internet of Things background service in .NET

One: Background

1. Storytelling

Last October, a friend found me from WeChat and said that his program memory was about to blow up. . . Screenshot below:

It's been a long time, and the pictures have been cleaned up, but it's a bit ironic that my program itself is doing monitoring, and it turns out that I have a problem, which is too embarrassing 🤣🤣🤣

Two: Windbg analysis

1. Managed or unmanaged

This is the first step to identify memory problems. It can be basically concluded !address -summary and !eeheap -gc

0:000> !address -summary                             
Mapping file section regions...
Mapping module regions...
Mapping PEB regions...
Mapping TEB and stack regions...
Mapping heap regions...
Mapping page heap regions...
Mapping other regions...
Mapping stack trace database regions...
Mapping activation context regions...

--- Usage Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
Free                                    237     7ffc`1e222000 ( 127.985 TB)           99.99%
<unknown>                               594        3`b9b20000 (  14.901 GB)  95.96%    0.01%
Heap                                    370        0`12a2a000 ( 298.164 MB)   1.88%    0.00%
Image                                  1248        0`0ee5a000 ( 238.352 MB)   1.50%    0.00%
Stack                                   315        0`06780000 ( 103.500 MB)   0.65%    0.00%
Other                                    13        0`001d7000 (   1.840 MB)   0.01%    0.00%
TEB                                     105        0`000d2000 ( 840.000 kB)   0.01%    0.00%
PEB                                       1        0`00001000 (   4.000 kB)   0.00%    0.00%

--- Type Summary (for busy) ------ RgnCount ----------- Total Size -------- %ofBusy %ofTotal
MEM_PRIVATE                            1178        3`ce03d000 (  15.219 GB)  98.00%    0.01%
MEM_IMAGE                              1409        0`0f6fd000 ( 246.988 MB)   1.55%    0.00%
MEM_MAPPED                               59        0`04694000 (  70.578 MB)   0.44%    0.00%

--- State Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
MEM_FREE                                237     7ffc`1e222000 ( 127.985 TB)           99.99%
MEM_COMMIT                             2326        3`c7543000 (  15.115 GB)  97.33%    0.01%
MEM_RESERVE                             320        0`1a88b000 ( 424.543 MB)   2.67%    0.00%

0:000> !eeheap -gc
Number of GC Heaps: 1
generation 0 starts at 0x0000009902B57670
generation 1 starts at 0x0000009902A56810
generation 2 starts at 0x00000095318C1000
ephemeral segment allocation context: (0x0000009902D724A8, 0x0000009902D724C0)
         segment             begin         allocated         committed    allocated size    committed size
...
00000098FFBE0000  00000098FFBE1000  0000009902D724A8  0000009902D7D000  0x31914a8(51975336)  0x319c000(52019200)
Large object heap starts at 0x00000095418C1000
         segment             begin         allocated         committed    allocated size    committed size
00000095418C0000  00000095418C1000  00000095475D8D98  00000095475D9000  0x5d17d98(97615256)  0x5d18000(97615872)
Total Allocated Size:              Size: 0x398e6cbc8 (15450164168) bytes.
Total Committed Size:              Size: 0x398e7b000 (15450222592) bytes.
------------------------------
GC Allocated Heap Size:    Size: 0x398e6cbc8 (15450164168) bytes.
GC Committed Heap Size:    Size: 0x398e7b000 (15450222592) bytes.     

Judging from the output information, good guy. . . The memory submitted by the process is 15G , and the managed heap is almost 15G , which means that it is a relatively simple managed memory leak.

2. What exactly is leaking

To know what is leaking, you can go to the managed heap to see if there are any abnormal objects, and use the !dumpheap -stat command.

0:000> !dumpheap -stat
Statistics:
              MT    Count    TotalSize Class Name
...
00007ff8815d0f88  7260233    290409320 System.Collections.ArrayList
00007ff8815e6830  7313696    326240826 System.String
000000952fbbd2b0 12141398    509369998      Free
00007ff880685cf0  7254983    928637824 System.Diagnostics.ProcessInfo
00007ff88065f7d0  7256845   2031916600 System.Diagnostics.Process
00007ff8815e6ea8  7391338   2230744600 System.Object[]
00007ff88068fa70 186800748   8966435904 System.Diagnostics.ThreadInfo

From the perspective of the hexagram, it is really strange. If you know the Process class, you should know that ProcessInfo and ThreadInfo are both hanging under Process , and the ThreadInfo object is as high as 180 million, which is really too 🐂👃 Keep doing Process.Start operations.

The next question to explore ThreadInfo being held? ? ? You can pick a few and look at their !gcroot , check a few first and last, but there is no reference root, as shown below:

0:000> !gcroot 0000009531e8f760
Found 0 unique roots (run '!GCRoot -all' to see all roots).
0:000> !gcroot 0000009531e8f670 
Found 0 unique roots (run '!GCRoot -all' to see all roots).
0:000> !gcroot 0000009531e8f378
Found 0 unique roots (run '!GCRoot -all' to see all roots).

3. Why is the unreferenced root not recycled?

Since the object doesn't have a reference root, why doesn't the GC collect it? I need to talk about experience here. In many memory leaks that I analyzed before, I was looking for problems from the production side of . It seems that there has not been a case of finding problems from the consumer side of . The reference model is as follows:

Since there is no problem with the producer, what can be wrong with the consumer? You can think about it, the consumer side of the managed heap has at least two roles.

1. GC
2. Finalizer thread

GC is definitely not a problem, then you can only suspect Finalizer thread. You can use the !t command to call up all the threads to see.

0:000> !t
ThreadCount:      9566
UnstartedThread:  0
BackgroundThread: 88
PendingThread:    0
DeadThread:       9471
Hosted Runtime:   no
                                                                                                        Lock  
       ID OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception
   0    1 40e18 000000952fbdfe50    26020 Preemptive  0000000000000000:0000000000000000 000000952fbd2e40 0     STA 
   2    2 41ce8 000000952fc0e4d0    2b220 Preemptive  0000000000000000:0000000000000000 000000952fbd2e40 0     MTA (Finalizer) 
   4    4 41cb4 000000954c324970    27220 Preemptive  0000000000000000:0000000000000000 000000952fbd2e40 0     STA 
   5    5 41cb8 000000954c36d1e0  2027220 Preemptive  0000000000000000:0000000000000000 000000952fbd2e40 0     STA 
   6    6 41c58 000000954c33f070  2027220 Preemptive  0000000000000000:0000000000000000 000000952fbd2e40 0     STA 
   7    7 41c38 000000954c33f840    27220 Preemptive  0000000000000000:0000000000000000 000000952fbd2e40 0     STA 
   8    8 41e0c 000000954c333580    27220 Preemptive  0000000000000000:0000000000000000 000000952fbd2e40 0     STA 
   9    9 41e2c 000000954c354440    27220 Preemptive  0000000000000000:0000000000000000 000000952fbd2e40 0     STA 
  10   10 41f24 000000954c355840    27220 Preemptive  0000000000000000:0000000000000000 000000952fbd2e40 0     STA 
...
XXXX 9446    0 000000957a233410  8039820 Preemptive  0000000000000000:0000000000000000 000000952fbd2e40 0     MTA (Threadpool Completion Port) 
XXXX 9447    0 0000009579f83e30  8039820 Preemptive  0000000000000000:0000000000000000 000000952fbd2e40 0     MTA (Threadpool Completion Port) 
XXXX 9450    0 000000957a46dcf0  8039820 Preemptive  0000000000000000:0000000000000000 000000952fbd2e40 0     MTA (Threadpool Completion Port) 
XXXX 9449    0 000000957967c6e0  8039820 Preemptive  0000000000000000:0000000000000000 000000952fbd2e40 0     MTA (Threadpool Completion Port) 
XXXX 9448    0 000000957aee0010  8039820 Preemptive  0000000000000000:0000000000000000 000000952fbd2e40 0     MTA (Threadpool Completion Port) 
XXXX 9452    0 00000095796824a0  8039820 Preemptive  0000000000000000:0000000000000000 000000952fbd2e40 0     MTA (Threadpool Completion Port) 
XXXX 9451    0 000000957af05df0  8039820 Preemptive  0000000000000000:0000000000000000 000000952fbd2e40 0     MTA (Threadpool Completion Port) 

I don’t know if I don’t see it, but I am shocked. There are currently 9566 processes and 9471 dead threads. Based new Thread what is doing, using ~2s & !dumpstack

0:002> ~2s
ntdll!NtWaitForSingleObject+0xa:
00007ff8`8e220c8a c3              ret
0:002> !dumpstack
OS Thread Id: 0x41ce8 (2)
Current frame: ntdll!NtWaitForSingleObject+0xa
Child-SP         RetAddr          Caller, Callee
0000009549e4e120 00007ff88b591118 KERNELBASE!WaitForSingleObjectEx+0x94, calling ntdll!NtWaitForSingleObject
0000009549e4e1c0 00007ff88da3e334 combase!MTAThreadWaitForCall+0x54 [d:\9147\com\combase\dcomrem\channelb.cxx:5657], calling KERNELBASE!WaitForSingleObject
0000009549e4e210 00007ff88d8fe089 combase!MTAThreadDispatchCrossApartmentCall+0x75 [d:\9147\com\combase\dcomrem\chancont.cxx:193], calling combase!MTAThreadWaitForCall [d:\9147\com\combase\dcomrem\channelb.cxx:5619]
0000009549e4e240 00007ff88da3e13d combase!CRpcChannelBuffer::SendReceive2+0x64b [d:\9147\com\combase\dcomrem\channelb.cxx:4796], calling combase!MTAThreadDispatchCrossApartmentCall [d:\9147\com\combase\dcomrem\chancont.cxx:156]
0000009549e4e2b0 00007ff88e1bb6f7 ntdll!RtlAllocateHeap+0xd7, calling ntdll!RtlpLowFragHeapAllocFromContext
...
0000009549e4f5d0 00007ff8827d79cd clr!ManagedThreadBase_DispatchOuter+0x75, calling clr!ManagedThreadBase_DispatchMiddle
0000009549e4f5e0 00007ff8828601af clr!EEConfig::GetConfigDWORD_DontUse_+0x3b, calling clr!EEConfig::GetConfiguration_DontUse_
0000009549e4f660 00007ff8828574fa clr!FinalizerThread::FinalizerThreadStart+0x10a, calling clr!ManagedThreadBase_DispatchOuter
0000009549e4f6a0 00007ff8827d55b9 clr!EEHeapFreeInProcessHeap+0x45, calling kernel32!HeapFreeStub
0000009549e4f700 00007ff882882e8f clr!Thread::intermediateThreadProc+0x86
0000009549e4f780 00007ff882882e6f clr!Thread::intermediateThreadProc+0x66, calling clr!_chkstk
0000009549e4f7c0 00007ff88dcd13d2 kernel32!BaseThreadInitThunk+0x22
0000009549e4f7f0 00007ff88e2003c4 ntdll!RtlUserThreadStart+0x34

Information from the stack to see the original thread stuck the end, from MTAThreadDispatchCrossApartmentCall see approach looks like MTA to STA made a call here an experienced friend should know that this com component and a relationship, and that is Finalizer The thread cannot release the COM object created by the STA thread, so which thread created the COM component that was not properly released?

4. Find the thread that created the COM component

To be honest, if you don't know COM components, it's hard to find the answer, but there is no way out. When I look back at the thread list, I find that there are actually 38 STA threads. The screenshots are as follows:

There must be a problem here. Next, draw a thread to see how the call stack looks like.

0:004> !clrstack 
OS Thread Id: 0x41cb4 (4)
        Child SP               IP Call Site
000000954da1ee38 00007ff88e220c8a [HelperMethodFrame: 000000954da1ee38] System.Threading.Thread.SleepInternal(Int32)
000000954da1ef30 00007ff88138c20a *** WARNING: Unable to verify checksum for mscorlib.ni.dll
System.Threading.Thread.Sleep(Int32)
000000954da1ef60 00007ff82322437f xxx.CFileLogTask.DoWork()
000000954da1f160 00007ff8232234d6 xxx.CTask.InitStart()
000000954da1f240 00007ff8813c31d3 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000954da1f310 00007ff8813c3064 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000954da1f340 00007ff8813c3032 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
000000954da1f390 00007ff8813bc812 System.Threading.ThreadHelper.ThreadStart()
000000954da1f5e8 00007ff8827d6bb3 [GCFrame: 000000954da1f5e8] 
000000954da1f938 00007ff8827d6bb3 [DebuggerU2MCatchHandlerFrame: 000000954da1f938] 

Next, decompile the xxx.CFileLogTask.DoWork() method to see how it is executed by Thread.

CurrThread.SetApartmentState(ApartmentState.STA); to the bottom of it here. The culprit is in the sentence 061e4cdad22ceb. I don't know why I need to give a STA when I open a thread. . .

Three: Summary

This accident is mainly because the COM component was used on the STA thread, which caused the Finalizer thread of the MTA model to be stuck when it was released, and this thread did not use Application.Run start the message loop, and the STA is also in the Sleep state. I personally feel that both Unable to communicate, the suggestion to my friends is to remove the STA of Thread.

In fact, a good point here is that when the memory skyrockets, it is not necessarily production end , but also the consumer end .