最近线上某个服务所有接口突然响应很慢,并且超时,一开始以为是网络的问题,分时段测试了一下,发现并没有太大问题,于是把问题聚焦到了服务本身,用top命令简单看下,CPU直接飙升到了800+%,好家伙,应该是存在明显问题了,经过一阵分析,问题解决,故记录一下排查过程,截图已经是解决后的效果,懒得再把代码换回去了,说明下思路即可。
1、首先使用 top 命令,做进程的简单分析观测
/2、
2、然后使用:jmap -heap 35,查看进程堆信息以及垃圾回收算法等 ,重点注意最后的老年代使用大小,一般超过80%肯定就不是很正常了,作者当时的环境直接99%,好家伙!
3、根据上一步,基本判断GC也会出点问题,使用:jstat -gc 35 1000,再看下gc快照
1000代表毫秒,重点看下FGC(fullgc次数)、FGCT(fullgc时间)、GCT(fullfc总时间),作者当时的环境,每个参数都特别离谱,一般fullgc次数越小越好,基本判定要不是永久代空间分配不足,要不就是代码死循环,产生过多无法释放的对象,要不就是死锁一类的,先猜测一下再说
4、顺便看下前20个占用内存做多的对象的类型: jmap -histo 35 | head -20
多半是已char为主,证明字符对象创建的还是挺多的,所以提醒我们写代码的时候要注意,避免循环里面重复创建太多对象,尽量在循环外声明,循环内赋值。这一步的主要目的是为了让你大概了解是什么对象占用了你太多的内存,能够帮你对问题有一个更加精确的把控
5、看占用资源较高的线程号:top -H -p 35
笔者现在的截图真的好美,问题未解决前,简直不忍直视!
6、使用printf '%x\n' 25595,获取占用最好线程的16进制nid,方便定位代码
7、查看该线程的具体状态:jstack 35 |grep '0x63fb' -C5
运气好的话,一般到这里,基本就能看出来出了问题的代码,如果没看出来,多查看几个线程的状态,对比分析一下,这里的截图只是做演示,所以是RUNNABLE状态,如果是wait,就要注意了;当然也可以直接使用:jstack -l 35 > ./test.jstack.log,打出日志,然后拿着nid直接进行搜索
(1)直接检查日志中的线程状态,如果有大量的wait,肯定证明有问题
cat jstack.log | grep "java.lang.Thread.State" | sort -nr | uniq -c
(2)从服务器下载jstack文件,直接使用notePad++进行预览查看
(3)进一步搜索定位,终于找到了出现问题的业务代码(认真查看代码发现是开发人员不小心使用了while(true)判断,由于业务数据问题,造成死循环,好low的故障。。。)
(4)jdk也有自带的分析工具,visualJVM,可以先在服务器使用:jmap -dump:format=b,file=heapdump.hprof 35 生成堆转储快照dump文件,然后打开工具,载入heapdump.hprof文件,进行具体分析
8、如果使用阿里的arthas,会更简单
java -jar arthas-boot.jar 启动
选择1,开始观察对应服务
生成火焰图:profiler start --event alloc
查看获取的样例数:profiler getSamples
停止监测:profiler stop --format html --file /home/rhino/output.html
监测一段时间,从服务器下载output.html文件,用浏览器打开,分析对象,同样也可以定位到问题代码