コンテンツにスキップ

async-profiler を使用したアプリケーションパフォーマンスのチューニング

Info

Java プロファイリングでは、JFR（Java Flight Recording）による取得のほかに、async-profiler を使用する方法もあります。

async-profiler の概要

async-profiler は、Safepoint bias problem が発生しない低オーバーヘッドの Java サンプリングプロファイラです。HotSpot の特殊な API を利用してスタック情報やメモリ割り当て情報を収集し、OpenJDK、Oracle JDK、およびその他の HotSpot ベースの Java 仮想マシン上で動作します。

async-profiler では以下のイベントを収集できます。

  • CPU cycles
  • ハードウェアおよびソフトウェアパフォーマンスカウンター（cache misses、branch misses、page faults、context switches など）
  • Java ヒープの割り当て
  • Contented lock attempts（Java object monitors や ReentrantLocks を含む）

1. CPU プロファイリング

このモードでは、プロファイラは Java メソッド、ネイティブ コール、JVM コード、カーネル 関数を含むスタックトレースサンプルを収集します。

一般的な方法は、perf_events が生成するコールスタックを受け取り、AsyncGetCallTrace が生成するコールスタックとマッチングすることで、Java コードとネイティブコードの両方の正確なプロファイルを生成することです。
さらに、async-profiler は AsyncGetCallTrace が失敗する一部のケースでスタックトレースを復元する回避策も提供します。

perf_events を直接使用してアドレスを Java メソッド名に変換する Java エージェントと比較した場合の利点は次のとおりです。

  • 古い Java バージョンでも動作します。-XX:+PreserveFramePointer が不要で、これは JDK 8u60 以降でのみ利用可能です。
  • -XX:+PreserveFramePointer によるパフォーマンスオーバーヘッド（まれに最大 10% に達する場合があります）が発生しません。
  • Java コードアドレスをメソッド名にマッピングするためのマップファイルを生成する必要がありません。
  • インタプリタフレームでも動作します。
  • ユーザースペーススクリプトでさらに処理するために perf.data ファイルを書き出す必要がありません。

2. メモリ割り当てプロファイリング

プロファイラは、CPU を消費するコードを検出する代わりに、最も多くのヒープメモリを割り当てている呼び出しサイトを収集するように設定できます。

async-profiler は、バイトコードインスツルメンテーションや高コストな DTrace プローブのような、パフォーマンスに大きな影響を与える可能性のある侵襲的な技術を使用しません。また、エスケープ解析や割り当て除去などの JIT 最適化を妨げることもありません。実際のヒープ割り当てのみを測定します。

このプロファイラは TLAB 駆動型サンプリング 機能を備えています。HotSpot 固有のコールバックに依存して、以下の 2 種類の通知を受け取ります。

  • 新しく作成された TLAB（フレームグラフでは水色のフレーム）内でオブジェクトが割り当てられたとき。
  • TLAB 外のスローパス上でオブジェクトが割り当てられたとき（茶色のフレーム）。

これは、割り当てごとにカウントするのではなく、N kB ごとの割り当て（N は TLAB の平均サイズ）のみをカウントすることを意味します。これにより、ヒープサンプリングは非常に低コストになり、本番環境に適しています。一方で、収集データは不完全になる可能性がありますが、実際には通常、最も高い割り当て元を反映します。

サンプリング間隔は --alloc オプションで調整できます。例：--alloc 500k は、平均 500 KB の割り当てごとに 1 回サンプリングします。ただし、TLAB サイズより小さい間隔は効果がありません。
サポートされる最小 JDK バージョンは、TLAB コールバックが登場した 7u40 です。

3. Wall-clock プロファイリング

-e wall オプションは、async-profiler に指定された期間ごとにすべてのスレッドを平均的にサンプリングさせます。スレッドの状態（実行中、スリープ中、ブロック中）は問いません。これは、アプリケーションの起動時間を分析する場合などに役立ちます。

Wall-clock プロファイラは、スレッド単位モード（-t）で最も有用です。

例：./profiler.sh -e wall -t -i 5ms -f result.html 8983

4. Java メソッドプロファイリング

-e ClassName.methodName オプションは、指定された Java メソッドをインスツルメントし、このメソッドのすべての呼び出しをスタックトレースで記録します。

  • 非ネイティブメソッドの場合：例：-e java.util.Properties.getProperty は、getProperty メソッドのすべての呼び出し元をプロファイリングします。
  • ネイティブメソッドの場合は、代わりにハードウェアブレークポイントイベントを使用します。例：-e Java_java_lang_Throwable_fillInStackTrace

注意: 実行時に async-profiler をアタッチする場合、非ネイティブ Java メソッドの最初のインスツルメンテーションは、すべてのコンパイル済みメソッドのデオプティマイゼーションを引き起こす可能性があります。後続のインスツルメンテーションは 関連コード のみをフラッシュします。

