createDirectories() に何が問題あるのか - CPUプロファイリングガイド

他の言語: English Español 한국어 Português 中文

アプリが正常に動作していても、スループットを向上させたり、レイテンシを減らすためにパフォーマンスを向上させたい場合があります。また、ランタイムでのコードの動作を知りたい、ホットスポットを特定したい、あるいはフレームワークがどのように動作するかを把握したい場合もあります。

これらはプロファイラがぴったりのユースケースです。プロファイラは任意の大きさの実行チャンクを全体像で見ることができ、大規模な問題を見つけるのに役立ちます。

多くの人が、ハイロードのアプリケーションを書かない限り、プロファイリングの方法を学ぶ必要はないと信じています。例えば、非常にシンプルなアプリケーションを扱っていても、プロファイリングからどのように恩恵を受けるかを見てみましょう。

例：アプリケーション

以下のようなプログラムがあるとします：

import java.io.IOException;
import java.nio.file.Files;
import java.nio.file.Path;
import java.nio.file.Paths;
import java.util.*;
import java.util.concurrent.TimeUnit;

public class CountEvents {

    public static int update(Deque<Long> events, long nanos, long interval) {
        events.add(nanos);
        events.removeIf(aTime -> aTime < nanos - interval);
        return events.size();
    }

    public static void main(String[] args) throws IOException {
        long start = System.nanoTime();
        int total = 100_000;
        long interval = TimeUnit.MILLISECONDS.toNanos(100);
        int[] count = new int[total];

        Deque<Long> collection = new ArrayDeque<>();
        for (int counter = 0; counter < count.length; counter++) {
            count[counter] = update(collection, System.nanoTime(), interval);
            Path p = Paths.get("./a/b");
            Files.createDirectories(p);
        }
        long spent = System.nanoTime() - start;

        //noinspection OptionalGetWithoutIsPresent
        System.out.println("Average count: " + (int) (Arrays.stream(count).average().getAsDouble()) + " op");
        System.out.println("Spent time: " + TimeUnit.NANOSECONDS.toMillis(spent) + " ms");
    }
}

このプログラムは、NIO2から取得した createDirectories() を使って、ファイルシステム内のパスを作成しようとします。そして、即興のベンチマークを使ってスループットを測定します。

タスクが実行されるたびに、ベンチマークロジックは現在のタイムスタンプをコレクションに保存し、現在の時間よりも前の時間を指すすべてのタイムスタンプを削除します。これにより、この時間間隔中に何回のイベントが発生したかをコレクションを問い合わせるだけで調査することが可能になります。このベンチマークは、 createDirectories() メソッドのパフォーマンスを評価するのに役立ちます。

プログラムを実行した結果、数値が著しく低いことがわかります：

Average count: 6623 op
Spent time: 1462 ms

これは何が問題なのかをプロファイリングして見るとよいでしょう。

スナップショットを取得する

私はIDEとの統合がきちんと実現されており、設定の手間が全くないIntelliJ Profilerを使用しています。IntelliJ IDEA Ultimateを持っていない場合は、他のプロファイラを使用することも可能です。その場合、手順が少し異なるかもしれません。

最初に、プロファイリングデータ（スナップショットとも呼ばれます）を収集する必要があります。この段階では、プロファイラはプログラムと一緒に動作し、その活動に関する情報を収集します。プロファイラは、メソッドの入力と出力を計測するなどの技術を使用してこれを実現します。 IntelliJ Profilerは、アプリケーションで動作しているすべてのスレッドから定期的にスタック情報を収集します。

IntelliJ IDEAからプロファイラをアタッチするには、アプリケーションを実行するために通常使用する実行設定を選択し、メニューからプロファイル (Profile)を選択します。

アプリケーションの実行が完了すると、スナップショットを開くように促すポップアップが表示されます。もしポップアップを誤って閉じてしまった場合でも、スナップショットはプロファイラー (Profiler)ツールウィンドウで利用可能です。

さあ、レポートを開いて中身を見てみましょう。

スナップショットを分析する

レポートを開いた最初の画面はフレームグラフです。これは基本的にすべてのサンプルスタックの要約です。同じスタックのサンプルがプロファイラによって収集されるほど、フレームグラフ上でこのスタックは広がります。つまり、フレームの幅は、この状態で過ごした時間の割合を大まかに示しています。

驚くべきことに、 createDirectories() メソッドが最も実行時間を占めていません。自家製のベンチマークが同じ程度の時間を実行に費やしています！

さらに、上のフレームを見てみると、これは主に removeIf() メソッドのためであり、このメソッドが update() の呼び出し時間のほとんどを占めています。

これは明らかに調査が必要です。

伝統的なツール（フレームグラフなど）に加えて、IntelliJ Profilerはエディタ内でパフォーマンスヒントを提供します。これは、クイックリファレンスやシンプルなシナリオに最適です：

ベンチマークを最適化する

キューからイベントを削除するためのコードが余分な作業をしているようです。

順序付きのコレクションを使用し、イベントが時間順に追加されるため、削除対象のすべての要素は常にキューの先頭にあることが確定しています。 removeIf() を、削除しないイベントの反復処理を開始したらループを抜けるようなものに置き換えることで、パフォーマンスを向上させる可能性があります。

// events.removeIf(aTime -> aTime < nanos - interval);
while (events.peekFirst() < nanos - interval) {
    events.removeFirst();
}

コードを変更したら、再度アプリをプロファイリングし、結果を見てみましょう：

新しいスナップショットで createDirectories() を指すと「すべての 96.49%」と表示されます

ベンチマークのロジックから生じるオーバーヘッドは最小限になり、 createDirectories() フレームは全体の実行時間の約95%を占めるようになりました。

改善はコンソールの出力でも見られます。

Average count: 14788 op
Spent time: 639 ms

ネイティブプロファイリング

ベンチマークの問題を解決した後、ここで止めて自分を褒めることもできます。しかし、 createDirectories() メソッドには何が起こっているのでしょうか？遅すぎますか？

ここでは余地が少ないように思えます。というのも、これはライブラリメソッドであり、その実装に制御権がないからです。しかし、プロファイラは私たちにヒントを与えてくれます。

折りたたまれたライブラリフレームを展開することで、内部の何が起こっているかを調査することができます。

フレームグラフ内のノードを展開すると、折りたたまれていた追加のライブラリノードが表示されます

この部分のフレームグラフを見ると、 createDirectories() の実行時間の主な貢献者は sun.nio.fs.UnixNativeDispatcher.mkdir0 であることがわかります。このフレームの大部分には上に何もありません。これは、そのメソッドのself-time（自己時間）と呼ばれ、それ以上にJavaコードがないことを示しています。ただし、ネイティブコードが存在する可能性はあります。

ディレクトリを作成しようとしているので、オペレーティングシステムのAPIを呼び出す必要があるため、 mkdir の自己時間はネイティブ呼び出しによるものが主であると期待できます。 UnixNativeDispatcher がクラス名に含まれていることで、これを裏付けています。

設定 (Settings) | ビルド、実行、デプロイ (Build, Execution, Deployment) | Java プロファイラー (Java Profiler) | ネイティブの呼び出しを収集 (Collect native calls)でネイティブプロファイリングを有効にしましょう：

ネイティブプロファイリングを有効にしてアプリケーションを再度実行すると、全体像が見えてきます：

ここで本当の問題点にたどり着きます。 createDirectories() メソッドのドキュメンテーションには次のように記述されています：

Creates a directory by creating all nonexistent parent directories first. Unlike the createDirectory method, an exception is not thrown if the directory could not be created because it already exists.

この説明はJavaの観点から見れば正しいです。なぜなら、Javaの例外を発生させないからです。しかし、既に存在するディレクトリを作成しようとすると、オペレーティングシステムレベルで例外が発生します。これが我々のシナリオにおいてリソースの大幅な無駄遣いにつながります。

これを避けるために、 createDirectories() の呼び出しを Files.exists() チェックでラップしてみましょう：

Path p = Paths.get("./a/b");
if (!Files.exists(p)) {
    Files.createDirectories(p);
}

プログラムは驚くほど高速になります！

Average count: 50000 op
Spent time: 87 ms

プログラムは元の速度の約16倍になりました。この例外処理は本当に高級でした！結果はハードウェアや環境によって異なるかもしれませんが、それでも印象的な結果が出るはずです。

スナップショットのdiff

IntelliJ Profilerを使用している場合、2つのスナップショットを視覚的に比較する便利なツールがあります。詳細な説明と手順については、ドキュメンテーションを参照してください。以下に、diffが表示する結果の概要を述べます：

新しいスナップショットに欠けているフレームは緑色で表示され、新しいフレームは赤色で表示されます。フレームが複数の色で表示されている場合、そのフレームは両方のスナップショットに存在するが、その全体的な実行時間が変わっていることを意味します。

上のスクリーンショットから明らかなように、当初プログラムが行っていた大部分の操作は不要で、それらを排除することができました。 CountEvents.update() は完全に緑色です。これは、最初の変更でメソッドの実行時間がほとんど完全に改善されたことを意味します。 Files.exists() の追加は100%の改善ではありませんでしたが、 createDirectories() をスナップショットから効果的に排除し、プログラムの実行時間に60ミリ秒しか追加しなかったことを示しています。

結論

このシナリオでは、プロファイラを使ってパフォーマンスの問題を検出し、修正しました。また、よく知られたAPIでさえも、 Javaプログラムの実行時間に大きな影響を及ぼす可能性があることを示しました。これにより、1秒あたりのトランザクション数を数百万に最適化しているわけではなくても、プロファイリングが有用なスキルであることがわかります。

これからの記事では、より多くのプロファイリングのユースケースとテクニックを考察します。お楽しみに！

all posts ->