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. In the Google Cloud console, on the project selector page, select or create a Google Cloud project.

   Note: If you don't plan to keep the resources that you create in this procedure, create a project instead of selecting an existing project. After you finish these steps, you can delete the project, removing all resources associated with the project.

   Go to project selector

3. In the Google Cloud console, on the project selector page, select or create a Google Cloud project.

   Note: If you don't plan to keep the resources that you create in this procedure, create a project instead of selecting an existing project. After you finish these steps, you can delete the project, removing all resources associated with the project.

   Go to project selector

4. Enable the required API.

   Enable the API

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

   

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

   

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

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

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

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

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

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

注: アプリケーションの実行時間については、一部のプロファイル データを収集するのに十分な時間のみが確保されます。実際には、プロファイル データを分析する前に、10 個以上のプロファイルを用意することをおすすめします。

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

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 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: CPU 時間の使用率が高い関数

最適化が必要なコードを特定するには、関数の表を表示し、貪欲な関数を特定します。

1. 表を表示するには、 [フォーカス関数のリスト] をクリックします。
2. 表を [合計] で並べ替えます。[合計] のラベルが付いた列には、関数とその子の CPU 時間の使用量が表示されます。

   この例では、GetMatchCount がリストの最初の shakesapp/server.go 関数です。この関数は、合計 CPU 時間のうち 1.7 秒、アプリケーションの合計 CPU 時間のうち 72% を使用しています。この関数は gRPC リクエストを処理します。

   

   フレームグラフでは、shakesapp/server.go 関数 GetMatchCount が MatchString を呼び出し、さらに Compile を呼び出すことにほとんどの時間を費やしていることを示しています。
   

   

ステップ 2: 学習した内容の活用方法

1. 言語の専門知識を活用する。MatchString は正規表現メソッドです。正規表現の処理は非常に柔軟ですが、必ずしもすべての問題に対して最も効率的な解決策とは限りません。
2. アプリケーションの専門知識を活用する。クライアントが単語またはフレーズを生成し、サーバーはこのフレーズを検索しています。
3. shakesapp/server.go メソッドの GetMatchCount の実装で MatchString の使用を検索して、その呼び出しをより単純で効率的な関数で置き換えることができるかどうかを判断します。

ステップ 3: アプリケーションを変更する方法

ファイル shakesapp/server.go では、既存のコードに MatchString の呼び出しが 1 つ含まれています。

    isMatch, err := regexp.MatchString(query, line)
    if err != nil {
           return resp, err
    }
    if isMatch {
           resp.MatchCount++
    }
    

1 つの方法は、MatchString ロジックを strings.Contains を使用する同等のロジックに置き換えることです。

    if strings.Contains(line, query) {
            resp.MatchCount++
    }
    

regexp パッケージの import ステートメントは必ず削除してください。

変更の評価

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

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

   go run . -version 2 -num_rounds 40
   

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

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

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

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

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

フレームの幅は、CPU 時間の使用状況に比例した測定値です。この例では、GetMatchCount のフレームの幅は、アプリケーションで使用するすべての CPU 時間の約 49% を使用することを示しています。元のフレームグラフでは、この同じフレームがグラフの幅の約 72% でした。正確な 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] を選択します。

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

   

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

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

アプリケーションの変更

ステップ 1: ヒープ割り当てのレートを最小限にすることに価値があるかどうかの確認

Go バックグラウンド ガベージ コレクション関数 runtime.gcBgMarkWorker.* の CPU 時間の使用量を使用して、ガベージ コレクションによるコストを削減するようにアプリケーションを最適化することが有益かどうかを判断できます。

• CPU 時間の使用状況が 5% 未満の場合は、最適化をスキップします。
• CPU 時間の使用状況が 25% 以上の場合は、最適化を実施します。

この例では、バックグラウンド ガベージ コレクタの CPU 時間の使用状況は 16.8% です。この値は十分高いため、shakesapp/server.go を最適化することには価値があります。

ステップ 2: 大量のメモリを割り当てる関数

ファイル shakesapp/server.go には、最適化の対象となる GetMatchCount と readFiles の 2 つの関数が含まれています。これらの関数のメモリ割り当てのレートを確認するには、[Profile type] を [Allocated heap] に設定してから、[Focus function list] を使用します。

この例では、10 秒間のプロファイル コレクション中の readFiles.func1 の合計ヒープ割り当てが平均化され、1.045 GiB、または合計割り当てメモリの 68% になります。10 秒間のプロファイル コレクション中の自己ヒープ割り当ては 255.4 MiB です。

この例では、Go メソッド makeSlice によって、10 秒間のプロファイル コレクションで平均 798.7 MiB が割り振られます。この割り当て量を減らす最も簡単な方法は、makeSlice の呼び出しを減らすことです。関数 readFiles ではライブラリ メソッドを使用して makeSlice を呼び出します。

この分析の結果、readFiles を最適化することによって、ヒープ割り当てのレートが低下する可能性があることがわかります。

ステップ 3: アプリケーションを変更する方法

1 つの方法は、ファイルを 1 回読み取り、その内容を再利用するようにアプリケーションを変更することです。たとえば、次のように変更します。

1. 最初のファイル読み取り結果を格納するグローバル変数 files を定義します。

   var files []string

2. files が定義されるときに、早期に戻るように readFiles を変更します。

          func readFiles(ctx context.Context, bucketName, prefix string) ([]string, error) {
                   
                   // return if defined
                   if files != nil {
                           return files, nil
                   }
                   
   
                   // Existing
                   type resp struct {
                           s   string
                           err error
                   }
                   ...
                   
                   // Save the result in the variable files
                   files = make([]string, len(paths))
                   for i := 0; i < len(paths); i++ {
                           r := <-resps
                           if r.err != nil {
                                   return nil, r.err
                           }
                           files[i] = r.s
                   }
                   return files, nil
                   
           }
           

変更の評価

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

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 と比較して 1.301 GiB 減少したことが表示されています。readFiles.func1 のツールチップには、1.045 GiB 減少したことが表示されています。

   

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

   

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 に減少したことがわかります。

  

概要

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

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

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

次のステップ

• プロファイルの収集方法と Google Cloud プロジェクトへの送信方法については、プロファイルの収集をご覧ください。

• DevOps に関するリソースを読む。また、研究プログラムについて確認する。

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

• Go アプリケーションのプロファイリング
• Java アプリケーションのプロファイリング
• Node.js アプリケーションのプロファイリング
• Python アプリケーションのプロファイリング
• Google Cloud の外部で実行されているアプリケーションのプロファイリング