async-profiler をエージェントとしてアタッチする場合、大規模な CodeCache フラッシュは発生しません。

以下は、プロファイリングに役立つ可能性のあるネイティブメソッドの例です。

  • G1CollectedHeap::humongous_obj_allocate – G1 GC の humongous allocation（巨大メモリ割り当て） を追跡します。
  • JVM_StartThread – 新しいスレッドの作成を追跡します。
  • Java_java_lang_ClassLoader_defineClass1 – クラスのロードを追跡します。

ディレクトリ構造

image.png

起動方法

async-profiler は JVMTI（JVM Tool Interface）に基づいて開発されたエージェントであり、2 つの起動方法をサポートしています。

    1. Java プロセスの起動とともに開始し、共有ライブラリを自動的にロードします。
    1. プログラム実行中に attach API を介して動的にロードします。

1 起動時にロード

注意

起動時のロードは、アプリケーションの起動時に分析を行う場合にのみ適しており、実行中にアプリケーションをリアルタイムで分析することはできません。

JVM 起動後すぐにコードを分析する必要がある場合、profiler.sh スクリプトを使用する代わりに、コマンドラインで async-profiler をエージェントとして指定できます。例：

$ java -agentpath:async-profiler-2.8.3/build/libasyncProfiler.so=start,event=alloc,file=profile.html -jar ...

image.png

エージェントライブラリは JVMTI パラメータインターフェースを介して設定され、パラメータ文字列の形式はソースコードで説明されています。

  • profiler.sh スクリプトは、実際にコマンドライン引数をこの形式に変換します。
    例：-e wall は event=wall に、-f profile.html は file=profile.html に変換されます。
  • profiler.sh スクリプトによって直接処理されるパラメータもあります。
    例：-d 5 は 3 つの操作を含み、start コマンドでプロファイラエージェントをアタッチし、5 秒間スリープし、その後 stop コマンドで再度エージェントをアタッチします。 image.png

2 実行時にロード

多くの場合、アプリケーションの実行中に分析を行う必要があります。

./profiler.sh -e alloc -d 10 -f out.html pid

image.png

その時点のメモリ使用割り当て状況を確認できます。reader が 99.77% のメモリを割り当てています。
現在のアプリケーションがサポートするイベントを表示します。

./profiler.sh list jps

image.png

注意

HTML 形式は単一イベントのみをサポートし、JFR 形式は複数イベントの出力をサポートします。

async-profiler と Guance

Guance は async-profiler と深く統合されており、データを DataKit に送信し、Guance の強力な UI および分析機能を活用して、ユーザーがさまざまな次元で分析できるようにします。

関連する統合ドキュメントを参照してください。

ケーススタディ

キーと値のペア（key:value）形式で保存された大容量ファイルを高速に読み取り、Map に解析します。

1 大容量ファイルの書き込み

import java.io.FileWriter;

public class MapGenerator {
    public static String fileName = "/opt/profiling/map-info.txt";
    public static void main(String[] args) {

        try (FileWriter writer = new FileWriter(fileName)) {
            writer.write("");//元のファイル内容をクリア
            for (int i = 0; i < 16500000; i++) {
                writer.write("name"+i+":"+i+"\n");
            }
            writer.flush();
            System.out.println("write success!");
        } catch (Exception e) {
            e.printStackTrace();
        }

    }
}

2 大容量ファイルの読み取り

private static Map<String,Long> readMap(String fileName) throws IOException {
        Map<String,Long> map = new HashMap<>();
        try(BufferedReader br = new BufferedReader(new FileReader(fileName))) {
            for (String line ;(line = br.readLine())!=null;){
                String[] kv = line.split(":",2);
                String key = kv[0].trim();
                String value = kv[1].trim();
                map.put(key,Long.parseLong(value));
            }
        }
        return map;
    }

MapReader を実行すると、全体の処理時間は 15.5 秒です。

[root@ip-172-31-19-50 profiling]# java MapReader
Profiling started
Read 16500000 elements in 15.531 seconds

MapReader の実行と同時に async-profiler を実行し、プロファイリング情報を Guance プラットフォームにプッシュして分析します。

[root@ip-172-31-19-50 async-profiler-2.8.3-linux-x64]# DATAKIT_URL=http://localhost:9529 APP_ENV=test APP_VERSION=1.0.0 HOST_NAME=datakit PROFILING_EVENT=cpu,alloc,lock PROFILING_DURATION=10 PROCESS_ID=`ps -ef |grep java|grep springboot|grep -v grep|awk '{print $2}'` SERVICE_NAME=demo bash collect.sh
profiling process 16134

Profiling for 10 seconds
Done
generate profiling file successfully for MapReader, pid 16134
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  110k  100    64  100  110k     99   172k --:--:-- --:--:-- --:--:--  172k
Info: send profile file to datakit successfully
[root@ip-172-31-19-50 async-profiler-2.8.3-linux-x64]#

