RabbitMQ處理過慢，原來是一個SQL緩存框架導致的GC頻繁觸發
作者：一線碼農聊技術
處理過慢原因有很多，可能是干活的人少了，也可能這些人摸魚去了，總之工作不飽和，接下來看看這幫人有沒有摸魚，從 線程池 看起。
一、背景
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的線程并不是罪魁禍首，它只不過是壓死駱駝的那最后一根稻草罷了。
責任編輯：武曉燕
來源：
一線碼農聊技術
