Go アプリを最適化する

このチュートリアルでは、プロファイル データを収集するように構成された、意図的に非効率的な Go アプリケーションをデプロイします。Profiler のインターフェースを使用して、プロファイル データを表示し、実行可能な最適化を特定します。次に、アプリケーションを変更してデプロイし、変更の効果を評価します。

準備

  1. Sign in to your Google Cloud account. If you're new to Google Cloud, create an account to evaluate how our products perform in real-world scenarios. New customers also get $300 in free credits to run, test, and deploy workloads.
  2. Google Cloud Console の [プロジェクト セレクタ] ページで、Google Cloud プロジェクトを選択または作成します。

    プロジェクト セレクタに移動

  3. Google Cloud Console の [プロジェクト セレクタ] ページで、Google Cloud プロジェクトを選択または作成します。

    プロジェクト セレクタに移動

  4. Google Cloud コンソールのナビゲーション パネルで [API とサービス] を選択し、[API とサービスの有効化] をクリックして、Cloud Profiler API を有効にします。

    [Profiler API] 設定に移動

  5. [API が有効です] が表示されている場合、API はすでに有効になっています。そうでない場合は、[有効にする] ボタンをクリックします。

  6. Cloud Shell を開くには、Google Cloud コンソールのツールバーで「Cloud Shell をアクティブにする」をクリックします。

    Cloud Shell をアクティブにします。

    しばらくすると、Google Cloud コンソール内で Cloud Shell セッションが開きます。

    Cloud Shell セッション。

サンプル アプリケーション

主な目的は、サーバーで処理できる 1 秒あたりのクエリ数を最大化することです。もう 1 つの目的は、不要なメモリ割り当てを削除することで、メモリ使用量を低減することです。

サーバーは gRPC フレームワークを使用して、単語またはフレーズを受け取り、その単語またはフレーズがシェイクスピアの作品に出現する回数を返します。

サーバーが処理できる平均の秒間クエリ数は、サーバーの負荷テストによって決まります。テストのラウンドごとに、クライアント シミュレータが呼び出され、20 件のシーケンシャル クエリを発行するように指示されます。ラウンドが完了すると、クライアント シミュレータによって送信されたクエリの数、経過時間、秒間クエリ数が表示されます。

サーバーコードは意図的に非効率になっています。

サンプル アプリケーションの実行

サンプル アプリケーションをダウンロードして実行します。

  1. Cloud Shell で、次のコマンドを実行します。

    git clone https://github.com/GoogleCloudPlatform/golang-samples.git
    cd golang-samples/profiler/shakesapp
    
  2. バージョンを 1 に設定し、ラウンド数を 15 に設定してアプリケーションを実行します。

    go run . -version 1 -num_rounds 15
    

    1~2 分後にプロファイル データが表示されます。プロファイル データは次の例のようになります。

    CPU 時間使用量の最初のフレームグラフ。

    スクリーンショットで、[プロファイルの種類] が CPU time に設定されていることが確認できます。これは、フレームグラフに CPU 使用率のデータが表示されていることを示しています。

    Cloud Shell に出力されるサンプル出力を以下に示します。

    $ go run . -version 1 -num_rounds 15
    2020/08/27 17:27:34 Simulating client requests, round 1
    2020/08/27 17:27:34 Stackdriver Profiler Go Agent version: 20200618
    2020/08/27 17:27:34 profiler has started
    2020/08/27 17:27:34 creating a new profile via profiler service
    2020/08/27 17:27:51 Simulated 20 requests in 17.3s, rate of 1.156069 reqs / sec
    2020/08/27 17:27:51 Simulating client requests, round 2
    2020/08/27 17:28:10 Simulated 20 requests in 19.02s, rate of 1.051525 reqs / sec
    2020/08/27 17:28:10 Simulating client requests, round 3
    2020/08/27 17:28:29 Simulated 20 requests in 18.71s, rate of 1.068947 reqs / sec
    ...
    2020/08/27 17:44:32 Simulating client requests, round 14
    2020/08/27 17:46:04 Simulated 20 requests in 1m32.23s, rate of 0.216849 reqs / sec
    2020/08/27 17:46:04 Simulating client requests, round 15
    2020/08/27 17:47:52 Simulated 20 requests in 1m48.03s, rate of 0.185134 reqs / sec
    

    Cloud Shell の出力には、各イテレーションの経過時間と平均リクエスト率が表示されます。アプリケーションの起動時に、「Simulated 20 requests in 17.3s, rate of 1.156069 reqs / sec」というエントリは、サーバーで 1 秒につき約 1 件のリクエストが実行されていることを示します。最後のラウンドでは、「Simulate 20 requests in 1m48.03s, rate of 0.185134 reqs / second」というエントリは、サーバーで 5 秒ごとに約 1 件のリクエストが実行されていることを示しています。

CPU 時間プロファイルを使用して 1 秒あたりのクエリ数を最大化する

1 秒あたりのクエリ数を最大化するアプローチの 1 つは、CPU 使用率の高いメソッドを特定し、その実装を最適化することです。このセクションでは、CPU 時間プロファイルを使用して、サーバー内の CPU 使用率の高いメソッドを識別します。

