一:背景 1. 講故事 前些天有位朋友微信找到我,說他們的WPF程式有記憶體泄漏的情況,讓我幫忙看下怎麼回事?並且dump也抓到了,網上關於程式記憶體泄漏,記憶體暴漲的文章不計其數,看樣子這個dump不是很好分析,不管怎麼說,上 windbg 說話。 二:WinDbg分析 1. 記憶體真的暴漲嗎 在.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 上找到了尋找真相的突破口。