RabbitMQ處理過(guò)慢，原來(lái)是一個(gè)SQL緩存框架導(dǎo)致的GC頻繁觸發(fā)

作者：一線(xiàn)碼農(nóng)聊技術(shù) 2021-11-12 08:07:31

處理過(guò)慢原因有很多，可能是干活的人少了，也可能這些人摸魚(yú)去了，總之工作不飽和，接下來(lái)看看這幫人有沒(méi)有摸魚(yú)，從線(xiàn)程池看起。

[[434658]]

一、背景

1. 講故事

上個(gè)月底，有位朋友微信找到我，說(shuō)他的程序多線(xiàn)程處理 RabbitMQ 時(shí)過(guò)慢，幫忙分析下什么原因，截圖如下：

這問(wèn)題拋出來(lái)，有點(diǎn)懵逼，沒(méi)說(shuō)CPU爆高，也沒(méi)說(shuō)內(nèi)存泄漏，也沒(méi)說(shuō)程序卡死。。。鬼知道為啥 Rabbitmq 處理過(guò)慢哈??????

既然沒(méi)有一個(gè)緣由，那就往 freeze 這個(gè)方向去找吧，上 windbg 說(shuō)話(huà)。

二、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

從輸出中看，當(dāng)前的 CPU=81%，大概率是這個(gè)程序引起的，既然 CPU 過(guò)高，可能是某些計(jì)算密集型操作，可能是大量鎖導(dǎo)致的上下文切換，也可能是 GC 頻繁觸發(fā)所致。

2. 是 GC 觸發(fā)嗎?

本系列到這里，我相信有很多朋友應(yīng)該知道如何從線(xiàn)程棧上看是否為 GC 觸發(fā)所致，用命令 ~*e !dumpstack 經(jīng)過(guò)一通尋找，發(fā)現(xiàn)是 214 號(hào)線(xiàn)程觸發(fā)了 GC，如下圖所示：

用 !dumpstack 輸出的信息太多，為了讓信息更加簡(jiǎn)化，改用 !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 操作的過(guò)程中觸發(fā)了 GC，我去，難道是從 redis 中讀了什么大數(shù)據(jù)?接下來(lái)用 !clrstack -a 看看到底從redis中讀了個(gè)啥?

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 的數(shù)據(jù)，才這么點(diǎn)數(shù)據(jù)，我還以為幾十M 呢 ??????，要說(shuō)這點(diǎn)東西就能觸發(fā)GC，我是不相信的。

3. 到底是什么誘使了 GC 觸發(fā) ?

那這個(gè) 罪魁禍?zhǔn)?到底是誰(shuí)呢?其實(shí)仔細(xì)想一想，GC觸發(fā)無(wú)非就是將對(duì)象從 gen0 推到 gen1，然后由 gen1 推到 gen2，那朋友的這個(gè) RabbitMQ 處理慢，肯定是觸發(fā)了多次GC，才有了這個(gè)肉眼可見(jiàn)的處理慢。

這里就有一個(gè)突破點(diǎn)，既然觸發(fā)多次GC，那gen2上肯定有很多帶根的對(duì)象，所以從這里入手比較好，用 !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 的對(duì)象，這太讓人好奇了，接下來(lái)隨便抽幾個(gè) address ，看看它的引用根是個(gè)啥?

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 一下這個(gè) dictionary，看看是個(gè)啥。

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]])

可以看到，當(dāng)前dict 的 size= 8.3w，總大小為 1.1G, 然后用 !mdt 抽查一下字典內(nèi)容。

可以看出，字典中的item大概都是 key= select * from xxx where AccountNo= xxxx， value = Func ，

4. 查看源碼

從 !gcroot 中知道當(dāng)前根在 187c0 號(hào)線(xiàn)程，然后我們通過(guò)線(xiàn)程棧去尋找下源碼。

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) 
...

從線(xiàn)程棧看,程序做了一個(gè) db 查詢(xún)的操作，源碼大概如下：

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); 
}

問(wèn)題就出現(xiàn)在這個(gè) sql 拼接上，底層的框架為了提高 mapping 速度，將 sql 和與之對(duì)應(yīng)的 Func<DataReader,Data> 做了緩存處理，由于每次sql都不一樣，這就導(dǎo)致底層的 dict越來(lái)越大，直到目前的 1.1 G。

三、總結(jié)

總的來(lái)說(shuō)，本次事故是由于不斷增長(zhǎng)的 dict 在不斷的擠壓小對(duì)象堆，加之程序多線(xiàn)程火力全開(kāi)分配對(duì)象導(dǎo)致gc在小對(duì)象堆上的頻繁回收造成的 rabbitmq 處理過(guò)慢。

修改辦法就是將 sql 參數(shù)化。

sql = "select * FROM [dbo].[xxx] where AccountNO = '" + transRecord.AccountNO + "'";

改成：

sql = "select * FROM [dbo].[xxx] where AccountNO = @AccountNO";

最后提一下，這個(gè)dump有一定的迷惑性，因?yàn)橛|發(fā)GC的線(xiàn)程并不是罪魁禍?zhǔn)祝徊贿^(guò)是壓死駱駝的那最后一根稻草罷了。

責(zé)任編輯：武曉燕來(lái)源：一線(xiàn)碼農(nóng)聊技術(shù)

SQL 緩存 RabbitMQ