|
|
|
|
公众号矩阵

RabbitMQ处理过慢,原来是一个SQL缓存框架导致的GC频繁触发

处理过慢原因有很多,可能是干活的人少了,也可能这些人摸鱼去了,总之工作不饱和,接下来看看这帮人有没有摸鱼,从 线程池 看起。

作者:一线码农聊技术来源:一线码农聊技术|2021-11-12 08:07

一、背景

1. 讲故事

上个月底,有位朋友微信找到我,说他的程序 多线程处理 RabbitMQ 时过慢,帮忙分析下什么原因,截图如下:

这问题抛出来,有点懵逼,没说CPU爆高,也没说内存泄漏,也没说程序卡死。。。鬼知道为啥 Rabbitmq 处理过慢哈??????

既然没有一个缘由,那就往 freeze 这个方向去找吧,上 windbg 说话。

二、Windbg 分析

1. 寻找 freeze 原因

处理过慢原因有很多,可能是干活的人少了,也可能这些人摸鱼去了,总之工作不饱和,接下来看看这帮人有没有摸鱼,从 线程池 看起。

  1. 0:000> !tp 
  2. CPU utilization: 81% 
  3. Worker Thread: Total: 187 Running: 172 Idle: 0 MaxLimit: 32767 MinLimit: 8 
  4. Work Request in Queue: 0 
  5. -------------------------------------- 
  6. Number of Timers: 0 
  7. -------------------------------------- 
  8. 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。

  1. 0:214> !clrstack  
  2. OS Thread Id: 0x290c (214) 
  3.         Child SP               IP Call Site 
  4. 000000bb2983c7d0 00007ffed8c3e335 System.Text.UTF8Encoding.GetString(Byte[], Int32, Int32) 
  5. 000000bb2983c810 00007ffe7aaecee9 StackExchange.Redis.RedisValue.op_Implicit(StackExchange.Redis.RedisValue) 
  6. 000000bb2983c860 00007ffe7aaecd92 xxxx.Util.Helper.RedisHelper.ConvertObj[[System.__Canon, mscorlib]](StackExchange.Redis.RedisValue) 
  7. 000000bb2983c8f0 00007ffe7abc3997 xxxx.Util.Helper.RedisHelper+c__DisplayClass29_0`1[[System.__Canon, mscorlib]].b__0(StackExchange.Redis.IDatabase) 
  8. 000000bb2983ca20 00007ffe7aaeaca0 xxxx.Util.Helper.RedisHelper.Do[[System.__Canon, mscorlib]](System.Func`2<StackExchange.Redis.IDatabase,System.__Canon>) 
  9. 000000bb2983caa0 00007ffe7abc3762 xxxx.Util.Helper.RedisHelper.HashGet[[System.__Canon, mscorlib]](System.String, System.String) 
  10. 000000bb2983cb40 00007ffe7abc2f3d xxxx.Implementation.xxx.GetCompany(System.String) 
  11. ... 
  12. 000000bb2983e170 00007ffe7ad2fadf xxx.xxx.MQ.xxx+c__DisplayClass21_0`1[[System.__Canon, mscorlib]].b__1() 
  13. 000000bb2983e1c0 00007ffed8c11862 System.Threading.Tasks.Task`1[[System.__Canon, mscorlib]].InnerInvoke() 
  14. 000000bb2983e220 00007ffed8c10937 System.Threading.Tasks.Task.Execute() 
  15. 000000bb2983e260 00007ffed8bc674e System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) 
  16. 000000bb2983e330 00007ffed8bc65e7 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean) 
  17. 000000bb2983e360 00007ffed8c10bdd System.Threading.Tasks.Task.ExecuteWithThreadLocal(System.Threading.Tasks.Task ByRef) 
  18. 000000bb2983e410 00007ffed8c10303 System.Threading.Tasks.Task.ExecuteEntry(Boolean) 
  19. 000000bb2983e450 00007ffed8bcfa10 System.Threading.ThreadPoolWorkQueue.Dispatch() 
  20. 000000bb2983e8e8 00007ffed9d465d3 [DebuggerU2MCatchHandlerFrame: 000000bb2983e8e8]  

从卦中信息看,程序在 RedisHelper.HashGet 操作的过程中触发了 GC,我去,难道是从 redis 中读了什么大数据?接下来用 !clrstack -a 看看到底从redis中读了个啥?

  1. 0:214> !clrstack -a 
  2. OS Thread Id: 0x290c (214) 
  3.         Child SP               IP Call Site 
  4. 000000bb2983c860 00007ffe7aaecd92 xxx.Util.Helper.RedisHelper.ConvertObj[[System.__Canon, mscorlib]](StackExchange.Redis.RedisValue) 
  5.     PARAMETERS: 
  6.         this (0x000000bb2983c8f0) = 0x000000bb182da3d0 
  7.         value (0x000000bb2983c960) = 0x000000bb18440778 
  8.     LOCALS: 
  9.         0x000000bb2983c8c4 = 0x0000000000000000 
  10.         0x000000bb2983c8a0 = 0x0000000000000000 
  11.         0x000000bb2983c898 = 0x0000000000000000 
  12.  
  13. 0:214> !do 0x000000bb18440778 
  14. Name:        System.Byte[] 
  15. MethodTable: 00007ffed8db93d0 
  16. EEClass:     00007ffed87f4dc8 
  17. Size:        6679(0x1a17) bytes 
  18. Array:       Rank 1, Number of elements 6655, Type Byte (Print Array) 
  19. 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 命令查看。

  1. 0:214> !dumpgen 2 -stat 
  2.        Count      Total Size      Type 
  3. ------------------------------------------------- 
  4.       87,738     24,925,316   System.Int32[] 
  5.      509,643     56,399,716   System.String 
  6.       83,077     65,760,888   System.Reflection.Emit.__FixupData[] 
  7.    2,158,346     69,067,072   System.Reflection.Emit.GenericMethodInfo 
  8.       92,388    172,765,392   System.Object[] 
  9.      796,870    179,587,796   **** FREE **** 
  10.   14,030,441    336,730,584   System.RuntimeMethodHandle 
  11.      428,376    348,743,274   System.Byte[] 

我去,gen2 上居然有 1.4 kw 的对象,这太让人好奇了,接下来随便抽几个 address ,看看它的引用根是个啥?

  1. 0:214> !dumpgen 2 -type System.RuntimeMethodHandle 
  2. Object             MT                    Size   Name 
  3. ------------------------------------------------------------------- 
  4. 000000bac9f8fe68   00007FFED8DB9978        24   System.RuntimeMethodHandle 
  5. 000000bac9f8fe80   00007FFED8DB9978        24   System.RuntimeMethodHandle 
  6. 000000bac9f8fe98   00007FFED8DB9978        24   System.RuntimeMethodHandle 
  7. 000000bac9f8feb0   00007FFED8DB9978        24   System.RuntimeMethodHandle 
  8. 000000bac9f8fec8   00007FFED8DB9978        24   System.RuntimeMethodHandle 
  9. ... 
  10. 000000baca1af510   00007FFED8DB9978        24   System.RuntimeMethodHandle 
  11. 000000baca1af548   00007FFED8DB9978        24   System.RuntimeMethodHandle 
  12. 000000baca1af560   00007FFED8DB9978        24   System.RuntimeMethodHandle 
  13. 000000baca1afd90   00007FFED8DB9978        24   System.RuntimeMethodHandle 
  14. 000000baca1afde0   00007FFED8DB9978        24   System.RuntimeMethodHandle 
  15.  
  16. 0:214> !gcroot 000000baca1afde0 
  17. Thread 187c0: 
  18.     000000baeeb5cb30 00007ffed8ba9c60 System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].FindEntry(System.__Canon) 
  19.         rsi:  
  20.             ->  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]] 
  21.             ->  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]][] 
  22.             ->  000000baca1b5210 System.Func`2[[System.Data.IDataReader, System.Data],[xxx.BAR_AccountDC, xxxx]] 
  23.             ->  000000baca1ae8b0 System.Reflection.Emit.DynamicMethod+RTDynamicMethod 
  24.             ->  000000baca1ae7f8 System.Reflection.Emit.DynamicMethod 
  25.             ->  000000baca1b51b0 System.RuntimeMethodInfoStub 
  26.             ->  000000baca1b4a18 System.Reflection.Emit.DynamicResolver 
  27.             ->  000000baca1aea60 System.Reflection.Emit.DynamicScope 
  28.             ->  000000baca1aea78 System.Collections.Generic.List`1[[System.Object, mscorlib]] 
  29.             ->  000000baca1b3b20 System.Object[] 
  30.             ->  000000baca1afde0 System.RuntimeMethodHandle 

