记一次生产redis线程堵塞fullgc问题分析

背景
目前线上运行推荐业务模块，因重构版本和老版本分别部署在不同的机器集群中，运行了几个版本后，老版本的流量已经少的可怜，日均50w左右，为了释放机器资源，然后把老版本代码复制到重构版本后的项目中继续为老版本用户提供服务。搞完后，测试通过，上线。当然我们也比较小心，首先切了一台网关然后观察了一段时间发现基本正常。等下一个上线日我们就把所有网关全部切到新项目的上边。首日基本正常，第二日后问题接踵而至。

一、老版本接口耗时超长

1.1 首次发现问题

首次发现问题是只在其中的一台机器(A)发生的，下图是首次发现问题监控截图，可以明显看到耗时已经非常高很不正常，99.99 已经达到1w 毫秒了。而且max已经达到30几万毫秒了。

再看当时的gc 情况，发现发生了一次fullgc. 因为当前业务访问量还挺高的，是不允许发生fullgc 的情况，否则肯定会阻塞。

虽然首次发生问题，也观察了，但是我们都没有把它当回事，在这里要给大家建议和奉劝。“要对生产充满敬意，否则你会被玩死的”。

1.2 第二次发现问题

查看第二次还是相同的机器，而且还是相同的时间点，也太巧了，可以看一下当时的监控耗时情况

gc情况

这次我们比上次当然要重视了，首先我们下载了问题机器的堆栈信息进行分析，下载堆栈可以使用命令

jstack pid >> heapStack.txt

从日志分析看到很多redis获取等待，难道是redis的问题？

我们找负责redis相关人员进行查看，得确是有一些慢查询，但是也看不出是具体什么问题。因为只有一台机器有这个问题。其他机器都正常。我们提前和领导说了这个问题。因为确实只有一台机器又问题。而且还是在同一时间点，同一机器。最后我们怀疑难道是机器的问题？话不多说，开始把有问题机器下线。切换到另一台机器继续运行观察。

1.3 第三次问题（严重）

这次发生问题，在晚上首先收到耗时报警

紧接着收到宕机报警

因为在晚上还是个周末，马不停蹄，开电脑、和领导汇报。和领导一块排查问题，因为这是核心业务，根本不能给你分析的时间，我就找了一台机器先把整个的堆栈dump下来。然后领导直接重启服务。分工合作。

重启服务后，恢复正常。

第二天，也就是周一，领导出事故报告，没有分析出根因，但是肯定是和老版本原来的代码有脱不了的干系。然后只能把原来老代码老服务，重新上线，释放资源就暂时放在一边。修改网关，上线运行目前没有发现问题，而且也没有任何相对之前有不正常的现象。因为研发时间问题，就这样解决了目前的问题。

二、原因分析及猜测

在空余时间时，因为不太甘心，不能死的这么不明不白的。然后分析之前下载下来的dump文件。我这里使用的是mat(https://www.eclipse.org/mat/downloads.php)，mat 的使用大家可以自行百度一下。

因为我们这个接口是多线程并发业务访问，这里看到问题ThreadPoolExecutor 里边的问题继续点detail查看

查看到具体的信息

可以看到大多数线程都在这个redis 这里等待，为什么会这个样子？结合堆栈信息分析

发现都是出现在ClusterCommandExecutor的executeMultiKeyCommand 这里。

可以看到这个方法内容其实是是使用异步线程去执行的，通过future来获取结果。这个线程池是什么时候创建的呢？

首先可以看到在当前类有一段代码块，来创建了当前的线程池。

跟踪initialize方法 来到可以看到创建线程池

上边创建线程使用的corePoolSize ，大家发现没有，这里核心线程数是 1.

如果真的是使用的1的话。那么在多线程调用的话，肯定会有等待。继续分析看看。

因为我们使用的是jedis 的客户端，然后就从JedisConnectionFactory开始分析

可以看到这里并没有指定线程池，所以就如咱们分析的一样，redis获取数据这块肯定会堵塞。导致接口慢。

给大家看一下老的代码线程执行的一个代码

可以看到这里使用countDownLath去等待线程全部执行完来获取结果，并没有指定超时时间，猜测在这个地方因为redis等待然后线程一直阻塞等待，后续进来的请求也会打到队列里边。而且之前请求一些获取的资源也一直在内存中，导致发生fullgc.从而进一步使服务恶化。这里我还有个猜测就是假如在发生fullgc 的时候，如果正在执行的countDownLatch 并不能够减到0，那么现在这个线程池就一直等待。只是猜测未做验证。我觉得也是可能发生的一个坑。

这里推荐大家使用ExecutorService invokeAll 指定线程超时时间，超时会发送线程中断信号。

三、内存分析常用命令

3.1 jstat（JVM Statistics Monitoring Tool）命令主要用来监控虚拟机运行状态信息，其命令格式为 jstat [options] [vmid] [interval[m|ms]] [count]

其中，options选项用来确定需要监视虚拟机的哪部分数据，vmid为本地虚拟机进程id，interval用于控制监控的时间间隔，可以加m|ms单位，count用来控制监控的次数。options选项取值如下：

选项	说明
-class	监控类装载，卸载数量，总空间以及类装载所耗费的时间
-gc	监视Java堆状况，包括Eden区，两个Survivor区，老年代等的容量，已用空间，GC时间合计等信息
-gccapacity	监视内容与-gc一样，但只要关注Java堆中各个区域使用到的最大，最小空间
-gcutil	监视内容与-gc一样，但只要关注已使用空间占总空间的百分比
-gccause	与-gcutil功能一样，但会额外输出导致上一次GC的原因
-gcnew	监视新生代GC状况
-gcnewcapacity	监视内容与-gcnew一样，但是主要关注使用新生代使用的最大，最小空间
-gcold	监视老年代GC状况
-gcoldcapacity	监视内容与-gcold一样，但是主要关注老年代使用的最大，最小空间
-compiler	输出JIT编译器编译过的方法，耗时等信息
-printcompilation	输出已经被JIT编译的方法

命令示例

jstat -gc 3830 2 5 
这个命令意思就是每隔2ms输出3830的gc情况，输出5次

C即Capacity 总容量，U即Used 已使用的容量

• S0C : survivor0区的总容量
• S1C : survivor1区的总容量
• S0U : survivor0区已使用的容量
• S1U : survivor1区已使用的容量
• EC : Eden区的总容量
• EU : Eden区已使用的容量
• OC : Old区的总容量
• OU : Old区已使用的容量
• PC 当前perm的容量 (KB)
• PU perm的使用 (KB)
• YGC : 新生代垃圾回收次数
• YGCT : 新生代垃圾回收时间
• FGC : 老年代垃圾回收次数
• FGCT : 老年代垃圾回收时间
• GCT : 垃圾回收总消耗时间

3.2 jmap

jmap命令的主要作用是生成堆转储文件，其命令格式为： jmap [option] vmid

其中，option的取值有如下几种：

选项	说明
-dump	用于生成堆转储快照文件，命令格式为:jmap -dump:[live,]format=b,file=,其中live参数表示只dump出存活的对象，命令示例： jmap -dump:format=b,file=./result.hprof 65684 ；或者 jmap -dump:live,format=b,file=./result.hprof 65684
-finalizerinfo	显示在F-QUeue中等待Finalizer线程执行finalize方法的对象，如： jmap -finalizerinfo 65684
-heap	显示Java堆详细信息，如使用哪种垃圾回收期，参数配置，分代状况等。如： jmap -heap 65684
-histo	显示堆中对象统计信息，包括类，实例数量，合计容量。如： jmap -histo 65684
-F	当虚拟机对-dump命令没有响应的时候，可以使用该参数强制生成dump文件

生成dump 命令 jmap -dump:format=b,file=a.hprof pid

3.3 jstack

jstack用于生成虚拟机当前时刻的线程快照（threaddump文件），命令格式为 jstack [option] vmid 。

其中option具体取值如下：

参数	说明
-F	当正常输出的请求不被响应时，强制输出线程堆栈
-l	除堆栈外，显示关于锁的信息
-m	如果调用到本地方法的话，可以显示C/C++的堆栈

jstack -l 3830 >>stack.txt 生成堆栈信息

3.4 jinfo

jinfo(JVM Configuration info)这个命令作用是实时查看和调整虚拟机运行参数。 之前的jps -v口令只能查看到显示指定的参数，如果想要查看未被显示指定的参数的值就要使用jinfo口令

命令格式为. jinfo [option] [args] vmid 。

其中option具体取值如下：

参数	说明
-flag	输出指定args参数的值 也可通过此来配置参数
-flags	不需要args参数，输出所有JVM参数的值
-sysprops	输出系统属性，等同于System.getProperties()

配置具体参数

jinfo -flag +HeapDumpBeforeFullGC 3830

jinfo -flag HeapDumpPath=/data/logs/dump_file 3830

查看配置是否生效

jinfo -flag HeapDumpPath 3830