近期公司运营同学经常表示线上我们一个后台管理系统运行特别慢,而且经常出现504超时的情况。对于这种情况我们本能的认为可能是代码有性能问题,可能有死循环或者是数据库调用次数过多导致接口运行过慢。应领导要求,我们将主站中进行性能测试的框架代码(见我前面一篇博文记录一次通过性能日志处理线上性能问题的过程)添加到了该后台管理系统中。上线运行一段时间后,查看相关日志可以看到如下分析日志:
性能分析日志
通过该日志可以发现,dao方法一直获取不到数据库链接池,但是根据实际情况考虑应该不大可能,原因有两点:
主站和后台管理系统使用的是同一套数据库,相较而言,主站的访问量更高,数据量也更大,却没有出现问题;
该性能问题的出现有一定的频率,即有的时候出现,有的时候情况好一些;
虽然根据分析我们认为不大可能是数据库问题,但我们还是查看了线上数据库链接的相关情况,具体链接情况如下:
数据库链接
这个两个是主要用到的两个数据库,而其他的数据库链接相对来说链接数也不高,总链接数加起来远远没有达到我们配置的最大链接数,并且在processlist中也没有发现什么耗时比较高的链接。因而确实证实了出现的性能问题不是数据库导致的。
既然不是数据库导致的,通过性能日志也可以确认不是代码中有死循环或者数据库调用次数过多的问题,我们就思考是否为jvm层面的问题。在登录线上机器之后,我们使用首先使用top命令查看了该机器进程的运行情况:
进程运行情况
可以看到,id为2580的进程cpu一直在100%以上,然后使用如下命令查看该进程中具体是哪个线程运行的cpu如此之高:
top -Hp 2580
结果如下:
线程运行情况
可以看到,id为2598的线程运行cpu达到了97.7%,基本上可以确定是这个线程的运行导致项目整体运行较慢。接下来我们使用jstack命令查看了该进行各个线程运行情况,具体的命令如下:
jstack 2580 > ~/jstack.log
这里有两点需要注意:
jstack命令需要在jdk的bin目录下执行,并且必须要以当前启动项目tomcat的用户身份运行,如果不是该用户登录的,可以使用如下命令导出线程运行日志:
sudo -u admin ~/jdk/bin/jstack 2580 > ~/jstack.log
在线程日志中,线程的id是使用十六进制的方式打印的,而在top -Hp命令中线程的id是10进制打印的,因而我们需要得到2598这个数字对应的16进制值,命令如下: