vlambda博客
学习文章列表

问题现象

在某个工作日，突然收到线上的服务告警，有大量的请求延时产生，查看线上服务发现基本上都是获取数据库连接超时，而且影响时间只有3~4秒钟，服务又恢复了正常。

隔了几分钟之后，又出现了大量的告警，还是影响3~4秒后又恢复正常。由于我们是底层服务，被重多的上层服务所依赖，这么频繁的异常波动已经严重影响到了业务使用。开始排查问题

排查过程

DB的影响？

• 当第一次告警产生时，第一反应是可能上层服务有大量的接口调用，并且涉及到一些复杂的SQL查询导致数据库连接数不够用，但是在分析了接口调用情况后发现异常前后的请求并没有明显的变化，排除突发流量造成的影响

• 查询DB情况，负载良好，无慢查询，排除DB造成的影响

容器或JVM的影响？

排除了DB的影响之后，再往上排查容器的影响， 我们再次回过头看异常告警，发现在每一波告警的时间段内，基本上都是同一个容器IP所产生。

这个时候基本上已经有80%的概率是GC的问题了。查询告警时间段内的容器CPU负载正常。再看JVM的内存和GC情况，发现整个内存使用曲线是像下面这样：

Heap

Old Gen

从上图可以发现内存中存在长时间被引用，无法被YongGC所回收的对象，并且对象大小一直在增长。直到Old Gen被堆满之后触发Full GC后对象才会回收。

临时措施

现在问题已经找到了，到目前为止只是3台实例触发了FullGC，但是在查看其它实例内存使用情况时，发现基本上所有的实例Old Gen都快到达临界点了。

所以临时解决方案是保留一台实例现场，滚动重启其它所有的实例，避免大量的实例同时进行FullGC。否则很可能导致服务雪崩。

原本服务是有设置jvm监控告警的，理论上来说当内存使用率达到一定值时会有告警通知，但是由于一次服务迁移导致告警配置失效，没有提前发现问题。

问题分析

什么对象没有被回收？

目前了解到的情况：内存无法被YoungGC回收，且无限增加，只有FullGC才能够回收这批对象

jmap -histo:live pid

先简单在线上观察了一波，排第2的HashMap$Node看起来比较异常，但是看不出更详细的情况了。最好的办法还是将内存快照dump出来，使用MAT分析一波

jmap -dump:format=b,file=filename pid 

使用MAT打开之后，可以发现很明显的问题：

class com.mysql.cj.jdbc.AbandonedConnectionCleanupThread

这个类占用了80%以上的内存，那么这个类是干嘛的呢？看类名就知道，应该是MySQL Driver中用来清理过期连接的一个线程。让我们看一下源码：

这个类是一个单例，会且仅会开一个线程，用来清理那些没有被显式的关闭的数据库连接。

可以看到这个类里面维护了一个Set

private static final Set<ConnectionFinalizerPhantomReference> connectionFinalizerPhantomRefs = ConcurrentHashMap.newKeySet();

对应我们上面看到的内存占用率排第二的HashMap$Node，基本上可以确定大概率是这里存在内存泄露了。在MAT上使用list_object确认一发：

果然没错，罪魁祸首找到了！那么它里面存的是啥东西呢？

为什么一直增长且无法被YoungGC回收？

看名字ConnectionFinalizerPhantomReference 我们可以猜到它里面保存的应该是数据库连接的phantom引用

什么是phantom reference? 当一个对象只有phantom reference引用时，则会在虚拟机GC时被回收，同时会将phantom reference的对象放入一个referenceQueue中。

让我们来跟踪源码确认一下

果然是PhantomReference，里面存放的是创建的MySQL连接，看一下是在哪里被放进来的：

可以看到，每次创建一个新的数据库连接时，都会将创建的连接包装成PhantomReference后放入connectionFinalizerPhantomRefs中，然后这个清理线程会在一个无限循环中，获取referenceQueue中的连接并关闭

只有在 connection对象 没有其它的引用，仅存在phantom reference时，才能够被GC，并且放入referenceQueue中

为什么Connection会无限增长？

现在问题找到了，数据库连接被创建之后，则会放入connectionFinalizerPhantomRefs中，但是由于某种原因，连接前期正常使用，经过了多次minor GC都没有被回收，晋升到了老年代。但是一段时间过后，由于某种原因连接失效，导致连接池又新建了连接。

我们项目用的数据库连接池是Druid，以下为连接池配置：

可以看到是设置了keepAlive，且minEvictableIdleTimeMillis设置的是5分钟，连接初始化之后，在DB请求数没有频繁的波动时，连接池应该都是维护着最小的30个连接，且会在连接空闲时间超过5分钟时进行一次keepAlive操作:

理论上来说，连接池是不会频繁的创建连接的，除非有活跃连接很少，且存在波动，并且keepAlive操作没有生效，在连接池进行keepAlive操作时，MySQL连接就已经失效，那么则会丢弃这个无效连接，下次再重建。

下面就是验证这个猜想，我们首先查看我们的活跃连接数，发现在大部分时候，单实例的数据库的活跃连接数都在3~20个左右波动，并且业务上还存在定时任务，每隔30分钟~1个小时会有大量的DB请求。

Druid既然有每隔5分钟有心跳行为，那为什么连接还会失效？最大的可能是MySQL服务端的操作，MySQL默认服务端的wait_timeout是8小时，难道是有变更对应的配置？

show global variables like '%timeout%'

果然，数据库的超时时间被设置成了5分钟！那么问题就很明显了

结论

• 空闲连接依赖于Druid的keepAlive定时任务来进行心跳检测和keepAlive，定时任务默认每60秒检测一次，并且只有当连接的空闲时间大于minEvictableIdleTimeMillis时才会进行心跳检测。

• 由于minEvictableIdleTimeMillis被设置为了5分钟，理论上空闲连接会在5分钟±60秒的时间区间内进行心跳检测。但是由于MySQL服务端的超时时间只有5分钟，所以大概率当Druid进行keepAlive操作时连接已经失效了。

• 由于数据库的活跃连接是波动的，且min-idle设置的是30，活跃连接处于波峰时，需要创建大量的连接，并且维护在连接池中。但是当活跃降到低谷时，大量的连接由于keepAlive失败，从连接池中被移除。周而复始。

• 每次创建连接时，又会将Connection对象放入connectionFinalizerPhantomRefs中，并且由于创建完之后连接是处于活跃状态，短时间内不会被miniorGC所回收，直至晋升到老年代。导致这个SET越来越大。

解决

知道问题的产生原因，要解决就很简单了，将minEvictableIdleTimeMillis设置为3分钟，保证keepAlive的有效性，避免一直重建连接即可。

源于：https://juejin.im/post/6844904201156296718

          
            
            
          

           
             
             
           
 
            
 
             
 
              
 
               
 
                
 
                  
                
 
                
 
                 给个[在看]，是对IT老哥最大的支持 
                
 
                

 
               
 
              
 
             
 
            
 
           
          
            
            
          

IT老哥 发起了一个读者讨论 欢迎留言 精选讨论内容

🤔:😶

老哥公司做的都是什么类型的项目呀？

疯风

有点看不懂啊，有没有更加简单的方式看懂

拿腿绊坦克

给老哥点个赞，我学JAVA的资料都是从你这弄得，非常受用 感谢

余下1条讨论内容