Measure the bottleneck! How to trace only slow methods in AspectJ

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

What is AspectJ in the first place?

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.

Creating a SlowMethodLogger aspect

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.

Creation of measurement target application

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.

Try to run

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

Measure the degree of performance deterioration

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.

With Agent

$ 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

No Agent

$ 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

Summary

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

Measure the bottleneck! How to trace only slow methods in AspectJ
How to get the date in java
How to debug the processing in the Ruby on Rails model only on the console
How to check the logs in the Docker container
How to add sound in the app (swift)
How to build the simplest blockchain in Ruby
How to check Rails commands in the terminal
How to implement UICollectionView in Swift with code only
How to set the display time to Japan time in Rails
[Java] How to omit the private constructor in Lombok
Organized how to interact with the JDK in stages
How to specify the resource path in HTML import
How to debug the generated jar file in Eclipse
[Rails] How to display an image in the view
How to get the class name / method name running in Java
How to correctly check the local HTML file in the browser
How to use the getter / setter method (in object orientation)
How to separate words in names in classes, methods, and variables
How to set chrony when the time shifts in CentOS7
How to connect the strings in the List separated by commas
How to create a placeholder part to use in the IN clause
How to retrieve the hash value in an array in Ruby
Uppercase only the specified range with substring. (How to use substring)
How to add the same Indexes in a nested array
How to mock some methods of the class under test
How to derive the last day of the month in Java
How to disable existing selected items in the select box
[Rails] How to display information stored in the database in view
[Rails / Routing] How to refer to the controller in the directory you created
[jOOQ] How to CASE WHEN in the WHERE / AND / OR clause
How to get the id of PRIMAY KEY auto_incremented in MyBatis
How to install the language used in Ubuntu and how to build the environment
[Behavior confirmed in December 2020] How to implement the alert display function
How to store the information entered in textarea in a variable in the method
How to solve the unknown error when using slf4j in Java
kotlin & Java: How to hide the toolbar only for specific fragments
[Rails] How to reset the database in production environment (Capistrano version)
How to call multiple names at once in the same category
How to get the length of an audio file in java
How to increment the value of Map in one line in Java
How to write the view when Vue is introduced in Rails?
[Ruby on Rails] How to log in with only your name and password using the gem devise
How to use the link_to method
How to use Lombok in Spring
How to find May'n in XPath
How to use the include? method
How to hide scrollbars in WebView
How to use the form_with method
How to run JUnit in Eclipse
Pass the i18n locale to JavaScript
How to iterate infinitely in Ruby
[Rails] How to write in Japanese
How to find the average angle
How to run Ant in Gradle
How to master programming in 3 months
How to use the wrapper class
How to learn JAVA in 7 days
How to get parameters in Spark
How to call classes and methods
How to install Bootstrap in Ruby
How to use InjectorHolder in OpenAM