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

时间:2022-12-02 18:07:30

一:背景

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,截图如下:

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

这两个蛛丝马迹已经告诉我们当前开启了非常多的线程,可以用 !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 

从卦中看: DBGID 的编号相差无几,说明是大多是托管线程,从后面的 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:\root\NewWF\System.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:\root\NewWF\System.Private.CoreLib.dll
String:      Console logger queue processing thread

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

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

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

4. 从源码中寻找答案

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

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

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

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

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

三: 总结

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

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