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/