Amazon Web Services ブログ

Amazon CodeGuru Profiler でパフォーマンスの問題を調査する

Amazon CodeGuru (プレビュー) は、アプリケーションのパフォーマンス特性を分析し、それを改善する方法を自動的に推奨します。Amazon CodeGuru Profiler は、アプリケーションで時間が費やされている部分をインタラクティブに視覚化します。このフレームグラフは、どのコードメソッドが遅延を引き起こしているのか、CPU を過度に使用しているのかをトラブルシューティングするのに役立つ強力なツールです。この記事では、フレームグラフを解釈する方法を説明し、次の場合にどう使用したらよいかを示します。

  1. アプリケーションのパフォーマンスプロファイルを分析し、それが既知のコードとどのように関連しているかを理解する
  2. プロファイル内の明らかな異常を見つける
  3. レイテンシーの問題を調査する
  4. CPU 使用率の最適化とコスト削減の機会を探す

アプリケーションを分析する

プロファイリンググループを開く

アプリケーションのプロファイリングを開始する前に、デモアプリケーションのおかげで、セットアップなしで CodeGuru Profiler をすぐに使用開始できます。AWS アカウントを持っている人なら誰でもご利用いただけます。デモアプリケーションにアクセスするには、Amazon CodeGuru コンソールで、[Profiler]、[Profiling groups] を選択します。この記事では DemoProfilingGroup-WithoutIssues を使用しています。

[Profiling groups] ページから選択すると、フレームグラフが表示されます。次のスクリーンショットは、この特定のデモアプリケーションのフレームグラフを示しています。

フレームグラフとは何ですか?

フレームグラフは、スタックトレースで表示される方法と同様に、階層的な方法で示されます。CodeGuru Profiler は、一定期間 (5 分など) にアプリケーションで実行されているコードからスタックトレースのスナップショットを定期的に取得し、1 度の視覚化で表示します。フレームと呼ばれる水平バーは、各メソッドを表します。CodeGuru Profiler がスタックトレース内のメソッドを頻繁に見るほど、グラフ内のフレームが広くなります。十分なサンプルを用いることで、アプリケーションが各メソッドに費やす時間の割合を確認できます。

フレームグラフには、時間に関する 2 つの概念があります。

  • CPU の稼働時間 – プロセッサがそのメソッドでアクティブに動作していた時間を表したもの。表示するには、CPU ビューモードを使用します。
  • 実際の経過時間 – これは、稼働時間に加えて、プロセスが待機していた時間も考慮します。表示するには、レイテンシービューモードを使用します。

デモアプリケーションが行っていること

視覚化により何が表示されるかを理解するには、実際にプロファイルされたアプリケーションが何をしているかを知るのがよいでしょう。

このデモアプリケーションでは、2 つの個別のスレッドを実行しています。スレッドの 1 つはタスクパブリッシャー用で、Amazon SQS キュー内にタスクを追加します。もう 1 つのスレッドはイメージプロセッサを実行しており、次のアクションを実行します。

  1. キューからタスクを取得する
  2. イメージを Amazon S3 バケットにダウンロードする
  3. イメージをローカルディスクにコピーする
  4. イメージを変換して S3 バケットにアップロードする
  5. イメージをローカルディスクから削除する
  6. キューからタスクを削除する

次の図は、このアーキテクチャを示しています。

概要の主要部分を特定する

プロファイリンググループのプロファイルを開いた後、デフォルトの視覚化タイプは CPU ビューモードの概要 (オーバービュー) です。マウスをフレームの上に移動すると、関数の完全な名前と追加情報が表示されます。たとえば、次のスクリーンショットは、この期間に観測された CPU 稼働時間の 51.65% が PNGImageWriter.encodePass 関数に費やされていたことを示しています。

特定のフレームの下のフレームは呼び出し元の関数で、上のフレームは呼び出した関数です。次のスクリーンショットは、さまざまな関数が示されています。

下から上に進むと、スレッドの開始方法を確認し、使用中の ImageProcessor と TaskPublisher クラスを見つけることができます。ImageProcessor.run 関数のすぐ上に、呼び出した関数があります。次のテーブルは、前のスクリーンショットで番号が付けられた各アクションとその動作をまとめたものです。

 