CPU 時間の使用量の確認

フレームグラフのルートフレームでは、コレクション間隔の 10 秒間でアプリケーションによって使用された合計 CPU 時間が一覧表示されます。

フレームグラフのルートフレーム展開表示。

この例では、サービスは 2.37 s を使用しています。システムが単一のコアで動作している場合、2.37 秒の CPU 時間の使用量は、そのコアの使用率 23.7% に相当します。詳細については、利用可能なプロファイリングの種類をご覧ください。

アプリケーションの変更

変更の評価

変更を評価するには、次の手順を行います。

  1. アプリケーションのバージョンを 2 に設定してアプリケーションを実行します。

    go run . -version 2 -num_rounds 40
    

    後のセクションでは、最適化によって、1 回のラウンドを実行するのにかかる時間が、変更されていないアプリケーションの実行と比較してかなり短いことを示します。プロファイルの収集とアップロードに十分な時間だけアプリケーションが実行されるようにするには、ラウンド回数を増やします。

  2. アプリケーションが完了するまで待ってから、このバージョンのアプリケーションのプロファイル データを表示します。

    • [現在] をクリックして最新のプロファイル データを読み込みます。詳細については、期間をご覧ください。
    • [バージョン] メニューで [2] を選択します。

たとえば、フレームグラフは次のようになります。

バージョン 2 の CPU 時間の使用状況を示すフレームグラフ。

この図では、ルートフレームは 7.8 s の値を示しています。文字列一致関数を変更した結果、アプリケーションによって使用される CPU 時間が、2.37 秒から 7.8 秒に増加(アプリケーションによる CPU コアの使用率が 23.7% から 78% に変化)しました。

フレームの幅は、CPU 時間の使用状況に比例した測定値です。この例では、GetMatchCount のフレームの幅は、アプリケーションで使用するすべての CPU 時間の約 49% を使用することを示しています。元のフレームグラフでは、この同じフレームがグラフの幅の約 72% でした。正確な CPU 時間の使用状況を表示するには、フレーム ツールチップを使用するか、フォーカス関数リストを使用します。

バージョン 2 の CPU 時間の使用量を示すフォーカス関数のリスト。

Cloud Shell の出力は、変更されたバージョンで 1 秒につき約 5.8 件のリクエストが完了していることを示しています。

$ go run . -version 2 -num_rounds 40
2020/08/27 18:21:40 Simulating client requests, round 1
2020/08/27 18:21:40 Stackdriver Profiler Go Agent version: 20200618
2020/08/27 18:21:40 profiler has started
2020/08/27 18:21:40 creating a new profile via profiler service
2020/08/27 18:21:44 Simulated 20 requests in 3.67s, rate of 5.449591 reqs / sec
2020/08/27 18:21:44 Simulating client requests, round 2
2020/08/27 18:21:47 Simulated 20 requests in 3.72s, rate of 5.376344 reqs / sec
2020/08/27 18:21:47 Simulating client requests, round 3
2020/08/27 18:21:51 Simulated 20 requests in 3.58s, rate of 5.586592 reqs / sec
...
2020/08/27 18:23:51 Simulating client requests, round 39
2020/08/27 18:23:54 Simulated 20 requests in 3.46s, rate of 5.780347 reqs / sec
2020/08/27 18:23:54 Simulating client requests, round 40
2020/08/27 18:23:58 Simulated 20 requests in 3.4s, rate of 5.882353 reqs / sec

アプリの小さな変更により、次の 2 つの影響がありました。

  • 1 秒あたりのリクエスト数が 1 秒あたり 1 件未満から 1 秒あたり 5.8 件に増えました。

  • CPU 使用率を 1 秒あたりのリクエスト数で割って算出した、1 件のリクエストあたりの CPU 時間が 23.7% から 13.4% に減少しました。

    CPU 時間の使用量が、単一の CPU コアの使用率 23.7% に相当する 2.37 秒から 7.8 秒(CPU コア使用率 78%)に増加した場合でも、1 件のリクエストあたりの CPU 時間は減少しました。

割り当てられたヒープ プロファイルを使用してリソースの使用状況を改善する

このセクションでは、ヒープ割り当てと割り当てられたヒープ プロファイルを使用して、アプリケーションで割り当ての多いメソッドを識別する方法を示します。

  • ヒープ プロファイルでは、プロファイルの収集時にプログラムのヒープ内に割り当てられるメモリの量が表示されます。

  • 割り当てられたヒープ プロファイルでは、プロファイルが収集された期間内にプログラムのヒープ内に割り当てられたメモリの合計量が表示されます。これらの値をプロファイル収集間隔の 10 秒で割ると、これらを割り当てレートとして解釈できます。

