RabbitMQ处理过慢，原来是一个SQL缓存框架导致的GC频繁触发-51CTO.COM

[[434658]]

一、背景

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的线程并不是罪魁祸首，它只不过是压死骆驼的那最后一根稻草罢了。