アクション 動作 グラフのフレーム名
1 SQS キューからタスクを取得する AmazonSQSClient.receiveMessage
2 S3 バケットから画像データを取得する AmazonS3Client.getObject
3 画像データをファイルにコピーする IOUtils.copy
4 画像データを変換し、S3 バケットにアップロードする

ImageProcessor $ BrightenImageProcessor.brightenAndUpload

ImageProcessor $ BWImageProcessor.monochromeAndUpload
5 ファイルを削除する N/A (このアクションは非常に高速で、サンプリングされませんでした)
6 SQS キューのメッセージを削除する AmazonSQSClient.deleteMessage

この視覚化を使用する場合、次のことを覚えておくことが重要です。

  • 同じコンテキストから呼び出された異なる関数は、実行順ではなく、アルファベット順に水平に表示されます。たとえば、前のスクリーンショットでは、アクション 6 はアクション 3 の左側にあります。
  • スタックトレースのすべてのステップが視覚化情報に表示されます。混乱を招く場合もあるかもしれません。上に同じ幅の関数が 1 つしかない場合、それは単なる中間関数であり、各フレームについて心配する必要はありません。たとえば、ImageProcessor クラスがプライベートクラス BrightenImageProcessor.brightenAndUpload を呼び出す場合、Java はグラフに表示される BrightenImageProcessor.access$300 メソッドを作成します。
  • CPU の消費量が多いのは、大きなフラット関数です。その関数を特定し、アプリケーションがその動作を行うのに多くの時間を費やしていることを確認する必要があります。この例では、大きな deflateBytes は画像処理ツールであるアプリケーションにとって必要であることは理解でき、PNG 画像を書き込むときに呼び出されます。

このビューから何を学べるでしょうか?

CPU の大部分は ImageProcessor に費やされ、この関数内では、画像を変換するアクション 4 にそのほとんどが費やされています。PNRImageWriter は Deflater で圧縮を行っており、アクティブな CPU 使用率は約 50% に上ります。

このプロセスは、AWS のサービス (Amazon SQS と Amazon S3) に対して呼び出しを複数回行っています。Amazon S3 の呼び出しにかかる CPU 時間はごくわずかです (たとえば、前のスクリーンショットでは ImageProcessor にステップ 2 はほとんど見られません)。ただし、レイテンシーには依然影響を与える可能性があります。

CodeGuru Profiler での異常の表示方法

次の使用例は、CodeGuru Profiler が異常を表示する方法を示しています。

バグの紹介

このユースケースは、実際のバグを単純化したバージョンです。次のコードを追加して、処理したメッセージを追跡し、SQS メッセージごとに呼び出すと仮定します。

   static final List<Message> existingMessagesList = new ArrayList<Message>();
    
   void trackMessages(Message message) {
        if (!existingMessagesList.contains(message)) {
            existingMessagesList.add(message);
        }
    }

残念ながら、考えられるメッセージはほんの少ししかないと予想していましたが、各 Message オブジェクトは異なるため、リストはアプリケーションの実行中、拡大し続けます。長いリストから検索していたのでは、うまくスケーリングできません。

プロファイルに異常を見つける

アプリケーションの実行時間が長いほど、消費する CPU が多くなります。このタイプの問題は、問題が発生するまで長時間実行する必要があるため、実稼働環境で実行する前に見つけるのが難しい場合があります。しばらく実行すると、プロファイルは次のスクリーンショットのようになります。

現在、幅のほとんどを占める大きな trackMessages フレームがあります。フレームは、この関数が使用している CPU 時間を示しています。

他のフレームはすべてそれよりも小さなものです。これらの処理に費やす CPU 時間は変わりませんが、trackMessages は以前よりも多くの CPU 時間を使用しているため、他のフレームは小さくなっています。すべての関数の幅は他の関数と比較して表示されることに注意してください。

ArrayList.indexOf に費やされたすべての時間を見ると、長いリストから検索しているため、ハッシュマップを使用するか、リストに含める項目が少なくなるようにする必要があります。

レイテンシーの改善

サービスベースのアプリケーションを使用している場合は、次のいずれかのアクションを実行して、サービスの 1 つのレイテンシーを改善できるかもしれません。

  • 改善しようとしている関数にズームインします。CPU に縛られていない場合、視覚化の他の部分には興味がないかもしれません。これらはおそらく他のサービスの呼び出しまたは別のスレッドで使用する関数で、興味のある部分には影響を与えないでしょう。
  • レイテンシービューに切り替えます。前述のように、デフォルトの CPU ビューには CPU 稼働時間のみが表示され、実際の経過時間は表示されません。対照的に、レイテンシービューには、アクティブなスレッド状態と待機中のスレッド状態の両方のサンプルが表示されるため、実際に何に時間が費やされたのかがわかります。レイテンシービューでは、さまざまな色を使って時間がどう異なるスレッド状態に分配されているかが示されます (したがって、どの部分がアクティブに処理され、ブロックされ、または待機中であったかを確認できます)。

CPU ビューとレイテンシービューの比較

次のスクリーンショットは、CPU ビューの ImageProcessor.run 関数を拡大したものです。

CPU ビューは、Amazon S3 からオブジェクトを取得するための呼び出しが無視できるように見えることを示しています (合計時間の 0.40%)。

次のスクリーンショットは、レイテンシービューの ImageProcessor.run 関数を拡大したものです。

レイテンシービューでは、応答を待つのに時間がかかるため、合計時間の 5.31% もかかっていることがわかります。

ユースケース: 外部呼び出しが異常に遅い

このユースケースでは、この呼び出しで Amazon S3 からオブジェクトを取得する際に問題が発生しています。たとえば、間違ったリージョンで呼び出している場合、呼び出しははるかに時間がかかります。この使用例では、CPU ビューは変更されませんが、レイテンシービューは次のスクリーンショットのようになります。

AmazonS3Client.getObject の呼び出しにかかっているのは、合計時間の 5% ではなく 36% で、ImageProcess.run の最大部分です。プロファイルが通常どのように見えるかに慣れている場合は、この問題をすぐに見つけることができます。慣れていない場合は、このビューにより、プロセスのどの部分に時間がかかり、どこに改善の余地があるかが示されます。

CPU 使用率の最適化とコスト削減の機会

次のユースケースは、CPU 使用率を最適化し、コストを削減する機会を見つける方法を示しています。

ホットスポット視覚化を使用して、使用率が最も高い関数を見つける

このユースケースでは、他のデモアプリケーション DemoProfilingGroup-WithIssues プロファイリンググループを使用します。これは同じ画像処理アプリケーションですが、非効率性が認められる部分もいくつかあります。目標は、最大に非効率な関数を見つけることです。

デフォルトのオーバービュー視覚化の代わりに、ホットスポット視覚化を使用できます。グラフ全体で CPU 使用率が最も高い関数が上部に表示されます。これは、CPU 使用率が高くなる低レベルの関数を見つけたい場合に役立ちます。

たとえば、このユースケースの場合、オーバービュー視覚化には ZipFile.entry で終わる複数のスタックがあります。これらはそれぞれ合計の約 4% であるため、個別には目立たないかもしれません。けれども、ホットスポットビューでは、それらの合計が約 20% にまでなることがわかります。そのスクリーンショットを次に示します。

この視覚化から学ぶ

PNG 画像が圧縮されて書き込まれたスタックがまだ表示されています。これは、前述のアクション 4 と同じです。非効率性の問題がなければ、アクティブな CPU 使用率の約 50% を占めていたはずです。

簡単に識別できる他の 2 つの大きなスタックは A と B です。(フレームにカーソルを合わせると) 黄色で強調表示されているため、発信者を見ると、A はほとんどがログ記録から、そして B はほとんどが AmazonSQSClient オブジェクトの構築であることがわかります。

関数を検査する

通常、AWS クライアントは再利用できるように設計されているため、構築に多くの時間を費やすのは非効率です。これをもう少し調べるには、[AmazonSQSClient.<init>] フレームを右クリックし、[Inspect] を選択します。 次のスクリーンショットは、この 3 番目の視覚化を示しています。これは、オーバービューとホットスポットを組み合わせたものですが、1 つの関数に焦点を当てています。フレームの上には、それが呼び出す他の関数があり、下にはそれを呼び出したさまざまな関数があります。

