Performance problems are always a problem for engineers. There are various kinds of slow processing. If one process is simply heavier than the threshold value, or because it is a batch, each process is not so slow, but it will be slow due to chiritsumo. Especially the latter is quite troublesome to identify. Even if you use Flight Recorder, it is quite troublesome to find out what is slower than plain Java, and the introduction of full-scale APM tends to be a big deal.
So, this time I tried to see if I could use AspectJ to trace slow methods. You can get the sample code from the following. https://github.com/koduki/example-aspectj
AspectJ is a Java library for AOP and aspect-oriented programming. Roughly speaking, it is "a method of embedding cross-cutting concerns (aspects) in multiple areas such as logging and permission checking into existing processing". It was quite popular as a method of complementing object orientation for a while, but it seems that I don't say much these days. It may be because the FW and the like are good for the things mentioned in the example, so it is no longer an area that individual engineers care about.
This time, by creating an aspect of "logging slow methods", I will try to output logs without modifying the existing processing of the measurement target.
Basically, you can develop with ordinary Java code, so you can easily start development with NetBeans + Maven. pom.xml looks like this. Note that it is necessary to add Plugin as well as dependency.
<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
<modelVersion>4.0.0</modelVersion>
<groupId>cn.orz.pascal</groupId>
<artifactId>example-aspectj</artifactId>
<version>0.1</version>
<packaging>jar</packaging>
<properties>
<project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
<maven.compiler.source>1.8</maven.compiler.source>
<maven.compiler.target>1.8</maven.compiler.target>
</properties>
<dependencies>
<dependency>
<groupId>org.aspectj</groupId>
<artifactId>aspectjrt</artifactId>
<version>1.8.13</version>
</dependency>
</dependencies>
<build>
<plugins>
<plugin>
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-dependency-plugin</artifactId>
<version>3.0.2</version>
<executions>
<execution>
<goals>
<goal>build-classpath</goal>
</goals>
<configuration>
<outputProperty>aspectj-weaver-path</outputProperty>
<includeGroupIds>org.aspectj</includeGroupIds>
<includeArtifactIds>aspectjweaver</includeArtifactIds>
</configuration>
</execution>
</executions>
</plugin>
<plugin>
<groupId>org.codehaus.mojo</groupId>
<artifactId>aspectj-maven-plugin</artifactId>
<version>1.11</version>
<dependencies>
<dependency>
<groupId>org.aspectj</groupId>
<artifactId>aspectjtools</artifactId>
<version>1.8.13</version>
</dependency>
</dependencies>
<executions>
<execution>
<goals>
<goal>compile</goal>
</goals>
<configuration>
<complianceLevel>1.8</complianceLevel>
<outxml>true</outxml>
</configuration>
</execution>
</executions>
</plugin>
</plugins>
</build>
</project>
Continue to create the aspect. However, you can write it as a Java class just by adding @Aspect.
@Aspect
public class SlowMethodLogger {
private static final long LIMIT_TIME;
static {
String limit = System.getenv("SLOW_METHOD_LIMIT");
LIMIT_TIME = (limit == null) ? 0 : Long.parseLong(limit);
}
@Around("execution(* cn.orz.pascal.example.aspectj.*.*(..))")
public Object logging(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
long start = System.nanoTime();
try {
return proceedingJoinPoint.proceed();
} finally {
long end = System.nanoTime();
long time = end - start;
if (time >= LIMIT_TIME) {
int line = proceedingJoinPoint.getSourceLocation().getLine();
String method = proceedingJoinPoint.getSignature().toString();
System.out.println("SLOW_METHOD:" + method + "\tLINE:" + line + "\tTIME(ns):" + time);
}
}
}
}
It's a method that @Around embeds as an aspect called pointcut. This time, using @Around, the execution time is measured by executing the target method [proceedingJoinPoint.proceed ()]. It is a form to log only when the value is larger than LIMIT_TIME after execution.
The target to be embedded is specified by execution, and with this writing method, all subordinates under cn.orz.pascal.example.aspectj are recorded regardless of private / public.
If you simply output all the logs, it will not end as a bottleneck in the process of looping 100 million times, so it is necessary to put in some sampling mechanism for recording timing and logging timing. There is.
This time it is a sample, so I use System.out.println, but in reality it is better to use log4j2 or something.
Now, let's create an application to be measured. There is basically no need to know the aspect created earlier, let alone the AspectJ related library at the time of development. However, only the package must match the one specified in ʻexecution`. * Normally, the execution will be changed according to the measurement target.
package cn.orz.pascal.example.aspectj;
public class Main {
public static void main(String[] args) {
System.out.println("run");
Sub1 sub = new Sub1();
for (int i = 0; i < Integer.parseInt(args[0]); i++) {
sub.getProcess();
}
}
}
package cn.orz.pascal.example.aspectj;
public class Sub1 {
private long count = 0;
public void getProcess() {
getPrivateProcess();
}
private void getPrivateProcess() {
if (count % 3 == 0) {
try {
Thread.sleep(500);
} catch (InterruptedException ex) {
throw new RuntimeException(ex);
}
}
count += 1;
}
}
I made it assuming the case where Sub is called in the loop from Main and Sub is slow about once every three times.
First, run the application to be measured normally.
$ time SLOW_METHOD_LIMIT=500000000 java -cp "example-targetapp-0.1.jar" cn.orz.pascal.example.aspectj.Main 10
run
real 0m2.158s
user 0m0.015s
sys 0m0.000s
It's the expected time because 500ms makes 4 turns. Next, let's attach the aspect created earlier. Use javaagent for attachment as well as JFR and other APM systems.
$ time SLOW_METHOD_LIMIT=500000000 java -cp "aspectjrt-1.8.13.jar;example-aspectj-0.1.jar;example-targetapp-0.1.jar" -javaagent:asp ectjweaver-1.8.13.jar cn.orz.pascal.example.aspectj.Main 10
run
SLOW_METHOD:void cn.orz.pascal.example.aspectj.Sub1.getPrivateProcess() LINE:24 TIME(ns):500278916
SLOW_METHOD:void cn.orz.pascal.example.aspectj.Sub1.getProcess() LINE:20 TIME(ns):503194581
SLOW_METHOD:void cn.orz.pascal.example.aspectj.Sub1.getPrivateProcess() LINE:24 TIME(ns):500142922
SLOW_METHOD:void cn.orz.pascal.example.aspectj.Sub1.getProcess() LINE:20 TIME(ns):501776905
SLOW_METHOD:void cn.orz.pascal.example.aspectj.Sub1.getPrivateProcess() LINE:24 TIME(ns):500856763
SLOW_METHOD:void cn.orz.pascal.example.aspectj.Sub1.getProcess() LINE:20 TIME(ns):502748879
SLOW_METHOD:void cn.orz.pascal.example.aspectj.Main.main(String[]) LINE:15 TIME(ns):2021801158
real 0m2.459s
user 0m0.000s
sys 0m0.000s
I measured it three times each, but in this case there wasn't much difference in performance. However, since it is a case-by-case basis, it is necessary to apply it to the code actually used and decide on the actual introduction.
$ time SLOW_METHOD_LIMIT=500000000 java -cp "aspectjrt-1.8.13.jar;example-aspectj-0.1.jar;example-targetapp-0.1.jar" -javaagent:asp ectjweaver-1.8.13.jar cn.orz.pascal.example.aspectj.Main 1000 > /dev/null
real 2m47.602s
$ time SLOW_METHOD_LIMIT=500000000 java -cp "aspectjrt-1.8.13.jar;example-aspectj-0.1.jar;example-targetapp-0.1.jar" -javaagent:asp ectjweaver-1.8.13.jar cn.orz.pascal.example.aspectj.Main 1000 > /dev/null
real 2m47.591s
$ time SLOW_METHOD_LIMIT=500000000 java -cp "aspectjrt-1.8.13.jar;example-aspectj-0.1.jar;example-targetapp-0.1.jar" -javaagent:asp ectjweaver-1.8.13.jar cn.orz.pascal.example.aspectj.Main 1000 > /dev/null
real 2m47.572s
$ time java -cp "aspectjrt-1.8.13.jar;example-aspectj-0.1.jar;example-targetapp-0.1.jar" cn.orz.pascal. example.aspectj.Main 1000 > /dev/null
real 2m47.327s
$ time java -cp "aspectjrt-1.8.13.jar;example-aspectj-0.1.jar;example-targetapp-0.1.jar" cn.orz.pascal. example.aspectj.Main 1000 > /dev/null
real 2m47.319s
$ time java -cp "aspectjrt-1.8.13.jar;example-aspectj-0.1.jar;example-targetapp-0.1.jar" cn.orz.pascal. example.aspectj.Main 1000 > /dev/null
real 2m47.304s
This time I tried using AspectJ to identify slow methods. It is easier to introduce than a full-scale APM, so it is convenient when you want to quickly put it in a development environment or verification environment. Also, it seems easier to do it with AOP than to make it yourself, such as the mechanism of distributed tracing. I haven't tried it so much, but now I realize the convenience of AspectJ ...
Then Happy Hacking!
Recommended Posts