记一次 .NET某管理局检测系统 内存暴涨分析
一：背景
1. 讲故事
前些天有位朋友微信找到我，说他们的WPF程序有内存泄漏的情况，让我帮忙看下怎么回事？并且dump也抓到了，网上关于程序内存泄漏，内存暴涨的文章不计其数，看样子这个dump不是很好分析，不管怎么说，上 windbg 说话。
二：WinDbg分析
1. 内存真的暴涨吗
在.NET调试训练营中我一直强调要相信数据，不要相信别人的一面之词，往往会把你带到沟里去，接下来使用 !address -summary 观察下提交内存。
0:000> !address -summary
--- Usage Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
Free 586 7dfd`f04e3000 ( 125.992 TB) 98.43%
<unknown> 1390 201`5a9bc000 ( 2.005 TB) 99.86% 1.57%
Heap 3989 0`7695c000 ( 1.853 GB) 0.09% 0.00%
Image 1744 0`2077d000 ( 519.488 MB) 0.02% 0.00%
Stack 957 0`1dc00000 ( 476.000 MB) 0.02% 0.00%
TEB 319 0`0027e000 ( 2.492 MB) 0.00% 0.00%
Other 61 0`001f9000 ( 1.973 MB) 0.00% 0.00%
PEB 1 0`00001000 ( 4.000 kB) 0.00% 0.00%
...
--- State Summary ---------------- RgnCount ----------- Total Size -------- %ofBusy %ofTotal
MEM_FREE 586 7dfd`f04e3000 ( 125.992 TB) 98.43%
MEM_RESERVE 2028 201`46def000 ( 2.005 TB) 99.85% 1.57%
MEM_COMMIT 6433 0`c8d1e000 ( 3.138 GB) 0.15% 0.00%
...
从卦中可知当前的提交内存是 3.1G，对于一个窗体程序来说这个内存量算是比较大了，接下来使用 !eeheap -gc 观察下托管堆内存。
0:000> !eeheap -gc
========================================
Number of GC Heaps: 1
----------------------------------------
generation 0 starts at 1b368e4de10
generation 1 starts at 1b3687ea4f0
generation 2 starts at 1b300001000
ephemeral segment allocation context: none
Small object heap
segment begin allocated committed allocated size committed size
01b300000000 01b300001000 01b30fffff88 01b310000000 0xfffef88 (268431240) 0x10000000 (268435456)
01b35dc70000 01b35dc71000 01b368e8fe28 01b369995000 0xb21ee28 (186773032) 0xbd25000 (198332416)
Large object heap starts at 1b310001000
segment begin allocated committed allocated size committed size
01b310000000 01b310001000 01b316d40560 01b316d41000 0x6d3f560 (114554208) 0x6d41000 (114561024)
01b3cfc50000 01b3cfc51000 01b3d6588320 01b3d6589000 0x6937320 (110326560) 0x6939000 (110333952)
Pinned object heap starts at 1b318001000
segment begin allocated committed allocated size committed size
01b318000000 01b318001000 01b3180812d0 01b318082000 0x802d0 (525008) 0x82000 (532480)
------------------------------
GC Allocated Heap Size: Size: 0x28914900 (680610048) bytes.
GC Committed Heap Size: Size: 0x29421000 (692195328) bytes.
从卦中数据看，当前的托管堆也才 692M，和当前的 3G 相差甚远，这就说明这个程序出现了比较麻烦的 非托管内存泄漏，接下来回头看下内存地址段发现 Heap=1.8G ，有了这个数据后用 !heap -s 观察下地址段。
0:000> !heap -s
************************************************************************************************************************
NT HEAP STATS BELOW
************************************************************************************************************************
LFH Key : 0x3861e2c156213079
Termination on corruption : ENABLED
Heap Flags Reserv Commit Virt Free List UCR Virt Lock Fast
(k) (k) (k) (k) length blocks cont. heap
-------------------------------------------------------------------------------------
000001b37a6b0000 00000002 194824 183768 194432 29846 1716 20 30 6fa1 LFH
External fragmentation 16 % (1716 free blocks)
000001b37a4e0000 00008000 64 8 64 6 1 1 0 0
000001b37c140000 00001002 3516 2492 3124 476 69 3 0 0 LFH
External fragmentation 19 % (69 free blocks)
000001b37c380000 00001002 60 36 60 8 3 1 0 0
000001b37c360000 00041002 60 8 60 5 1 1 0 0
000001b37d510000 00001002 1472 88 1080 38 7 2 0 0 LFH
000001b320a10000 00001002 1472 204 1080 71 12 2 0 0 LFH
000001b327a60000 00001002 452 32 60 4 3 1 0 0 LFH
000001b3292b0000 00001002 1513284 1215876 1512892 74984 6445 924 4 2e72c3 LFH
Virtual address fragmentation 19 % (924 uncommited ranges)
Lock contention 3044035
000001b327e80000 00001002 1472 812 1080 439 11 2 0 2 LFH
000001b327cb0000 00001002 3516 1140 3124 519 12 3 0 0 LFH
External fragmentation 45 % (12 free blocks)
000001b327ec0000 00001002 1472 824 1080 468 10 2 0 0 LFH
000001b327cc0000 00001002 1472 1012 1080 441 11 2 0 0 LFH
-------------------------------------------------------------------------------------
从卦中数据看当前的内存都被 Heap=000001b3292b0000 这个私有heap给吃掉了，看样子是某个程序为了某个目的单独分配的，由于没有开启 ust ，这里就没法进行下去了，接下来陷入了迷茫。
2. 在绝望中寻找希望
没有开启ust是不是就没有突破口了呢？大多情况下是的，但作为调试师，需要具备在 绝望中寻找希望 的能力，再回头看地址段，发现 TEB=319，也就说当前程序有 319 个线程，对于一个窗体程序来说这么多线程很明显是一个异常信号，那这个就是突破口，先用 !tp 观察下托管线程列表。
从卦中数据看基本都是线程池的工作线程，为什么会开启这么多线程呢？第一个反应就是线程是不是卡住了？马上用 !syncblk 命令做下验证。
0:000> !syncblk
Index SyncBlock MonitorHeld Recursion Owning Thread Info SyncBlock Owner
2363 000001B3984D6928 381 1 000001B335581A80 607c 135 000001b35e3a0d98 System.Object
-----------------------------
Total 2410
CCW 301
RCW 126
ComClassFactory 1
Free 1783
我去。。。卦中的数据又让我看到了希望！原来有190 个线程卡在 System.Object 锁上，赶紧找个线程观察下线程栈，为了隐私我就多隐藏一点。
0:263> ~~[5a2c]s
ntdll!NtWaitForMultipleObjects+0x14:
00007fff`c800fec4 c3 ret
0:292> !clrstack
OS Thread Id: 0x5a2c (292)
Child SP IP Call Site
0000002E98DFEB48 00007fffc800fec4 [HelperMethodFrame_1OBJ: 0000002e98dfeb48] System.Threading.Monitor.ReliableEnter(System.Object, Boolean ByRef)
0000002E98DFECA0 00007fff12dd2ca3 xxx.SqliteHelper.Insert[[System.__Canon, System.Private.CoreLib]](System.__Canon, System.String ByRef)
...
0000002E98DFF220 00007fff136902b6 System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef, System.Threading.Thread)
0000002E98DFF2D0 00007fff12d1a12b System.Threading.ThreadPoolWorkQueue.Dispatch()
0000002E98DFF360 00007fff136de091 System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart()
0000002E98DFF6B0 00007fff7115aed3 [DebuggerU2MCatchHandlerFrame: 0000002e98dff6b0]
从卦中可以看到当前卡在 SqliteHelper.Insert 方法上，这到底是何方神圣？赶紧看一下代码。
用 Task.Run 去跑一个异步逻辑，是一个编程大坑，一旦这个 Task.Run 运行比较慢或者前端请求比较大，很容易造成线程饥饿，从这个程序中的 SetBlob 方法来看，就是将 byte[] 丢到 SqlLite 里，所以这个非托管内存泄漏其实是 Sqlite 在非托管层持有的数据。
挖到了根子上的原因之后，解决办法就比较简单了。
- 尽量的批量化Insert，不要用 foreach 一条一条的 Insert
- 用单独线程队列化处理，不要用偷懒式 Task.Run
三：总结
这次分析之旅是典型的 在绝望中寻找希望，调试者需要具备沉着冷静的心态，坚持不放弃最终在 内存段 的 TEB 上找到了寻找真相的突破口。