image.png

image.png

結果 
メモリ割り当て状況を確認すると、合計 3.79 GB のメモリが生成されました。

private static Map<String,Long> readMap(String fileName) throws IOException {
        Map<String,Long> map = new HashMap<>();
        try(BufferedReader br = new BufferedReader(new FileReader(fileName))) {
            for (String line ;(line = br.readLine())!=null;){
                int sep = line.indexOf(":");
                String key = trim(line,0,sep);
                String value = trim(line,sep+1,line.length());
                map.put(key,Long.parseLong(value));
            }
        }
        return map;
    }

    private static String trim(String line,int from,int to){
        while (from<to && line.charAt(from) <= ' '){
            from ++;
        }
        while (to > from && line.charAt(to-1) <= ' '){
            to--;
        }
        return line.substring(from,to);
    }

MapReader2 を実行すると、全体の処理時間は 11.257 秒です。

[root@ip-172-31-19-50 profiling]# java MapReader2
Profiling started
Read 16500000 elements in 11.257 seconds
[root@ip-172-31-19-50 profiling]#

MapReader2 の実行と同時に async-profiler を実行し、プロファイリング情報を Guance プラットフォームにプッシュして分析します。実行コマンドは方法 1 と同じです。

image.png

結果 
メモリ割り当て状況を確認すると、合計 2.49 GB のメモリが生成されました。方法 1 と比較して 1.3 GB のメモリを節約し、所要時間も約 4 秒短縮されました。

private static Map<String,Long> readMap(String fileName) throws IOException {
        Map<String,Long> map = new HashMap<>(600000);
        try(BufferedReader br = new BufferedReader(new FileReader(fileName))) {
            for (String line ;(line = br.readLine())!=null;){
                int sep = line.indexOf(":");
                String key = trim(line,0,sep);
                String value = trim(line,sep+1,line.length());
                map.put(key,Long.parseLong(value));
            }
        }
        return map;
    }

    private static String trim(String line,int from,int to){
        while (from<to && line.charAt(from) <= ' '){
            from ++;
        }
        while (to > from && line.charAt(to-1) <= ' '){
            to--;
        }
        return line.substring(from,to);
    }

image.png

結果 
操作手順は方法 2 と同じです。MapReader3 は MapReader2 と異なり、MapReader3 では Map の初期化時に容量を指定しているため、方法 3 は方法 2 よりも 0.3 GB のメモリを節約し、方法 1 よりも 1.6 GB のメモリを節約しています。

3 メトリクスとトレースを組み合わせた連携分析

上記のデモコードはライフサイクルが非常に短いため、全体的な観測（JVM 関連メトリクス、ホスト関連メトリクスなど）を行うことができません。そのため、デモコードを Spring Boot アプリケーションに移行し、APM（ddtrace-agent）を JVM メトリクスおよび async-profiler と組み合わせて使用することで、メトリクス（JVM/ホスト）、トレース（現在のトレース状況）、プロファイリング（パフォーマンス分析） の 3 つの次元から観測可能にします。対応する URL にアクセスすることで、async-profiler による分析を実行します。

  • Profiling ビュー

image.png

  • JVM ビュー

image.png

  • Trace ビュー

image.png

4 まとめ

image.png

TLAB について

TLAB は Thread Local Allocation Buffer の略で、スレッドローカル割り当てバッファです。これは Java メモリ割り当ての概念であり、スレッドがオブジェクトを作成する際にメモリを割り当てるためのスレッド専用のメモリ割り当て領域です。主にマルチスレッド環境において、スレッド間のメモリ割り当て競合を減らすことを目的としています。スレッドがメモリ領域を割り当てた後、そのスレッドがメモリを割り当てる必要がある場合、優先的にこの領域に割り当てられます。そのため、この領域は現在のスレッドにプライベートであり、割り当て時にロックなどの保護操作は必要ありません。

Note

ほとんどの JVM アプリケーションでは、ほとんどのオブジェクトは TLAB 内で割り当てられます。TLAB 外での割り当てが多すぎる場合、または TLAB の再割り当てが多すぎる場合は、コードを確認し、大きなオブジェクトや不規則に伸縮するオブジェクトの割り当てがないかをチェックし、コードを最適化する必要があります。

Allocations in New TLAB Size

主に jdk.ObjectAllocationInNewTLAB イベントを収集します。これは「TLAB スロー割り当て」と呼ばれます。

Allocations Outside TLAB Size

主に jdk.ObjectAllocationOutsideTLAB イベントを収集します。これは「TLAB 外割り当て」と呼ばれます。

Profiling ツールの比較

image.png

参考ドキュメント

<async-profiler>

<DataKit 統合 async-profiler>

<async-profiler デモコード>

<async-profiler Spring Boot デモコード>

フィードバック

このページは役に立ちましたか？