记一次 .NET 某电子厂OA系统 非托管内存泄露分析

一：背景

1.讲故事

这周有个朋友找到我，说他的程序出现了内存缓慢增长，没有回头的趋势，让我帮忙看下到底怎么回事，据朋友说这个问题已经困扰他快一周了，还是没能找到最终的问题，看样子这个问题比较刁钻，不管怎么说，先祭出 WinDbg。

二：WinDbg 分析

1. 托管还是非托管泄露

一直关注这个系列的朋友都知道，托管和非托管的排查是两个体系，分析方式完全不一样，所以要鉴定是哪一块的内存问题，首先要用 !address -summary 观察进程的 虚拟内存 布局。

 0:000> !address -summary  --- Usage Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal Free                                    710     7d93`20465000 ( 125.575 TB)           98.11% <unknown>                              7547      240`9bea8000 (   2.252 TB)  92.87%    1.76% Stack                                 33363       2c`1fae0000 ( 176.495 GB)   7.11%    0.13% Heap                                   1179        0`126d3000 ( 294.824 MB)   0.01%    0.00% Image                                  2988        0`0c274000 ( 194.453 MB)   0.01%    0.00% TEB                                   11121        0`056e2000 (  86.883 MB)   0.00%    0.00% Other                                    11        0`001d9000 (   1.848 MB)   0.00%    0.00% PEB                                       1        0`00001000 (   4.000 kB)   0.00%    0.00%  --- Type Summary (for busy) ------ RgnCount ----------- Total Size -------- %ofBusy %ofTotal MEM_MAPPED                             7302      200`071b1000 (   2.000 TB)  82.47%    1.56% MEM_PRIVATE                           45920       6c`cc766000 ( 435.195 GB)  17.52%    0.33% MEM_IMAGE                              2988        0`0c274000 ( 194.453 MB)   0.01%    0.00%  --- State Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal MEM_FREE                                710     7d93`20465000 ( 125.575 TB)           98.11% MEM_RESERVE                           12136      26c`84ccf000 (   2.424 TB)  99.94%    1.89% MEM_COMMIT                            44074        0`5aebc000 (   1.421 GB)   0.06%    0.00%  

从卦中看，当前进程的提交内存是 MEM_COMMIT= 1.4G， NT堆的内存占用是 Heap=294M，乍一看应该是托管内存泄露，接下来用 !eeheap -gc 观察托管堆。

 0:000> !eeheap -gc Number of GC Heaps: 12 ------------------------------ Heap 0 (0000028577D73020) generation 0 starts at 0x00000285B7000020 generation 1 starts at 0x00000285B6C00020 generation 2 starts at 0x0000028590800020 ephemeral segment allocation context: none ... ------------------------------ GC Allocated Heap Size:    Size: 0x9598958 (156862808) bytes. GC Committed Heap Size:    Size: 0xea1c7e0 (245483488) bytes.  

从卦中看很奇怪，托管堆也就 GC Committed Heap Size= 245M 的内存占用，说明问题不在托管堆上。

2. 到底是哪里的泄露

这就是本篇文章的亮点之处，毕竟没有按照以前的套路出牌，接下来问题在哪里呢？ 还是得回头看下 虚拟内存布局，终于你会发现 Stack 处很奇怪，内存占用高达 TotalSize =176G， 内存段高达 RgnCount=3.3w，截图如下：

这两个蛛丝马迹已经告诉我们当前开启了非常多的线程，可以用 !address: -f:Stack 观察线程数和线程栈信息。

 0:000> !address -f:Stack          BaseAddress      EndAddress+1        RegionSize     Type       State                 Protect             Usage --------------------------------------------------------------------------------------------------------------------------       c0`80000000       c0`8104b000        0`0104b000 MEM_PRIVATE MEM_RESERVE                                    Stack      [~139; 323a8.320a4]       c0`8104b000       c0`8104e000        0`00003000 MEM_PRIVATE MEM_COMMIT  PAGE_READWRITE | PAGE_GUARD        Stack      [~139; 323a8.320a4]       c0`8104e000       c0`81050000        0`00002000 MEM_PRIVATE MEM_COMMIT  PAGE_READWRITE                     Stack      [~139; 323a8.320a4]       c0`81050000       c0`8209b000        0`0104b000 MEM_PRIVATE MEM_RESERVE                                    Stack      [~140; 323a8.316b8]       c0`8209b000       c0`8209e000        0`00003000 MEM_PRIVATE MEM_COMMIT  PAGE_READWRITE | PAGE_GUARD        Stack      [~140; 323a8.316b8]       c0`8209e000       c0`820a0000        0`00002000 MEM_PRIVATE MEM_COMMIT  PAGE_READWRITE                     Stack      [~140; 323a8.316b8]       ...       ed`460d0000       ed`4711b000        0`0104b000 MEM_PRIVATE MEM_RESERVE                                    Stack      [~11119; 323a8.8b20]       ed`4711b000       ed`4711e000        0`00003000 MEM_PRIVATE MEM_COMMIT  PAGE_READWRITE | PAGE_GUARD        Stack      [~11119; 323a8.8b20]       ed`4711e000       ed`47120000        0`00002000 MEM_PRIVATE MEM_COMMIT  PAGE_READWRITE                     Stack      [~11119; 323a8.8b20]       ed`47120000       ed`4816b000        0`0104b000 MEM_PRIVATE MEM_RESERVE                                    Stack      [~11120; 323a8.9828]       ed`4816b000       ed`4816e000        0`00003000 MEM_PRIVATE MEM_COMMIT  PAGE_READWRITE | PAGE_GUARD        Stack      [~11120; 323a8.9828]       ed`4816e000       ed`48170000        0`00002000 MEM_PRIVATE MEM_COMMIT  PAGE_READWRITE                     Stack      [~11120; 323a8.9828]  

