LoginSignup
4
4

More than 5 years have passed since last update.

@koduki

ボトルネックを計測せよ！ AspectJで遅いメソッドだけをトレースする方法

Posted at

性能問題はエンジニアの悩みの常ですね。遅い処理と言っても色々あります。
単純に一つの処理が閾値より重い場合、あるいはバッチなので1つ1つの処理はそこまで遅く無いけどチリツモで遅くなってしまうケース。
特に後者は特定も結構面倒です。Flight Recorderを使うにしても素のJavaに対してだとどこが遅いか探すのは結構面倒ですし、本格的なAPMの導入はどうしても大掛かりになりがちです。

なので、今回はAspectJを使って遅いメソッドをトレースすることが出来ないかを試してみました。
サンプルコードは下記より取得できます。
https://github.com/koduki/example-aspectj

そもそもAspectJって？

AspectJはAOP、アスペクト指向を実現するためのJavaのライブラリです。
めっちゃ乱暴に説明すると「ロギングとかパーミッションチェックとかの複数の領域への横断的関心事(アスペクト)を既存の処理に埋め込む手法」です。
オブジェクト指向を補完する手法として一時結構盛んだったのですが、最近はあまり言わない印象ですね。
例に挙げたようなことはFWとかが良しなにしてくれるので個々のエンジニアが気にする領域ではなくなったからかもしれません。

今回は「遅いメソッドをロギングする」というアスペクトを作る事で、計測対象の既存処理に手を加えずにログが出るようにしてみます。

SlowMethodLoggerアスペクトの作成

基本的には普通のJavaのコードで開発できるのでNetBeans + Mavenで簡単に開発を始めれます。
pom.xmlはこんな感じ。依存だけじゃなくてPluginも追加してやる必要があるので注意。

<?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>

引き続き、アスペクトを作成します。といっても@Aspectを付けるだけでJavaのクラスとして記述することが出来ます。

@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);
            }
        }
    }   
}

@Aroundがポイントカットと呼ばれるアスペクトとして埋め込むメソッドですね。今回は@Aroundを使い対象のメソッド実行[proceedingJoinPoint.proceed()]で実行時間を計測する作りにしています。実行後にLIMIT_TIMEより大きな値の時だけログに出す形ですね。
executionで埋め込む対象を指定しており、この書き方だとprivate/public関わらずにcn.orz.pascal.example.aspectj配下をすべて記録します。

単純にすべてのログを出してしまうと1億回ループしてる処理の中とかだとそれ自体がボトルネックになって終わらないので、記録タイミングやロギングタイミングは何らかのサンプリングする仕組みを入れておく必要があります。

今回はサンプルならのでSystem.out.println使ってますが実際はlog4j2とかを使ったほうが性能的にも良いかと.

計測対象アプリケーションの作成

では、計測対象のアプリケーションを作成してみます。こちらは開発時にAspectJ関連のライブラリはもちろん、先ほど作ったアスペクトについて知る必要も基本ありません。
ただし、パッケージだけはexecutionで指定したのものと合わせる必要があります。※ 通常は計測対象に合わせてexecutionを変えることになると思います。

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;
    }
}

MainからSubがループの中で呼ばれていて、Subは3回に1回ほど遅いというケースを想定して作ってみました。

実行してみる

まずは普通に計測対象のアプリを実行します。

$ 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

500msが4回動くので期待値の時間ですね。続いて先ほど作成したアスペクトをアタッチしてみましょう。
アタッチにはJFRやその他APM系と同様にjavaagentを使用します。

$ 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

性能劣化具合を計測

3回ずつ測ってみましたが、今回のケースではあまり性能差は出なかったでね。とはいえケースバイケースでしょうから実際に使うコードに適用して本番導入等は決める必要がありますね。

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

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

まとめ

今回は遅いメソッドを特定するためにAspectJを使ってみました。本格的なAPMよりも導入が手軽なので開発環境や検証環境にサクッと入れたいときには便利でしょう。
また、分散トレーシングの仕組みとかもちまちま自前で作るよりAOPでやったほうが簡単そうですね。あんまり試してなかったけど今更AspectJの便利さに気付く...

それではHappy Hacking!

4
4
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
4
4