从引用链看,它是被 Dictionary 所持有,那我们就 dump 一下这个 dictionary,看看是个啥。

  1. 0:214> !do 000000baca4c6ef0 
  2. 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]] 
  3. MethodTable: 00007ffe7a937f18 
  4. EEClass:     00007ffed87f7cb8 
  5. Size:        80(0x50) bytes 
  6. File:        C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll 
  7. Fields: 
  8.               MT    Field   Offset                 Type VT     Attr            Value Name 
  9. 00007ffed8dc3e30  400182a        8       System.Int32[]  0 instance 000000badaaa2c10 buckets 
  10. 00007ffed9874d38  400182b       10 ...non, mscorlib]][]  0 instance 000000badab3b8a0 entries 
  11. 00007ffed8dc3e98  400182c       38         System.Int32  1 instance            83000 count 
  12. 00007ffed8dc3e98  400182d       3c         System.Int32  1 instance            83000 version 
  13. 00007ffed8dc3e98  400182e       40         System.Int32  1 instance               -1 freeList 
  14. 00007ffed8dc3e98  400182f       44         System.Int32  1 instance                0 freeCount 
  15. 00007ffed8d9a430  4001830       18 ...Canon, mscorlib]]  0 instance 000000baca2ec958 comparer 
  16. 00007ffed8d9c550  4001831       20 ...Canon, mscorlib]]  0 instance 0000000000000000 keys 
  17. 00007ffed8dcef28  4001832       28 ...Canon, mscorlib]]  0 instance 0000000000000000 values 
  18. 00007ffed8dc1c98  4001833       30        System.Object  0 instance 0000000000000000 _syncRoot 
  19.  
  20. 0:214> !objsize 000000baca4c6ef0 
  21. 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 号线程,然后我们通过线程栈去寻找下源码。

  1. 0:089> ~~[187c0]s 
  2. ntdll!NtWaitForSingleObject+0xa: 
  3. 00007ffe`e9ea06fa c3              ret 
  4. 0:089> !clrstack  
  5. OS Thread Id: 0x187c0 (89) 
  6.         Child SP               IP Call Site 
  7. 000000baeeb5caa0 00007ffed9718dfe System.Tuple`4[[System.__Canon, mscorlib],[System.__Canon, mscorlib],[System.Int32, mscorlib],[System.Int32, mscorlib]].System.Collections.IStructuralEquatable.GetHashCode(System.Collections.IEqualityComparer) 
  8. 000000baeeb5cb00 00007ffed8ba90a7 System.Collections.Generic.ObjectEqualityComparer`1[[System.__Canon, mscorlib]].GetHashCode(System.__Canon) 
  9. 000000baeeb5cb30 00007ffed8ba9c60 System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].FindEntry(System.__Canon) 
  10. 000000baeeb5cba0 00007ffed8bc53a4 System.Collections.Generic.Dictionary`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].TryGetValue(System.__Canon, System.__Canon ByRef) 
  11. 000000baeeb5cbe0 00007ffe7abd8069 xxx.Internal.Cache`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].Get(System.__Canon, System.Func`1<System.__Canon>) 
  12. 000000baeeb5cc50 00007ffe7abd6d52 xxx.Database+d__49`1[[System.__Canon, mscorlib]].MoveNext() 
  13. 000000baeeb5ccd0 00007ffed733768e System.Linq.Enumerable.FirstOrDefault[[System.__Canon, mscorlib]](System.Collections.Generic.IEnumerable`1<System.__Canon>) 
  14. 000000baeeb5cd40 00007ffe7af5489e xxx.xxx.ParsePapPayDebitRecord(xxx, xxx.BAR_AccountDC ByRef, System.String ByRef, xxx ByRef, Boolean, xxx, Boolean) 
  15. ... 

从线程栈看,程序做了一个 db 查询的操作,源码大概如下:

  1. public static InvalidTxnCode ParsePapPayDebitRecord(xxx) 
  2.     sql = "select * FROM  [dbo].[xxx]  where AccountNO = '" + transRecord.AccountNO + "'"
  3.  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 参数化。

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

改成:

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

最后提一下,这个dump有一定的迷惑性,因为触发GC的线程并不是罪魁祸首,它只不过是压死骆驼的那最后一根稻草罢了。

【编辑推荐】

  1. 五分钟,让你明白MySQL是怎么选择索引的
  2. Android与SQLite学生信息管理Java版
  3. MySQL 主从复制 Replication 详解(Linux 和 Windows 交叉环境)
  4. MMM 集群部署实现 MySQL 高可用和读写分离
  5. Oracle SQL 项目级实战指南视频课程-技能篇
【责任编辑:武晓燕 TEL:(010)68476606】

点赞 0
分享:
大家都在看
猜你喜欢

订阅专栏+更多

带你轻松入门 RabbitMQ

带你轻松入门 RabbitMQ

轻松入门RabbitMQ
共4章 | loong576

55人订阅学习

数据湖与数据仓库的分析实践攻略

数据湖与数据仓库的分析实践攻略

助力现代化数据管理:数据湖与数据仓库的分析实践攻略
共3章 | 创世达人

14人订阅学习

云原生架构实践

云原生架构实践

新技术引领移动互联网进入急速赛道
共3章 | KaliArch

42人订阅学习

订阅51CTO邮刊

点击这里查看样刊

订阅51CTO邮刊

51CTO服务号

51CTO官微