一：背景
1. 講故事
上個月底，有位朋友微信找到我，說他的程式 多執行緒處理 RabbitMQ 時過慢，幫忙分析下什麼原因，截圖如下：
這問題丟擲來，有點懵逼，沒說CPU爆高，也沒說記憶體洩漏，也沒說程式卡死。。。鬼知道為啥 Rabbitmq 處理過慢哈??? 。
既然沒有一個緣由，那就往 freeze 這個方向去找吧，上 windbg 說話。
二：Windbg 分析
1. 尋找 freeze 原因
處理過慢原因有很多，可能是幹活的人少了，也可能這些人摸魚去了，總之工作不飽和，接下來看看這幫人有沒有摸魚，從 執行緒池 看起。
0:000> !tp
CPU utilization: 81%
Worker Thread: Total: 187 Running: 172 Idle: 0 MaxLimit: 32767 MinLimit: 8
Work Request in Queue: 0
--------------------------------------
Number of Timers: 0
--------------------------------------
Completion Port Thread:Total: 1 Free: 1 MaxFree: 16 CurrentLimit: 1 MaxLimit: 1000 MinLimit: 8
從輸出中看，當前的 CPU=81%， 大概率是這個程式引起的，既然 CPU 過高，可能是某些計算密集型操作，可能是大量鎖導致的上下文切換，也可能是 GC 頻繁觸發所致。
2. 是 GC 觸發嗎？
本系列到這裡，我相信有很多朋友應該知道如何從執行緒棧上看是否為 GC 觸發所致，用命令 ~*e !dumpstack 經過一通尋找，發現是 214 號執行緒觸發了 GC，如下圖所示：
用 !dumpstack 輸出的資訊太多，為了讓資訊更加簡化，改用 !clrstack。
0:214> !clrstack
OS Thread Id: 0x290c (214)
Child SP IP Call Site
000000bb2983c7d0 00007ffed8c3e335 System.Text.UTF8Encoding.GetString(Byte[], Int32, Int32)
000000bb2983c810 00007ffe7aaecee9 StackExchange.Redis.RedisValue.op_Implicit(StackExchange.Redis.RedisValue)
000000bb2983c860 00007ffe7aaecd92 xxxx.Util.Helper.RedisHelper.ConvertObj[[System.__Canon, mscorlib]](StackExchange.Redis.RedisValue)
000000bb2983c8f0 00007ffe7abc3997 xxxx.Util.Helper.RedisHelper+c__DisplayClass29_0`1[[System.__Canon, mscorlib]].b__0(StackExchange.Redis.IDatabase)
000000bb2983ca20 00007ffe7aaeaca0 xxxx.Util.Helper.RedisHelper.Do[[System.__Canon, mscorlib]](System.Func`2<StackExchange.Redis.IDatabase,System.__Canon>)
000000bb2983caa0 00007ffe7abc3762 xxxx.Util.Helper.RedisHelper.HashGet[[System.__Canon, mscorlib]](System.String, System.String)
000000bb2983cb40 00007ffe7abc2f3d xxxx.Implementation.xxx.GetCompany(System.String)
...
000000bb2983e170 00007ffe7ad2fadf xxx.xxx.MQ.xxx+c__DisplayClass21_0`1[[System.__Canon, mscorlib]].b__1()
000000bb2983e1c0 00007ffed8c11862 System.Threading.Tasks.Task`1[[System.__Canon, mscorlib]].InnerInvoke()
000000bb2983e220 00007ffed8c10937 System.Threading.Tasks.Task.Execute()
000000bb2983e260 00007ffed8bc674e System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000bb2983e330 00007ffed8bc65e7 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000bb2983e360 00007ffed8c10bdd System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef)
000000bb2983e410 00007ffed8c10303 System.Threading.Tasks.Task.ExecuteEntry(Boolean)
000000bb2983e450 00007ffed8bcfa10 System.Threading.ThreadPoolWorkQueue.Dispatch()
000000bb2983e8e8 00007ffed9d465d3 [DebuggerU2MCatchHandlerFrame: 000000bb2983e8e8]
從卦中資訊看，程式在 RedisHelper.HashGet 操作的過程中觸發了 GC，我去，難道是從 redis 中讀了什麼大資料？接下來用 !clrstack -a 看看到底從redis中讀了個啥？
0:214> !clrstack -a
OS Thread Id: 0x290c (214)
Child SP IP Call Site
000000bb2983c860 00007ffe7aaecd92 xxx.Util.Helper.RedisHelper.ConvertObj[[System.__Canon, mscorlib]](StackExchange.Redis.RedisValue)
PARAMETERS:
this (0x000000bb2983c8f0) = 0x000000bb182da3d0
value (0x000000bb2983c960) = 0x000000bb18440778
LOCALS:
0x000000bb2983c8c4 = 0x0000000000000000
0x000000bb2983c8a0 = 0x0000000000000000
0x000000bb2983c898 = 0x0000000000000000
0:214> !do 0x000000bb18440778
Name: System.Byte[]
MethodTable: 00007ffed8db93d0
EEClass: 00007ffed87f4dc8
Size: 6679(0x1a17) bytes
Array: Rank 1, Number of elements 6655, Type Byte (Print Array)
Content: {"ID":104x,"Code":"130x","xxx":"1304","xxx":"8888","Name":"...............","xxx":"...............","MqConnStr"
可以看到，redis 讀了大概 6.6 k 的資料，才這麼點資料，我還以為 幾十M 呢 ???， 要說這點東西就能觸發GC，我是不相信的 。
3. 到底是什麼誘使了 GC 觸發 ？
那這個 罪魁禍首 到底是誰呢？ 其實仔細想一想，GC觸發無非就是將物件從 gen0 推到 gen1，然後由 gen1 推到 gen2，那朋友的這個 RabbitMQ 處理慢，肯定是觸發了多次GC，才有了這個肉眼可見的處理慢。
這裡就有一個突破點，既然觸發多次GC，那gen2上肯定有很多帶根的物件，所以從這裡入手比較好，用 !dumpgen 命令檢視。
0:214> !dumpgen 2 -stat
Count Total Size Type
-------------------------------------------------
87,738 24,925,316 System.Int32[]
509,643 56,399,716 System.String
83,077 65,760,888 System.Reflection.Emit.__FixupData[]
2,158,346 69,067,072 System.Reflection.Emit.GenericMethodInfo
92,388 172,765,392 System.Object[]
796,870 179,587,796 **** FREE ****
14,030,441 336,730,584 System.RuntimeMethodHandle
428,376 348,743,274 System.Byte[]
我去，gen2 上居然有 1.4 kw 的物件，這太讓人好奇了，接下來隨便抽幾個 address ，看看它的引用根是個啥？
0:214> !dumpgen 2 -type System.RuntimeMethodHandle
Object MT Size Name
-------------------------------------------------------------------
000000bac9f8fe68 00007FFED8DB9978 24 System.RuntimeMethodHandle
000000bac9f8fe80 00007FFED8DB9978 24 System.RuntimeMethodHandle
000000bac9f8fe98 00007FFED8DB9978 24 System.RuntimeMethodHandle
000000bac9f8feb0 00007FFED8DB9978 24 System.RuntimeMethodHandle
000000bac9f8fec8 00007FFED8DB9978 24 System.RuntimeMethodHandle
...
000000baca1af510 00007FFED8DB9978 24 System.RuntimeMethodHandle
000000baca1af548 00007FFED8DB9978 24 System.RuntimeMethodHandle
000000baca1af560 00007FFED8DB9978 24 System.RuntimeMethodHandle
000000baca1afd90 00007FFED8DB9978 24 System.RuntimeMethodHandle
000000baca1afde0 00007FFED8DB9978 24 System.RuntimeMethodHandle
0:214> !gcroot 000000baca1afde0
Thread 187c0:
000000baeeb5cb30 00007ffed8ba9c60 System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].FindEntry(System.__Canon)
rsi:
-> 000000baca4c6ef0 System.Collections.Generic.Dictionary`2[[System.Tuple`4[[System.String, mscorlib],[System.String, mscorlib],[System.Int32, mscorlib],[System.Int32, mscorlib]], mscorlib],[System.Delegate, mscorlib]]
-> 000000badab3b8a0 System.Collections.Generic.Dictionary`2+Entry[[System.Tuple`4[[System.String, mscorlib],[System.String, mscorlib],[System.Int32, mscorlib],[System.Int32, mscorlib]], mscorlib],[System.Delegate, mscorlib]][]
-> 000000baca1b5210 System.Func`2[[System.Data.IDataReader, System.Data],[xxx.BAR_AccountDC, xxxx]]
-> 000000baca1ae8b0 System.Reflection.Emit.DynamicMethod+RTDynamicMethod
-> 000000baca1ae7f8 System.Reflection.Emit.DynamicMethod
-> 000000baca1b51b0 System.RuntimeMethodInfoStub
-> 000000baca1b4a18 System.Reflection.Emit.DynamicResolver
-> 000000baca1aea60 System.Reflection.Emit.DynamicScope
-> 000000baca1aea78 System.Collections.Generic.List`1[[System.Object, mscorlib]]
-> 000000baca1b3b20 System.Object[]
-> 000000baca1afde0 System.RuntimeMethodHandle
從引用鏈看，它是被 Dictionary 所持有，那我們就 dump 一下這個 dictionary，看看是個啥。
0:214> !do 000000baca4c6ef0
Name: System.Collections.Generic.Dictionary`2[[System.Tuple`4[[System.String, mscorlib],[System.String, mscorlib],[System.Int32, mscorlib],[System.Int32, mscorlib]], mscorlib],[System.Delegate, mscorlib]]
MethodTable: 00007ffe7a937f18
EEClass: 00007ffed87f7cb8
Size: 80(0x50) bytes
File: C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll
Fields:
MT Field Offset Type VT Attr Value Name
00007ffed8dc3e30 400182a 8 System.Int32[] 0 instance 000000badaaa2c10 buckets
00007ffed9874d38 400182b 10 ...non, mscorlib]][] 0 instance 000000badab3b8a0 entries
00007ffed8dc3e98 400182c 38 System.Int32 1 instance 83000 count
00007ffed8dc3e98 400182d 3c System.Int32 1 instance 83000 version
00007ffed8dc3e98 400182e 40 System.Int32 1 instance -1 freeList
00007ffed8dc3e98 400182f 44 System.Int32 1 instance 0 freeCount
00007ffed8d9a430 4001830 18 ...Canon, mscorlib]] 0 instance 000000baca2ec958 comparer
00007ffed8d9c550 4001831 20 ...Canon, mscorlib]] 0 instance 0000000000000000 keys
00007ffed8dcef28 4001832 28 ...Canon, mscorlib]] 0 instance 0000000000000000 values
00007ffed8dc1c98 4001833 30 System.Object 0 instance 0000000000000000 _syncRoot
0:214> !objsize 000000baca4c6ef0
sizeof(000000baca4c6ef0) = 1116325152 (0x4289c520) bytes (System.Collections.Generic.Dictionary`2[[System.Tuple`4[[System.String, mscorlib],[System.String, mscorlib],[System.Int32, mscorlib],[System.Int32, mscorlib]], mscorlib],[System.Delegate, mscorlib]])
可以看到，當前dict 的 size= 8.3w，總大小為 1.1G, 然後用 !mdt 抽查一下字典內容。
可以看出，字典中的item大概都是 key= select * from xxx where AccountNo= xxxx， value = Func ，
4. 檢視原始碼
從 !gcroot 中知道當前根在 187c0 號執行緒，然後我們通過執行緒棧去尋找下原始碼。
0:089> ~~[187c0]s
ntdll!NtWaitForSingleObject+0xa:
00007ffe`e9ea06fa c3 ret
0:089> !clrstack
OS Thread Id: 0x187c0 (89)
Child SP IP Call Site
000000baeeb5caa0 00007ffed9718dfe System.Tuple`4[[System.__Canon, mscorlib],[System.__Canon, mscorlib],[System.Int32, mscorlib],[System.Int32, mscorlib]].System.Collections.IStructuralEquatable.GetHashCode(System.Collections.IEqualityComparer)
000000baeeb5cb00 00007ffed8ba90a7 System.Collections.Generic.ObjectEqualityComparer`1[[System.__Canon, mscorlib]].GetHashCode(System.__Canon)
000000baeeb5cb30 00007ffed8ba9c60 System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].FindEntry(System.__Canon)
000000baeeb5cba0 00007ffed8bc53a4 System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].TryGetValue(System.__Canon, System.__Canon ByRef)
000000baeeb5cbe0 00007ffe7abd8069 xxx.Internal.Cache`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].Get(System.__Canon, System.Func`1<System.__Canon>)
000000baeeb5cc50 00007ffe7abd6d52 xxx.Database+d__49`1[[System.__Canon, mscorlib]].MoveNext()
000000baeeb5ccd0 00007ffed733768e System.Linq.Enumerable.FirstOrDefault[[System.__Canon, mscorlib]](System.Collections.Generic.IEnumerable`1<System.__Canon>)
000000baeeb5cd40 00007ffe7af5489e xxx.xxx.ParsePapPayDebitRecord(xxx, xxx.BAR_AccountDC ByRef, System.String ByRef, xxx ByRef, Boolean, xxx, Boolean)
...
從執行緒棧看,程式做了一個 db 查詢的操作，原始碼大概如下：
public static InvalidTxnCode ParsePapPayDebitRecord(xxx)
{
sql = "select * FROM [dbo].[xxx] where AccountNO = '" + transRecord.AccountNO + "'";
IEnumerable<BAR_AccountDC> enumerable3 = new YiBll<BAR_AccountDC>(transRecord.AccountNO).QuerySql(sql);
}
問題就出現在這個 sql 拼接上，底層的框架為了提高 mapping 速度，將 sql 和與之對應的 Func<DataReader,Data> 做了快取處理，由於每次sql都不一樣，這就導致底層的 dict越來越大，直到目前的 1.1 G。
三：總結
總的來說，本次事故是由於不斷增長的 dict 在不斷的擠壓小物件堆，加之程式多執行緒火力全開分配物件導致gc在小物件堆上的頻繁回收造成的 rabbitmq 處理過慢。
修改辦法就是將 sql 引數化。
sql = "select * FROM [dbo].[xxx] where AccountNO = '" + transRecord.AccountNO + "'";
改成
sql = "select * FROM [dbo].[xxx] where AccountNO = @AccountNO";
最後提一下，這個dump有一定的迷惑性，因為觸發GC的執行緒並不是罪魁禍首，它只不過是壓死駱駝的那最後一根稻草罷了。