一：背景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 StackExchangeisisValue.op_Implicit(StackExchangeisisValue)
000000bb2983c860 00007ffe7aaecd92 xxxx.Util.HelperisHelper.ConvertObj[[System.__Canon, mscorlib]](StackExchangeisisValue)
000000bb2983c8f0 00007ffe7abc3997 xxxx.Util.HelperisHelper+c__DisplayClass29_0`1[[System.__Canon, mscorlib]].b__0(StackExchangeis.IDatabase)
000000bb2983ca20 00007ffe7aaeaca0 xxxx.Util.HelperisHelper.Do[[System.__Canon, mscorlib]](Systemc`2)
000000bb2983caa0 00007ffe7abc3762 xxxx.Util.HelperisHelper.HashGet[[System.__Canon, mscorlib]](System.String, System.String)
000000bb2983cb40 00007ffe7abc2f3d xxxxplementation.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.ExecutionContextInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
000000bb2983e330 00007ffed8bc65e7 System.Threading.ExecutionContext(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.HelperisHelper.ConvertObj[[System.__Canon, mscorlib]](StackExchangeisisValue)
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 SystemtimeMethodHandle
428,376 348,743,274 System.Byte[]
我去，gen2 上居然有 1.4 kw 的对象，这太让人好奇了，接下来随便抽几个 address ，看看它的引用根是个啥？
0:214> !dumpgen 2 -type SystemtimeMethodHandle
Object MT Size Name
——————————————————————-
000000bac9f8fe68 00007FFED8DB9978 24 SystemtimeMethodHandle
000000bac9f8fe80 00007FFED8DB9978 24 SystemtimeMethodHandle
000000bac9f8fe98 00007FFED8DB9978 24 SystemtimeMethodHandle
000000bac9f8feb0 00007FFED8DB9978 24 SystemtimeMethodHandle
000000bac9f8fec8 00007FFED8DB9978 24 SystemtimeMethodHandle
…
000000baca1af510 00007FFED8DB9978 24 SystemtimeMethodHandle
000000baca1af548 00007FFED8DB9978 24 SystemtimeMethodHandle
000000baca1af560 00007FFED8DB9978 24 SystemtimeMethodHandle
000000baca1afd90 00007FFED8DB9978 24 SystemtimeMethodHandle
000000baca1afde0 00007FFED8DB9978 24 SystemtimeMethodHandle
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 Systemc`2[[System.Data.IDataReader, System.Data],[xxx.BAR_AccountDC, xxxx]]
-> 000000baca1ae8b0 System.Reflection.Emit.DynamicMethod+RTDynamicMethod
-> 000000baca1ae7f8 System.Reflection.Emit.DynamicMethod
-> 000000baca1b51b0 SystemtimeMethodInfoStub
-> 000000baca1b4a18 System.Reflection.Emit.DynamicResolver
-> 000000baca1aea60 System.Reflection.Emit.DynamicScope
-> 000000baca1aea78 System.Collections.Generic.List`1[[System.Object, mscorlib]]
-> 000000baca1b3b20 System.Object[]
-> 000000baca1afde0 SystemtimeMethodHandle
从引用链看，它是被 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, Systemc`1)
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)
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 enumerable3=new YiBll(transRecord.AccountNO).QuerySql(sql);
}
问题就出现在这个 sql 拼接上，底层的框架为了提高 mapping 速度，将 sql 和与之对应的 Func 做了缓存处理，由于每次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的线程并不是罪魁祸首，它只不过是压死骆驼的那最后一根稻草罢了。