I don’t know if you have encountered this situation. After writing the interface business logic, I used postman to adjust it. I found that the interface response time was very long, so I had to optimize the interface. However, at this time, the interface code is often more logically complex and has many call levels, making it difficult to locate the code blocks that take a long time.
How do you locate the time-consuming code blocks in this situation?
I see many people directly use System.currentTimeMillis() to bury the code.
public static void main(String[] args) {
Long startTime = System.currentTimeMillis();
exec();
Long endTime = System.currentTimeMillis();
log.info("exec method execution time: {}ms", endTime - startTime);
}
Or using the StopWatch printing method is time-consuming
public static void main(String[] args) throws InterruptedException {
StopWatch stopWatch = new StopWatch();
stopWatch.start("exec");
exec();
stopWatch.stop();
System.out.println(stopWatch.prettyPrint());
}
These two methods are essentially the same. They both manually bury points in the code block and print out the time-consuming method. This method is not only time-consuming and labor-intensive, but also intrusive to the code. After fixing the problem, deleting the code is still a hassle. thing
The following describes how to locate time-consuming code blocks through Arthas
Introduction to Arthas
Arthas is a Java diagnostic tool open sourced by Alibaba. It can check the application load, memory, gc, thread and other status information in real time without restarting the JVM. It can also check the input and output parameters of method calls and the time taken for method calls in real time. wait
Arthas Quick Start
Directly download the Arthasjar package and then start it with the java -jar command
$ curl -O https://arthas.aliyun.com/arthas-boot.jar $ java -jar arthas-boot.jar
When Arthas starts, it will print out the currently running java process.
$ 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
Then we can select the java process we need to attach. Here we select 1 and press Enter. Arthas will attach to the target process and output the log:
[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
At this point, Arthas has been attached to our target process. We try to use the dashboad command to view the process information.
$ 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
You can see that the dashboad command will display a real-time data panel, listing the data indicators we usually care about, such as memory usage, gc status, etc.
For more commands, please refer to the command list on the official website.
Use Trace command to count method time consumption
The trace command can actively search for the method calling path corresponding to class-pattern/method-pattern, render and count all performance overhead on the entire calling link, and track the calling link.
For example, the following interface
@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);
}
}
Start the Arthas process and attach it to our springboot project, and then use the trace command to track the calling of the method.
$ trace com.huangxy.springstudy.controller.HelloController test
The first parameter of the trace method is the path of the class to be attached, and the second parameter is the method name. Then we call the interface once, and we can see the call stack of the hello method and its time consumption.
It can be seen that the most time-consuming thing here is the tow() method, which took 1029ms, accounting for 90.73%.
However, it should be noted that the trace command will only trace the sub-calls in the matched function, and will not trace down multiple layers. If you need to trace multiple layers, you can use regular expressions to match multiple functions, such as
$ trace -E com.huangxy.springstudy.controller.HelloController test|two
Now it is clearer to locate that the method that takes too long is the three() method. After locating the method, just optimize the time-consuming code block in a targeted manner.