この視覚化から学ぶ

すべてのアプリケーションコードで、AmazonSQSClient オブジェクトの構築に CPU 稼働時間の 36% を費やしました。1 つの静的インスタンスを作成して再利用するのではなく、使用するたびにクライアントを作成しているように見えます。

視覚化の上部から、主にクラスの読み込みに時間がかかっていることがわかります。

下部から、このコンストラクターを呼び出す場所を 1 か所確認できます。独自のコードの一部である最初の関数は、おそらく修正できる部分です。

コードを修正するには、sqsClient 関数を見つけます。次のコードを参照してください。

public class Main {
    static AmazonSQS sqsClient() {
       return AmazonSQSClientBuilder.standard().build();
    }
}

コードを次のように変更します。

public class Main {
    static AmazonSQS sharedSqsClient = 
AmazonSQSClientBuilder.standard().build();
    static AmazonSQS sqsClient() {
        return sharedSqsClient;
    }
}

このようにコードを少し変更することで、CPU 使用量を最大 36% 節約できる可能性があります。

推奨事項

アプリケーションには多くの一般的な効率上の問題があります。開発者が全員同じ調査を行う必要がないように、CodeGuru Profiler は問題を自動的に検出しようとします。

この記事で説明した調査を行う前に、CodeGuru プロファイラーに推奨事項があるかどうかを確認する必要があります。CodeGuru コンソールの [Profiling groups] で、プロファイルグループを選択します。利用できる推奨事項がある場合は、[Recommendations] を選択します。

次のスクリーンショットは、デモプロファイルに 4 つの推奨事項があることを示しています。

修正したばかりの問題は、CodeGuru Profiler が検出した問題です。次のスクリーンショットは、この問題に対する最初の推奨事項を示しています。

推奨事項では、問題の場所と修正方法を説明しています。このユースケースの最初の推奨事項は、まさにここで発見して修正したものです。調査を開始する前に、必ず推奨レポートを確認してください。時間を節約できるかもしれません。

アプリケーションはアイドル状態ですか?

あまり知らないアプリケーションのプロファイリンググループを調べて、コストを削減する機会を探すときは、アプリケーションがほとんどアイドル状態である可能性があることを頭に入れておきましょう。(たとえば、ほとんどリクエストを受信しないトランザクションベースのアプリケーションは、ほとんどの時間を呼び出しの待機に費やしています)。 このユースケースでは、コードを処理するサンプルが非常に少ないため、フレームグラフは正確ではない可能性があり、コストを削減する機会は非常に限られています。フリートのサイズが低トラフィックに適合しているかどうかを確認する必要があります。単に Amazon EC2 インスタンスをいくつかリリースすることで、さらに節約できるかもしれません。

次のインジケータは、アイドル状態のアプリケーションをすばやく見つけるのに役立ちます。

  • 非常に小さなフレームはありません。サンプルがわずかしかないため、1 つのサンプルに対応する幅は通常より大きくなります。
  • 大きなフレームであっても、実行可能時間またはネイティブ時間はわずかです。
  • CodeGuru プロファイラーのオーバーヘッドを表すフレーム (ProfilingCommand.run) は、これがこのアプリケーションで処理するほとんど唯一のものであるため、通常よりも大きくなっています。

まとめ

この記事では、CodeGuru Profiler がパフォーマンスの問題とコスト削減の機会を見つけるのに役立つ主なユースケースについて説明しました。各ユースケースでは、異なる視覚化を使用して CPU 使用率またはレイテンシーを改善する方法を示しました。

この記事からデモアプリケーションプロファイルを詳しく調べるには、Amazon CodeGuru コンソールにアクセスして自分でプロファイルを確認するか、新しいプロファイリンググループを作成して独自のアプリケーションをオンボードします。

著者について

Pierre Marieu は、ロンドンの Amazon CodeGuru Profiler チームのソフトウェア開発エンジニアです。彼は、他のソフトウェアエンジニアの日常業務を支援するツールを構築するのが大好きです。それ以前は、Amadeus IT で勤務し、旅行業界向けのソフトウェアを構築していました。