java排查耗时代码的几种方式
当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/