当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的情况
打印结果如下:
# 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进制:
# printf "0x%x\n" 34
0x22
最后,我们去查找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判断:
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进程,输入序号(不是进程号)进入此进程的监控命令行。
(补充,如果你的机器上装了多个jdk,或者环境变量没配等情况,会出现jps命令找不到,这时候直接 <java_path>/bin/java -jar arthas-boot.jar 进程号 即可)
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
本文采用 CC BY-SA 4.0 协议 ,转载请注明原始链接: https://blog.wowtools.org/2023/03/30/2023-03-30-java-find-slow-code/