当java程序出现性能问题时,我们可以通过一些工具,快速定位出拖慢程序的代码:
jstack
jstack是jdk自带的堆栈跟踪工具
首先,我们用ps -ef|grep java
命令列出正在运行的java进程:
| # ps -ef|grep java root 33 32 67 21:52 tty2 00:00:10 java -jar xxx.jar root 101 11 0 21:52 pts/0 00:00:00 grep --color=auto java
|
得到其进程号,这个例子里,xxx.jar程序的进程号是33。
(如果你的系统是windows执行不了这些命令,强烈建议装一个wsl1,IDEA支持把代码跑在wsl里了,调试起来会非常舒服,wsl2目前与windows本体的文件交换机制是网络传输,性能很差不建议。)
现在,我们执行两个命令,分别打印出进程33的线程运行情况、最忙的线程(建议把打印结果复制到一个txt文件里方便ctrl+f查找)
jstack -l 33
命令打印线程运行情况
ps p 33 -L -o pcpu,pid,tid,time,tname,cmd
打印出线程使用cpu的情况
打印结果如下:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30
| # jstack -l 33 Full thread dump OpenJDK 64-Bit Server VM (17.0.2+8-86 mixed mode, sharing):
Threads class SMR info: _java_thread_list=0x00007f3658001890, length=12, elements={ 0x00007f369c023f10, 0x00007f369c1739b0, ... }
"main" #1 prio=5 os_prio=0 cpu=90140.00ms elapsed=98.18s tid=0x00007f369c023f10 nid=0x22 runnable [0x00007f36a12fe000] java.lang.Thread.State: RUNNABLE at org.rocksdb.RocksDB.get(Native Method) at org.rocksdb.RocksDB.get(RocksDB.java:1965) at org.wowtools.giscat.vector.rocksrtree.TreeTransaction.get(TreeTransaction.java:74) at org.wowtools.giscat.vector.rocksrtree.TreeBuilder.getLeaf(TreeBuilder.java:186) ...
Locked ownable synchronizers: - None
"Reference Handler" #2 daemon prio=10 os_prio=0 cpu=0.00ms elapsed=97.06s tid=0x00007f369c1739b0 nid=0x29 waiting on condition [0x00007f367955e000] java.lang.Thread.State: RUNNABLE at java.lang.ref.Reference.waitForReferencePendingList(java.base@17.0.2/Native Method) at java.lang.ref.Reference.processPendingReferences(java.base@17.0.2/Reference.java:253) at java.lang.ref.Reference$ReferenceHandler.run(java.base@17.0.2/Reference.java:215)
Locked ownable synchronizers: - None
...
|
| # ps p 33 -L -o pcpu,pid,tid,time,tname,cmd %CPU PID TID TIME TTY CMD 91.9 33 33 00:01:02 tty2 /mydata/java/jdk-17/bin/java 87.9 33 34 00:00:59 tty2 /mydata/java/jdk-17/bin/java 0.0 33 35 00:00:00 tty2 /mydata/java/jdk-17/bin/java 0.0 33 36 00:00:00 tty2 /mydata/java/jdk-17/bin/java ...
|
现在我们知道了34号线程是最忙的,占了87.9%的CPU(33是主线程看不出什么内容),然后把34转为16进制:
最后,我们去查找jstack -l 33的输出里找关键字0x22:
| "main" #1 prio=5 os_prio=0 cpu=90140.00ms elapsed=98.18s tid=0x00007f369c023f10 nid=0x22 runnable [0x00007f36a12fe000] java.lang.Thread.State: RUNNABLE at org.rocksdb.RocksDB.get(Native Method) at org.rocksdb.RocksDB.get(RocksDB.java:1965) at org.wowtools.giscat.vector.rocksrtree.TreeTransaction.get(TreeTransaction.java:74) at org.wowtools.giscat.vector.rocksrtree.TreeBuilder.getLeaf(TreeBuilder.java:186) ...
|
可以发现,这段代码是频繁地去RocksDB里get数据,导致性能过低,我们用一个HashMap缓存一下,避免重复的get,性能一下就上去了~~~
火焰图
jstack -l
命令是用来获取当前的线程栈信息,也就是它的结果是瞬时的,如果我们的实际应用场景比较复杂,往往需要采样一段时间内的运行情况,再找出这段时间内总耗时最多的方法。
火焰图怎么看
实操前,我们先学习一下火焰图的阅读方法,这里引用阮一峰大佬这篇博客里的一张火焰图:
图中的a、b、c…、i表示一个函数(java里面叫方法)。
首先我们看y轴,也就是按图的自上而下看,下面的方法调用了紧贴着它上层的方法。例如图中方法f调用了方法g,而方法d调用了方法e、f。
注意,由于火焰图是一个采样结果,所以不一定说方法d执行一次就会同时执行到e、f,比如d里面可能有个if判断:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17
| class XX{ public void d(int input) { if (input > 100) { e(input); } else { f(input); } }
public void e(int input){ }
public void f(int input){ } }
|
而在采样的这段时间内,由于有不同的input,导致d->e、d->f路径都被走过。
接下来我们看x轴,也就是看每个方法所在矩形的宽度。宽度越宽代表着执行时间越长,但是要减掉上一层的宽度,也就是把调用其他方法的时间扣除掉才是此方法的实际耗时:
所以,方法的耗时如下(单位是像素~~):
e: 92
g: 212
d: 390-212-92=86,即方法d的实际耗时需要减掉调用f、e的耗时
i: 100
所以,在排查性能问题和优化时,首先去检查最耗时的g,再依次去检查 i、e、d、等等。
arthas生成火焰图
这里的arthas不是魔兽里的洛丹伦孝子,是阿里开源的一个java线上监测工具。
1、下载:https://arthas.aliyun.com/doc/download.html
2、java -jar arthas-boot.jar
启动arthas,会有一个列表列出当前在运行的java进程,输入序号(不是进程号)进入此进程的监控命令行。
3、输入profiler start
开始采样
4、采样一段时间后,输入profiler stop
结束采样,会生成一个html文件,在把这个html拖到chrome里就能看到火焰图了。
这个火焰图是可以交互的,例如左上角的放大镜按钮可以用来高亮出包含关键字的矩形,如果方法调用层次太深,也可以点击某个矩形,只查看此矩形之上的部分。
jprofiler
jprofiler是一个性能分析神器,安装好后,按如下步骤即可执行java程序CPU运行情况的统计和实时展现:
start center -> quickly attach -> 选择对应java进程 -> samping -> ok -> cpu views -> start recording
jprofiler也可以和arthas联动,运行如下命令后得到一个jrf,然后把jrf丢进jprofiler里也能查看CPU情况:
| profiler start -f /mnt/e/%t.jfr -d 10
|
详见这里