前言

        一个微服务模块在运行一段时间之后,整体服务就不可用了,但是服务却没有打印任何错误日志。而对服务进行重启之后,服务就可以暂时提供一段时间服务,过一段时间之后再次不可用。

分析

        服务进行重启就可以正常提供功能,说明是某些资源没有释放。接下来需要确定的是什么资源被占用不能够释放就可以定位到问题并解决了。

处理过程

        1、首先查看服务器的磁盘、cpu占用情况,发现还有很大空闲,因此不是服务器资源不够用的问题;

        2、检查JVM的GC情况,我这里是在对服务重启的命令上添加了远程链接的参数,hostname是服务器的ip,port是向外暴露的一个端口号。然后就可以在本地使用jvisualvm对服务器上的JVM运行情况进行检测了。

-Djava.rmi.server.hostname=ip 
-Dcom.sun.management.jmxremote 
-Dcom.sun.management.jmxremote.port=9999 
-Dcom.sun.management.jmxremote.ssl=false 
-Dcom.sun.management.jmxremote.authenticate=false  

        检测过程中,发现GC情况是正常的,在服务即将不可用之前,也没有出现频繁GC或者内存过高甚至内存溢出的问题。

        3、由于短时间之内没有发现问题,且不知道服务什么时候就会失效,只好写了一个定时脚本,检测服务是否可用,不可用时将此刻的内存快照保存下来,以下是检测服务、下载内存快照、重启服务的脚本。

serverurl=http://ip:port/actuator/health
urlstatus=$(curl -s -m 5 -IL $serverurl|grep 200)
if [ "$urlstatus" == "" ];then
        echo "eis服务不可用"
        ID=`ps -ef | grep eis | grep -v "$0" | grep -v "grep" | awk '{print $2}'`
        echo $ID
        /home/tkbo/JDK/jdk1.8.0_301/bin/jmap -dump:format=b,file=/home/tkbo/menhuJar/serviceDump.dat $ID
	     kill -9 $ID
        echo "已终止eis服务"
        nohup /home/tkbo/JDK/jdk1.8.0_301/bin/java -Djava.rmi.server.hostname=ip -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=9999 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false  -jar /home/tkbo/menhuJar/ace-eis-manager.jar --eureka.instance.ip-address=ip --eureka.client.serviceUrl.defaultZone=http://ip:8761/eureka/,http://ip:8761/eureka/ --spring.profiles.active=ergo > /home/tkbo/menhuJar/ace-eis-manager.nohup 2>&1 &
        time=$(date "+%Y-%m-%d %H:%M:%S")
        echo "当前时间为${time},服务已重启"
else
        echo "服务正常"
fi

        4、将下载下来的dump文件修改后缀名为.hprof,然后用Jprofiler工具进行分析。

        可以看到有很多的线程阻塞在了获取druid连接这一块,那么问题很明显了,服务在获取数据库连接的时候出现了超时,项目中使用的数据库连接池是druid,果然在github找到有人遇到了同样的问题,https://github.com/alibaba/druid/issues/1160,都是druid卡在了这里

com.alibaba.druid.pool.DruidDataSource.takeLast() (line: 1444)
com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(long) (line: 1088)
com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(long) (line: 953)
com.alibaba.druid.pool.DruidDataSource.getConnection(long) (line: 933)
com.alibaba.druid.pool.DruidDataSource.getConnection() (line: 923)
com.alibaba.druid.pool.DruidDataSource.getConnection() (line: 100)

 解决方法

        解决的方法也很简单,只需要加上两个属性就可以了。注意这里由于druid版本的不同,对这两个参数的配置也有可能不太一样,如果想要判断配置是否生效,可以在修改配置之后查看下Druid的web监控页面。

#设置获取连接最大等待时间,不再一直等待获取连接
maxWait: 60000
#是否自动回收超时连接
removeAbandoned=true
#超时时间(以秒数为单位)
removeAbandonedTimeout=180

问题分析

        为什么会出现获取连接超时的情况呢?我们知道Druid提供了数据库连接池的功能,因此我们执行数据库查询时,会从连接池中获取一个可用的连接进行查询。但如果一直获取不到可用的连接,就会导致线程一直等待了。

        Druid从数据库线程池获取连接分为两种方式:如果maxWait>0,则调用pollLast()方法;否则调用takeLast()方法。poll()、take()是不是很熟悉,没错这是从阻塞队列中获取元素的方法。poll()在指定时间内如果获取失败了可以直接返回,take()则是持续等待。我这里大致说下获取连接用到的方法,具体可以看这篇博客。Druid连接池核心原理_毛龙蛋的博客-CSDN博客_druid连接池

        maxWait参数可以让获取连接的线程不一直阻塞,而两个removeAbandoned参数则是让超时的连接及时被回收。

 最终原因

        上一步说明了,修改了Druid的属性之后,服务就可以正常运行了。但其实还没有触及到问题的根本原因,项目的并发并不高,连接线程数的数量也是够用的,为什么还是会出现获取不到可用连接的情况呢?

        通过Druid的web页面可以监控到项目中的长SQL,而我问题的根本原因就是,项目中有个查询使用到的表会出现行独占锁导致查询一直失败,而且这个表锁是偶发性的,最开始我测试这个长SQL的时候没有出现表锁,所以很长一段时间都没有定位到问题。

        产生行级排它锁的原因?以下是我跟据表业务功能锁进行的推测,并没有实际验证。

        被查询的这张表是数据报表,我们的数据工程师会在指定时间内把处理好的数据插入这张表中,在表进行数据插入的时候,这张表被加上了行级排它锁,因此其它事务对这张表中的所有数据进行查询时就出现了一直等待的情况。

最后

        这是自己第一次通过JVM的内存快照信息排查项目的问题,博客写的比较短,但实际上从发现问题到解决问题用了两周的时间,期间走了不少弯路,不过还好最终解决了问题,那些走的弯路也让自己学到了更多的知识。

        写这篇博客也是对排查过程进行一次总结,还有一个很重要的原因,昨天和一位老师交流JVM排查问题的经历,由于自己表述不清楚,那位老师以为我是看的别人的博客,把别人的解决问题的经历说成了自己的,呜呜呜,你可以觉得我的技术很菜,但不能说孩子抄袭啊啊啊。不过也确实是自己理解不够深,不能够把排查的过程系统的串联起来,因此今天对排查过程进行了总结,也可以避免大家使用Druid时遇到相似的问题。

Logo

为开发者提供学习成长、分享交流、生态实践、资源工具等服务,帮助开发者快速成长。

更多推荐