不知道大家有没有遇到这种情况,接口业务逻辑写完后,用 postman 一调,发现接口响应时间好长,不得不对接口进行优化。但是此时接口的代码往往逻辑比较复杂,调用层次也比较多,很难定位到耗时较长的代码块。
遇到这种情况大家都是如何定位耗时代码块的呢?
我看到很多人都是直接用System.currentTimeMillis()对代码进行埋点:
public static void main(String[] args) {
Long startTime = System.currentTimeMillis();
exec();
Long endTime = System.currentTimeMillis();
log.info("exec 方法执行耗时:{}ms", endTime - startTime);
}
或者用StopWatch打印方法耗时:
public static void main(String[] args) throws InterruptedException {
StopWatch stopWatch = new StopWatch();
stopWatch.start("exec");
exec();
stopWatch.stop();
System.out.println(stopWatch.prettyPrint());
}
这两种方法本质上是一样的,都是通过手动在代码块上进行埋点,打印出方法的耗时,该方法不仅费时费力,而且对代码有侵入,修复问题后删掉代码还是一个麻烦事。
下面介绍如果通过Arthas定位耗时代码块。
Arthas 简介
Arthas是阿里开源的一款 Java 诊断工具,可以在无需重启 JVM 的情况下,实时查看应用 load、内存、gc、线程等状态信息,还能实时查看方法调用入参、出参、方法调用耗时等。
Arthas 快速开始
直接下载Arthasjar 包,然后用java -jar命令启动即可:
$ curl -O https://arthas.aliyun.com/arthas-boot.jar
$ java -jar arthas-boot.jar
Arthas启动的时候,会打印出当前运行的 java 进程:
$ java -jar arthas-boot.jar
[INFO] JAVA_HOME: /Library/Java/JavaVirtualMachines/jdk1.8.0_351.jdk/Contents/Home/jre
[INFO] arthas-boot version: 3.6.9
[INFO] Found existing java process, please choose one and input the serial number of the process, eg : 1. Then hit ENTER.
* [1]: 12512 com.huangxy.springstudy.SpringStudyApplication
[2]: 12511 org.jetbrains.jps.cmdline.Launcher
然后可以选择我们需要 attach 的 java 进程,这里我们选择 1,然后按回车。Arthas 会 attach 到目标进程上,并输出日志:
[INFO] arthas home: /Users/huangxiaoyu/.arthas/lib/3.6.9/arthas
[INFO] Try to attach process 12512
[INFO] Attach process 12512 success.
[INFO] arthas-client connect 127.0.0.1 3658
,---. ,------. ,--------.,--. ,--. ,---. ,---.
/ O \ | .--. ''--. .--'| '--' | / O \ ' .-'
| .-. || '--'.' | | | .--. || .-. |`. `-.
| | | || |\ \ | | | | | || | | |.-' |
`--' `--'`--' '--' `--' `--' `--'`--' `--'`-----'
wiki https://arthas.aliyun.com/doc
tutorials https://arthas.aliyun.com/doc/arthas-tutorials.html
version 3.6.9
main_class com.huangxy.springstudy.SpringStudyApplication
pid 12512
time 2023-07-25 09:14:22
到这里,Arthas 已经 attach 到我们的目标进程上了,我们尝试使用dashboad命令,查看进程的信息:
$ dashboard
ID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPT DAEMON
36 DestroyJavaVM main 5 RUNNABLE 0.0 0.000 0:1.748 false false
-1 C1 CompilerThread3 - -1 - 0.0 0.000 0:0.761 false true
-1 VM Periodic Task Thread - -1 - 0.0 0.000 0:0.237 false true
24 http-nio-8081-exec-1 main 5 WAITING 0.0 0.000 0:0.098 false true
-1 VM Thread - -1 - 0.0 0.000 0:0.071 false true
25 http-nio-8081-exec-2 main 5 WAITING 0.0 0.000 0:0.055 false true
54 arthas-NettyHttpTelnetBootstra system 5 RUNNABLE 0.0 0.000 0:0.054 false true
-1 GC task thread#8 (ParallelGC) - -1 - 0.0 0.000 0:0.043 false true
-1 GC task thread#1 (ParallelGC) - -1 - 0.0 0.000 0:0.043 false true
-1 GC task thread#7 (ParallelGC) - -1 - 0.0 0.000 0:0.042 false true
-1 GC task thread#6 (ParallelGC) - -1 - 0.0 0.000 0:0.042 false true
-1 GC task thread#0 (ParallelGC) - -1 - 0.0 0.000 0:0.042 false true
-1 GC task thread#9 (ParallelGC) - -1 - 0.0 0.000 0:0.042 false true
-1 GC task thread#2 (ParallelGC) - -1 - 0.0 0.000 0:0.042 false true
-1 GC task thread#3 (ParallelGC) - -1 - 0.0 0.000 0:0.042 false true
-1 GC task thread#5 (ParallelGC) - -1 - 0.0 0.000 0:0.042 false true
-1 GC task thread#4 (ParallelGC) - -1 - 0.0 0.000 0:0.042 false true
Memory used total max usage GC
heap 83M 432M 7282M 1.14% gc.ps_scavenge.count 4
ps_eden_space 72M 212M 2688M 2.69% gc.ps_scavenge.time(ms) 24
ps_survivor_space 0K 21504K 21504K 0.00% gc.ps_marksweep.count 2
ps_old_gen 10M 199M 5461M 0.20% gc.ps_marksweep.time(ms) 61
nonheap 53M 56M -1 94.71%
code_cache 6M 7M 240M 2.87%
metaspace 40M 43M -1 94.45%
compressed_class_space 5M 5M 1024M 0.53%
direct 16K 16K - 100.01%
mapped 0K 0K - 0.00%
Runtime
os.name Mac OS X
os.version 13.0.1
java.version 1.8.0_351
java.home /Library/Java/JavaVirtualMachines/jdk1.8.0_351.jdk/Contents/
Home/jre
systemload.average 3.80
processors 12
可以看到dashboad命令会展示一个实时的数据面板,列出了我们平时比较关心的数据指标,如内存使用量,gc 状态等。
使用 Trace 命令统计方法耗时
trace命令能主动搜索class-pattern/method-pattern对应的方法调用路径,渲染和统计整个调用链路上的所有性能开销和追踪调用链路。
比如下面接口:
@RestController
public class HelloController {
@GetMapping("/test")
public String test() throws InterruptedException {
one();
two();
return "hello";
}
private void two() throws InterruptedException {
Thread.sleep(20);
three();
}
private void three() throws InterruptedException {
Thread.sleep(1000);
}
private void one() throws InterruptedException {
Thread.sleep(100);
}
}
启动Arthas进程,并 attach 到我们的 springboot 项目上,接着使用trace命令跟踪方法的调用情况:
$ trace com.huangxy.springstudy.controller.HelloController test
trace方法第一个参数是要 attach 的类的路径,第二个参数是方法名称,接着我们调用一遍接口,就能看到 hello 方法的调用堆栈及其耗时
可以看到,这里耗时比较严重的是tow()方法,花了 1029ms,占了 90.73% 的比重。
不过需要注意的是,trace 命令只会 trace 匹配到的函数里的子调用,并不会向下 trace 多层,如果需要 trace 多层,可以用正则匹配多个函数,如:
$ trace -E com.huangxy.springstudy.controller.HelloController test|two
这下更清晰的定位到,导致耗时过长的方法是three()方法,定位到方法后,针对性的优化耗时代码块即可。
最后,推荐一款应用开发神器
关于目前低代码在技术领域很活跃!
低代码是什么?一组数字技术工具平台,能基于图形化拖拽、参数化配置等更为高效的方式,实现快速构建、数据编排、连接生态、中台服务等。通过少量代码或不用代码实现数字化转型中的场景应用创新。它能缓解甚至解决庞大的市场需求与传统的开发生产力引发的供需关系矛盾问题,是数字化转型过程中降本增效趋势下的产物。
这边介绍一款好用的低代码平台——JNPF快速开发平台。近年在市场表现和产品竞争力方面表现较为突出,采用的是最新主流前后分离框架(SpringBoot+Mybatis-plus+Ant-Design+Vue3)。代码生成器依赖性低,灵活的扩展能力,可灵活实现二次开发。
以JNPF为代表的企业级低代码平台为了支撑更高技术要求的应用开发,从数据库建模、Web API构建到页面设计,与传统软件开发几乎没有差异,只是通过低代码可视化模式,减少了构建“增删改查”功能的重复劳动,还没有了解过低代码的伙伴可以尝试了解一下。
应用:https://www.jnpfsoft.com/?csdn
有了它,开发人员在开发过程中就可以轻松上手,充分利用传统开发模式下积累的经验。所以低代码平台对于程序员来说,有着很大帮助。