从卦中看，当前线程高达 1.1w 个，有点吓人，终于算是找到源头了，

3. 为什么会有 1w+ 的线程

接下来就需要鉴定下这些线程是托管线程还是非托管线程，可以用 !t 观察。

 0:000> !t ThreadCount:      11104 UnstartedThread:  0 BackgroundThread: 11099 PendingThread:    0 DeadThread:       4 Hosted Runtime:   no                                                                                                             Lock    DBG   ID     OSID ThreadOBJ           State GC Mode     GC Alloc Context                  Domain           Count Apt Exception   20    1    32588 0000028577D0DB30  202a020 Preemptive  0000000000000000:0000000000000000 0000028577529fc0 -00001 MTA    35    2    3262c 0000028577F3D000    2b220 Preemptive  00000285C0002660:00000285C0004008 0000028577529fc0 -00001 MTA (Finalizer)    36    4    326b4 0000028577F941B0  102b220 Preemptive  0000000000000000:0000000000000000 0000028577529fc0 -00001 MTA (Threadpool Worker)    37    5    31848 000002857811A420  202b220 Preemptive  0000000000000000:0000000000000000 0000028577529fc0 -00001 MTA    ... 11116 11100     966c 000002C620A45300  202b220 Preemptive  00000285C86CB910:00000285C86CD868 0000028577529fc0 -00001 MTA  11117 11101     95b4 000002C61B928970  202b220 Preemptive  00000285996DF978:00000285996E18D0 0000028577529fc0 -00001 MTA  11118 11102     9630 000002C61B928FC0  202b220 Preemptive  00000285996E1978:00000285996E38D0 0000028577529fc0 -00001 MTA  11119 11103     8b20 000002C620A465F0  202b220 Preemptive  00000285B46B15C0:00000285B46B3518 0000028577529fc0 -00001 MTA  11120 11104     9828 000002C61E014CB0  202b220 Preemptive  00000285C86CD910:00000285C86CF868 0000028577529fc0 -00001 MTA   

从卦中看： DBG 和 ID 的编号相差无几，说明是大多是托管线程，从后面的 MTA 来看，这是一个 new Thread 出来的线程，接下来试探看下它有没有 Name，我们拿 ThreadOBJ=000002C61E014CB0 来看吧。

 0:000> dt coreclr!Thread 000002C61E014CB0    ...    +0x1c0 m_ExposedObject  : 0x00000285`7821d160 OBJECTHANDLE__    ...  0:000> !do poi(0x00000285`7821d160) Name:        System.Threading.Thread MethodTable: 00007ffa63844320 EEClass:     00007ffa6379af48 Tracked Type: false Size:        72(0x48) bytes File:        D:rootNewWFSystem.Private.CoreLib.dll Fields:               MT    Field   Offset                 Type VT     Attr            Value Name 00007ffa63a0d608  4000b0d        8 ....ExecutionContext  0 instance 00000285c0acf930 _executionContext 00007ffa64cbaa78  4000b0e       10 ...ronizationContext  0 instance 0000000000000000 _synchronizationContext 00007ffa637afd00  4000b0f       18        System.String  0 instance 0000028590888a78 _name  0:000> !DumpObj /d 0000028590888a78 Name:        System.String MethodTable: 00007ffa637afd00 EEClass:     00007ffa6379a6e0 Tracked Type: false Size:        98(0x62) bytes File:        D:rootNewWFSystem.Private.CoreLib.dll String:      Console logger queue processing thread  

经过抽检，发现线程名都是 Console logger queue processing thread，看样子和日志有关系，接下来使用 ~*e !clrstack 查看当前所有线程，发现线程都卡在 ConsoleLoggerProcessor.TryDequeue 上，截图如下：

看样子和微软的控制台日志组件有关系，下一步就要观察源码。

4. 从源码中寻找答案

导出源码后，利用 ILSpy 的代码回溯功能，发现是 ConsoleLoggerProcessor 类的构造函数 new 出来的线程，截图如下：

结合海量的重复线程栈，大概可以猜测到是代码将 Singleton 的模式改成了 Transient，导致不断的 new，不断的产生新的 Thread 去处理队列。

接下来我也懒得细究代码了，让朋友重点看一下 Microsoft.Extensions.Logging.Console 组件，朋友也很给力，终于找到了是 AppService 类在不断的 new 造成的，截图如下：

三： 总结

这次事故如果朋友有专业的 APM 监控，相信很快就能发现 Thread 爆高的问题，从 dump 中用内存来反推线程爆高，确实有一点出乎意料。

这个 dump 的教训是：理解 Singleton 和 Transient 的利弊，尽量遵循官方文档的写法吧。