ヒープ プロファイルの収集の有効化

  1. アプリケーションのバージョンを 3 に設定してアプリケーションを実行し、ヒープと割り当てられたヒープ プロファイルの収集を有効にします。

    go run . -version 3 -num_rounds 40 -heap -heap_alloc
    
  2. アプリケーションが完了するまで待ってから、このバージョンのアプリケーションのプロファイル データを表示します。

    • [現在] をクリックして最新のプロファイル データを読み込みます。
    • [Version] メニューで [3] を選択します。
    • [Profiler type] メニューで、[Allocated heap] を選択します。

    たとえば、フレームグラフは次のようになります。

    バージョン 3 の割り当て済みヒープ プロファイルのフレームグラフ。

ヒープ割り当てレートの特定

ルートフレームには、プロファイルの収集時に 10 秒間に割り当てられたヒープの合計量が、すべてのプロファイルで平均化されて表示されています。この例では、ルートフレームに、平均 1.535 GiB のメモリが割り当てられたことが表示されています。

アプリケーションの変更

変更の評価

変更を評価するには、次の手順を行います。

  1. アプリケーションのバージョンを 4 に設定してアプリケーションを実行します。

    go run . -version 4 -num_rounds 60 -heap -heap_alloc
    
  2. アプリケーションが完了するまで待ってから、このバージョンのアプリケーションのプロファイル データを表示します。

    • [現在] をクリックして最新のプロファイル データを読み込みます。
    • [Version] メニューで [4] を選択します。
    • [Profiler type] メニューで、[Allocated heap] を選択します。
  3. ヒープ割り当てレートでの readFiles の変更による影響を数値化するために、バージョン 4 に割り当てられているヒープ プロファイルとバージョン 3 で収集されたヒープ プロファイルを比較します。

    バージョン 4 とバージョン 3 に割り当てられたヒープ プロファイルの比較。

    ルートフレームのツールチップには、バージョン 4 を使用した場合、プロファイル コレクション中に割り当てられるメモリの平均量が、バージョン 3 と比較して 1.301 GiB 減少したことが表示されています。readFiles.func1 のツールチップには、1.045 GiB 減少したことが表示されています。

    割り当て済みヒープ プロファイルの種類に関する readfile のツールチップの比較。

  4. ガベージ コレクションへの影響を数値化するには、CPU 時間のプロファイルの比較を構成します。次のスクリーンショットでは、Go のガベージ コレクタ runtime.gcBgMarkWorker.* のスタックを表示するためにフィルタが適用されています。このスクリーンショットは、ガベージ コレクションの CPU 使用率が 16.8% から 4.97% に減少していることを示しています。

    v4 と v3 のバックグラウンド ガベージ コレクションの CPU 時間の使用量の比較。

  5. アプリケーションによって処理される 1 秒あたりのリクエスト数の変更によって影響が生じるかどうかを確認するには、Cloud Shell で出力を表示します。この例では、バージョン 4 で 1 秒あたり最大 15 件のリクエストを処理します。これは、バージョン 3 の 1 秒あたり 5.8 件のリクエストよりも大幅に増加しています。

    $ go run . -version 4 -num_rounds 60 -heap -heap_alloc
    2020/08/27 21:51:42 Simulating client requests, round 1
    2020/08/27 21:51:42 Stackdriver Profiler Go Agent version: 20200618
    2020/08/27 21:51:42 profiler has started
    2020/08/27 21:51:42 creating a new profile via profiler service
    2020/08/27 21:51:44 Simulated 20 requests in 1.47s, rate of 13.605442 reqs / sec
    2020/08/27 21:51:44 Simulating client requests, round 2
    2020/08/27 21:51:45 Simulated 20 requests in 1.3s, rate of 15.384615 reqs / sec
    2020/08/27 21:51:45 Simulating client requests, round 3
    2020/08/27 21:51:46 Simulated 20 requests in 1.31s, rate of 15.267176 reqs / sec
    ...
    

    アプリケーションで処理される 1 秒あたりのクエリ数の増加は、ガベージ コレクションに費やされる時間の短縮が要因である可能性があります。

  • ヒープ プロファイルを表示すると、readFiles への変更の影響を詳細に把握できます。バージョン 4 のヒープ プロファイルとバージョン 3 のヒープ プロファイルの比較により、ヒープ使用量が 70.95 MiB から 18.47 MiB に減少したことがわかります。

    バージョン 4 とバージョン 3 のヒープ使用量の比較。

概要

このクイックスタートでは、CPU 時間と割り当てられたヒープ プロファイルを使用して、アプリケーションの潜在的な最適化を特定しました。目標は、1 秒あたりのリクエスト数を増やし、不要な割り当てを排除することでした。

  • CPU 時間プロファイルを使用することで、CPU 使用率の高い関数が特定されました。簡単な変更を適用した後、サーバーのリクエスト レートが、1 秒あたり約 1 から 1 秒あたり 5.8 に増加しました。

  • 割り当てられたヒープ プロファイルを使用することで、shakesapp/server.go 関数 readFiles の割り当てレートが高いことがわかりました。readFiles を最適化した後、サーバーのリクエスト率が 1 秒あたり 15 件に増加し、10 秒間のプロファイル コレクション中に割り当てられるメモリの平均量が 1.301 GiB 減少しました。

次のステップ

Cloud Profiler エージェントの実行については、以下をご覧ください。