Cloud Monitoring と OpenCensus でアプリのレイテンシの原因を特定する

このドキュメントでは、OpenCensusMonitoring を使用してアプリ開発者向けの指標と分散トレースをモニタリングすることにより、テール レイテンシの原因を特定するために利用できる情報を提供します。

アプリがユーザーにサービスを提供するところを観察すると、一部のユーザーのレイテンシが他のユーザーよりも長くなっていることがわかります。ユーザーの集団がより多様になりリソースがより頻繁に使用される場合に、その違いはより鮮明になります。高レイテンシの原因を特定して対処することで、リソースを最適レベルで使用し、ユーザーベースを拡大してより多くのユーザーの利用に供することができます。リソースの使用量を増やした場合に、リソース競合によって最初に顕著になるのはテール レイテンシです。

高レイテンシを経験するユーザーは少ないとしても、そのユーザーが新しい潜在的な市場において最先端の位置に存在している場合、その存在が重要になる可能性があります。

このドキュメントでは、これらのユーザーが経験する高レイテンシの原因を特定し記述する方法について説明します。特に、このドキュメントによって次の質問に対する回答が得られます。

  • テール レイテンシを正確に測定するにはどうすればよいか?
  • アプリのレイテンシの主な原因は何か?
  • テール レイテンシを最小化するための戦略をどのように評価できるか?

これらの質問に対する回答の主なテーマは次のとおりです。

  • モニタリング指標の推定値が不正確である原因を特定する。
  • 高レイテンシの原因を特定する。
  • テール レイテンシを最小化する。

テストアプリのソースコードは GitHub リポジトリで提供されます。

このドキュメントは、OpenCensus、Cloud MonitoringCloud TraceBigQuery、および Java のアプリ開発における基本的な使用方法に読者が精通していることを前提としています。

用語

指標
アプリの性能を測る尺度。
レイテンシ
アプリがタスクを実行するのにかかる時間。このドキュメントで示すレイテンシの値は、アプリのコード内で測定されたものです。
テール レイテンシ
少数のユーザーが経験する高いレイテンシの値。テール レイテンシは、パーセンタイル レベルで定義できます。たとえば、99 パーセンタイル値は、ある時間間隔で測定されたリクエストのレイテンシ値の上位 1% です。詳しくは、Site Reliability Engineering の「Monitoring Distributed Systems」の章のセクション「Worrying about your Tail」をご覧ください。
集約モデル
収集された測定値の統計分布を示すモニタリング指標の表現。このドキュメントでは、バケットに分割されたレイテンシの範囲、および各時間間隔で記録された各バケットのカウントを含むヒストグラム モデルを想定しています。Monitoring では、この種類の表現を含む指標に対して、分布指標という用語を使用します。

背景

クラウドアプリの所有者は、多くの場合、レイテンシの中央値とテール値を組み合わせてモニタリングします。レイテンシの中央値は、アプリの全体的な健全性をうまく表す指標です。ただし、アプリの規模が大きくなると、レイテンシの中央値だけでは容易に確認できない微妙な問題が発生する可能性があります。

テール レイテンシを理解することにより、多くの目的を達成できます。

  • レイテンシの中央値だけでは明らかにならない、新しい問題を早期に検出する。
  • 一部のリクエストの処理が最適化されていなくても、使用率が高くならないようにする。
  • 単一サーバーが異常である場合や少数のユーザーのみが利用するコードパスが適切に処理されない場合の動作をモニタリングする。
  • タイムアウトやバックオフ再試行に適切な値を設定するなど、テール レイテンシを最小限に抑えるための戦略を表示する。リクエストを長時間保留にするのではなく、接続を放棄して再試行するまでのタイムアウトを 99 パーセンタイルのレイテンシよりわずかに高く調整できます。

テール レイテンシには多くの原因が考えられます。典型的な原因は次のとおりです。

  • リクエストのペイロード サイズの変化
  • 高い CPU 使用率
  • 最適でないアプリケーションのコード構造
  • ネットワーク コールのルーティング距離の変化
  • ときどき接続が切断されコールド スタートが発生する予期しないサーバーの再起動
  • バッファリングまたはキューイング
  • 古い接続の再確立などの接続管理
  • パケット損失を含むネットワーク輻輳
  • ユーザー リクエストの処理の中断につながるデータのガベージ コレクションまたは圧縮
  • クラウド サービスのレイテンシの変動
  • 接続タイムアウトの最適でない設定

レイテンシの原因を特定するための戦略には以下が含まれます。

  • 正確なレイテンシの測定方法を確立する: 定義によれば、テール レイテンシにあたるのはトラフィックのうちのごく一部のみであるため、測定の精度について理解する必要があります。
  • モニタリング、トレース、ロギング ソリューションを実装する: OpenCensus と Monitoring を使用することにより、アプリによってルートスパンのトレースが作成され、さまざまな測定の子スパンを含めるリクエストが生成されます。その後、OpenCensus HTTP 統合を使用して子スパンが自動的に生成され、追加コンテキストを記録するためのログ統合のトレースが追加されます。これにより、モニタリングとトレースに必要な追加コードが最小限に抑えられます。
  • データを探索する: 長時間実行されているリクエストのテールを示すレポートとチャートを見て、どの子スパンが実行に最も時間がかかるかを特定します。
  • テール レイテンシの理由を特定する: 子スパンが長くなる理由を説明するための情報を関連ソースから収集し、サンプルスパンの注釈と比較します。
  • クエリをより詳細に理解する: ログを BigQuery にエクスポートし、トレース情報と組み合わせてアプリの動作をドリルダウンして定量化します。

このドキュメントで説明する分析は、Cloud Storage とマイクロサービスを使用してスケールアウトされた高トラフィック システムを分析した結果です。テール レイテンシの変動の主な原因は、測定エラー、ペイロードのサイズ、クラウド サービスのレイテンシの変動、およびアプリをホストする仮想マシンの負荷でした。

クラウドのユーザーは、ライブラリに含まれる構築済みの統合から提供される指標、クラウド プロバイダがサポートする指標、およびカスタム指標のいずれかを選択できます。構築済みの統合から提供される指標としては、OpenCensus と gRPC、HTTP、SQL の統合の例があります。Google Cloud では、Monitoring を通じて公開されている多数の指標がサポートされています。もう 1 つの方法は、追加のカスタム指標をコーディングすることです。多くの場合、タイマやカウンタがコーディングされます。マイクロサービスのレイテンシのソースとアプリデータのストレージを分析する際の一般的なタスクとして、上記の 3 つのソースを時系列で比較することが挙げられます。

テストアプリの概要

テストアプリはテール レイテンシの問題をシミュレートし、OpenCensus および Monitoring と統合して、問題を特定するために必要なツールとアプローチを示します。ソースコードとビルドファイルと手順は、GitHub プロジェクトで提供されます。サンプルアプリは Java で記述されていますが、このドキュメントは他の言語にも適用できます。Jetty Integration for JavaGo で、HTTP リクエストの OpenCensus インストゥルメンテーションの詳細を確認できます。テストアプリは、この GitHub のサンプルコードに基づいています。

以下はアプリの概略図です。

Compute Engine 上の Cloud Storage およびサーバーアプリと通信するクライアント アプリのアーキテクチャ図。

クライアント アプリは、Cloud Storage および Compute Engine インスタンスでホストされるサーバー側アプリと通信します。

以下は、典型的なリクエストのフローです。

  1. Cloud Storage API が、クライアント アプリの Cloud Storage から JSON ファイルを取得します。
  2. ファイルの内容がサーバーに送信されます。
  3. サーバーは、クライアントから送信されたデータを処理して、実際のアプリが使用する時間とリソースをシミュレートします。
  4. HTTP レスポンスがクライアントに返されます。
  5. クライアントがダウンストリーム処理を実行します。この時点で、テストアプリによりビジネス ロジックが単純な算術に置き換えられます。

アプリがスタートアップする際に、次の初期化が行われます。

  • クライアントの Java Util Logging(JUL)が初期化され、トレース ID を使用して Cloud Logging がエクスポートされます。サーバーが、Logback アペンダーを使用してトレースとログの相関係数を取得します。
  • OpenCensus HTTP 指標ビューが登録されます。OpenCensus の JAVA 用 HTTP 統合には、レイテンシ、HTTP レスポンス コード、および送受信されたバイト数に関する多数の指標ビューが含まれています。
  • OpenCensus Monitoring stats エクスポータが、集計された指標をバックグラウンド スレッドで Monitoring に送信します。
  • OpenCensus Monitoring トレース エクスポータが、バックグラウンド スレッドで Monitoring にトレーススパンを送信します。
  • Cloud Storage クライアント API が、HTTP ペイロードに使用されるファイルをダウンロードします。
  • アプリ スレッドプールが、アプリへの負荷を駆動するために作成されます。複数のスレッドにより、単一のスレッドよりもサーバーに高い負荷がかかります。

モニタリング指標とトレースデータが、次の手順を使用して収集および処理されます。

  1. OpenCensus ライブラリが、指標データとトレースデータを収集します。
  2. OpenCensus が、指標データを定期的に集約し、Monitoring にエクスポートします。トレースデータは、集約されずに Trace にエクスポートされます。
  3. OpenCensus が、Cloud Logging エントリにトレース ID を追加します。ログエントリが、Cloud Logging サービスにエクスポートされます。

OpenCensus で収集された指標は、ストレージ、分析、可視化、およびアラートを提供する多くのバックエンド モニタリング システムにエクスポートできます。各システムにはそれぞれ異なるデータ表現形式が存在しています。このドキュメントでは、Monitoring に焦点を当てます。

集約されたモニタリング指標の精度

OpenCensus と Monitoring によって、アプリの性能をモニタリングするために使用できるツールが提供されます。チャート上に表示される線を誤って理解しないようにするには、特に 99 パーセンタイル(p99)などのテール レイテンシを表す線が作成された経緯を理解する必要があります。次のセクションでは、指標データの集計の制限について説明します。

Monitoring での指標時系列の表現

Monitoring では、数値間隔でのバケット境界に基づいて、分布指標のレイテンシ パーセンタイルが計算されます。この方法は、Monitoring と OpenCensus で使用される一般的なもので、OpenCensus が指標データを表現して Monitoring にエクスポートします。Cloud Monitoring API の TimeSeries.list メソッドの戻り値は、プロジェクトと指標のタイプのバケットのカウントと境界です。Cloud Monitoring API BucketOptions オブジェクトでバケットの境界を取得できます。この値は、TimeSeries.list API Explorer でテストできます。

API Explorer で OpenCensus HTTP クライアントのレイテンシをフィルタリングするには、次のフィルタを使用できます。

resource.type=global metric.type="custom.googleapis.com/opencensus/opencensus.io/http/client/roundtrip_latency"

結果には、データポイント オブジェクトの配列が含まれます。次の例は、バケットとバケット カウントのスキームを示しています。

"points": [ {
  "interval": { "startTime": "2019-02-14T18:11:24.971Z",
                "endTime": "2019-02-14T18:33:35.541Z" },
  "value": {
    "distributionValue": {
...
    "explicitBuckets": {
      "bounds": [0, 1, 2, 3, 4, 5, 6, 8, 10, 13, 16, 20, 25, 30, 40, 50, 65, 80, 100, 130, ...] }
              },
      "bucketCounts": [0, 0, 0, 0, 0, 14, 17, 164, 3, 0, 1, 0, 0, 0, 0, ...]
}}]

レイテンシ値のモニタリング チャートに表示される各ポイントは、分布から導出されます。各バケットの境界を定義する代わりに、増加係数を使用してバケットを定義できます。たとえば、増加係数が 2.0 の場合、バケット境界は 0-1、1-2、2-4、4-8、...になります。Monitoring の指標について詳しくは、指標タイプの構造をご覧ください。

このチャートを編集して、50 パーセンタイル(中央値)、95 パーセンタイル、および 99 パーセンタイルのレイテンシのラインを示した次のラインチャートを表示できます。

50、95、および 99 パーセンタイルを表示するテール レイテンシ チャート。

これらのパーセンタイル値の計算に使用されるデータを理解するには、ヒートマップ チャートタイプを追加します。Aggregatorsum に設定されている場合、次のクライアント レイテンシ ヒートマップが表示されます。

テール レイテンシに関するヒートマップ チャート。

ヒートマップは、Monitoring によって保存された分布データを表示する方法のひとつです。ヒートマップの領域は、REST API を使用して取得されたバケット境界に対応しています。ヒートマップの領域にポインタを置くと、特定のバケットに一定期間含まれているポイントの数を確認できます。折れ線グラフのパーセンタイル値の計算に使用されるデータはまばらです。

より精確なレイテンシの測定が必要な場合は、いくつかの戦略を利用できます。

  • データを追加する。テストでは多くのデータを生成できますが、本番アプリへのトラフィックが不足する可能性があります。
  • バケットを小さくし、データに合わせて境界を変更する。これは、独自のカスタム指標を作成する場合のオプションです。ただし、事前に構築された OpenCensus 統合からのデータを使用している場合、または Google Cloud によってバックエンド サービスから収集されたデータを使用している場合、これらの調整を行うことができない場合があります。OpenCensus 統合のバケット境界は、Views の OpenCensus 統合の実装者が決定します。たとえば、HTTP クライアント レイテンシ バケットの境界は、クラス HttpViewConstants.java で定義されます。同様に、Google Cloud指標は Monitoring で内部的に定義されます。
  • テール パーセンタイルの指標データの代わりにトレースまたはログを使用する。これらのオプションについては、このドキュメントの後のセクションで説明します。

シミュレートされたデータ

集計モデルの精度をランダム分布から取得した生のシミュレーション データと比較して、バケットの境界がどの程度の違いをもたらすかを確認できます。この例では、ベータ分布により、実際のレイテンシ値の典型的な偏りのある分布をモデル化しています。これは、負の値がない連続的なランダム変数の分布であり、明確なピークと長く減少していくテールから成ります。このベータ分布では、NumPyrandom.beta 関数をパラメータ a = 2, b = 5 で使用し、70 の定数係数を乗算して、中央値が 18.5 ms の現実的なレイテンシ値をシミュレートしています。このシミュレーションには、GitHub プロジェクトに含まれる Colab シート tail_latency_lab.ipynb のベータ分布からの 100,000 のランダムな値が含まれます。

次のグラフは、growthFactor = 2.0 でバケットの間隔が空きすぎているため、テール レイテンシを正確に推定できないことを示しています。

増加係数 2.0 を示す集計モデル。

チャートの線形軸は、ランダム分布の意図された形状を示します。次のグラフは、growthFactor = 1.4 のバケット境界を示しています。

増加係数 1.4 を示す集計モデル。

次のグラフは、growthFactor = 1.2 のバケット境界が意図した形状に近いことを示していますが、分布の高いほうの端はなおやや粗いままになっています。

増加係数 1.2 を示す集計モデル。

次の表は、未加工の値に基づく計算と比較したバケットベースの分布に基づく推定値を示しています。

分布 中央値 99 パーセンタイル
未加工 18.5 49.5
増加係数 2.0 19.2 62.0
増加係数 1.4 18.7 53.9
増加係数 1.2 18.6 51.1

この場合、99 パーセンタイル レイテンシの合理的に正確な推定値を得るには、増加係数 1.2 を使用する必要があります。OpenCensus エクスポータ内で、未加工の値からサンプリングされた分布に値を変換できます。OpenCensus ビューを作成するときに、バケット境界を構成できます。ビューには Aggregation オブジェクトが含まれます。詳しくは、Java のドキュメントまたは Go のドキュメントをご覧ください。

OpenCensus を使用した HTTP レイテンシの測定

HTTP レイテンシを測定するときは、クライアントからサーバーに HTTP リクエストを送受信する時間を測定し結果を記録します。OpenCensus Tag を作成するか、HTTP クライアント用に事前に構築された統合を使用することにより、この処理をコード内で実装できます。HTTP 統合は、Go では Go HTTP パッケージを使用して、Java では Jetty HTTP クライアントを使用して、それぞれ提供されます。OpenCensus HTTP 統合を使用する利点は、収集するすべての指標に Tag オブジェクトを追加する必要がないことです。

レイテンシの原因の特定

前述のテストアプリでは、テスト自体にストレスを発生させ、テール レイテンシを増加させていました。次のような問題が示されます。

  • ときどき発生する大規模なペイロード
  • 高使用率の CPU
  • 短いタイムアウト
  • 再試行によるアプリ コードパスの変動

以下のセクションでは、これらの問題を検出および定量化する方法について説明します。

大規模なペイロードの影響

ペイロードのサイズの影響を調べるために、次のコードで 20 の HTTP リクエストのうち 1 つで送信されるペイロードのサイズをランダムに増やしました。

static byte[] getContent(String bucket) {
  BlobId blobId = null;
  int n = rand.nextInt(100);
  if (n >= 95) {
    blobId = BlobId.of(bucket, LARGE_FILE);
  } else {
    blobId = BlobId.of(bucket, SMALL_FILE);
  }
  return storage.readAllBytes(blobId);
}

Trace list にレイテンシが長いリクエストのトレースを表示すると、それらのリクエストをより大きなペイロード サイズに関連付けることができます。

レイテンシが長いリクエストを示すトレースリスト。

[Show Events] をクリックすると、送受信されたペイロードの詳細を表示できます。レイテンシが長い場合、ペイロードのサイズが大きくなります。

レイテンシの特定に関しては、次の理由により、Cloud Trace の方が Monitoring よりも優れています。

  • トレースによって、集約された値ではなくリクエストのレイテンシ値を提供される。
  • トレースによって、リクエストのペイロード サイズが示される。

高い CPU 使用率の影響

CPU の使用率が高い場合、同時処理によりテール レイテンシが増加する可能性があり、リソースの競合が発生したり、リクエスト処理のための CPU のキューイングが後で発生したりする場合があります。Monitoring では、Compute Engine インスタンスの組み込み指標の 1 つとして、CPU 使用率が提供されます。ただし、パフォーマンス テストを実行したり、パフォーマンスの問題を調査したりする場合は、メモリ、ディスク使用量、さまざまな種類のリソース競合を示すその他の指標など、オペレーティング システムおよびオープンソース指標をより多く提供するために、Monitoring エージェントをインストールすることをおすすめします。詳しくは、エージェント指標のリストをご覧ください。

自動スケーリングされるため、CPU 使用率の管理は、クライアント アプリよりもサーバーアプリの方が容易です。Compute Engine では、マネージド インスタンス グループは、平均 CPU 使用率、負荷分散のサービス容量、または Monitoring の指標に基づいた自動スケーリング ポリシーを使用できます。これらのポリシーでは、負荷を処理するためにフリートを適切にサイズ設定するための仮想マシンを追加します。クライアントの CPU 使用率を一貫して管理することが困難になる場合があります。また、ペイロードをネットワークから読み取ってシリアル化解除する必要があるため(CPU 使用率が増大)、クライアントの CPU 使用率がレイテンシの測定値に影響を与える可能性があります。クライアント アプリにおけるレイテンシの表示によりユーザー エクスペリエンスが大幅に影響を受けるため、このドキュメントではそうしたレイテンシに焦点を当てます。

通常、CPU の使用率が高い理由は 1 つの HTTP リクエストだけに帰着できないため、CPU 使用率の高い効果を特定する方法としては、トレースよりもモニタリングの方が適切です。次の例では、テストアプリを使用して複数のエグゼキュータ スレッドを一度に実行し、g1-small 仮想マシンでクライアント コードを実行することにより、CPU 使用率の影響を調査しています。次に、この CPU 使用率とレイテンシが、n1-standard-1 vCPU 仮想マシンで実行されているクライアント アプリの値と比較されます。

次のグラフは、テストの中央値および 95 パーセンタイルのエンドツーエンドのレイテンシを示しています。リクエスト間のスリープ ステートメントの削除によりリクエスト率が午前 3:21 に増加しました。これは、CPU 使用率の大幅な増加に伴ってレイテンシが変動したことを示しています。仮想マシンを作成しテストを実行するコマンドは、GitHub リポジトリから利用できます。

インスタンス ID チャートが示すレイテンシの中央値。

上のグラフは、負荷テスト中のクライアントとサーバー双方のレイテンシの中央値を示しています。負荷が増加した 3:21 時点の増加に注意してください。次のグラフは、同じテスト中の 95 パーセンタイルのレイテンシを示しています。

インスタンス ID チャートが示す 95 パーセンタイルのレイテンシ。

次のグラフは、このテストの CPU 使用率を示しています。3:21 時点でも増加しています。

Compute Engine インスタンスの CPU 使用率グラフ。

リクエスト率を上げるとレイテンシに影響しますが、CPU 使用率には比例しません。小規模インスタンスが約 78% の CPU 使用率で実行されていたにもかかわらず、1 vCPU と小規模インスタンスの両方でレイテンシが一致しているというのは驚くべきことです。この結果は、CPU 使用率が高いデバイスを実行できることを示しています。ただし、ここで注意が必要なのは、このテストはベンチマーク調査を目的としたものではないため、アプリの実装中に結果が異なる可能性があることです。

Cloud Profiler は、CPU 消費量が高いインスタンスを調査するうえで役立つツールです。

アプリコードのブランチとパラメータ値によるレイテンシ

ロギングは、アプリのレイテンシに関する最も困難な問題を解決するのに役立ちます。このセクションでは、ログデータとトレースデータを組み合わせて、さまざまなコードパスとパラメータ値の影響を受けるレイテンシの問題を調査する方法を示します。トレースをログと組み合わせるアプローチにより、コードに多くのタイミング ステートメントを追加するのを回避します。マイクロサービス ベースのアプリにおける一般的な問題は、タイムアウトと再試行の管理です。タイムアウトが長い場合、ユーザー エクスペリエンスが低下し、接続数が多くなった場合にアプリが無効になる可能性があります。タイムアウトを短く設定し、しばらく待ってから再試行することをおすすめします。ただし、頻繁に再試行すると、再試行のストームにつながり、インシデントの回復を困難にする可能性が生じます。タイムアウトを設定して、リクエストのごく一部(たとえば 1% 未満)で再試行が必要になるようにする必要がありますただし、テストアプリは、テストサーバーへの HTTP リクエストの再試行時間を低い値に設定して、実際の停止が発生するのを待たずにアクションの再試行を行います。

再試行は Cloud Storage 用の Google API クライアント ライブラリにも実装されているため、独自のコードで実装する必要はありません。指数バックオフについて詳しくは、指数バックオフの切り捨てをご覧ください。

OpenCensus Monitoring Log Correlation 統合を使用すると、トレースからログエントリを表示できます。この統合では、Cloud Logging の Enhancer を使用して、トレース情報がログに追加されます。Logging for Java をセットアップし、opencensus-contrib-log-correlation-stackdriver1 Maven 依存関係をビルドに追加すれば、このトレース情報をアプリに追加できます。このドキュメントの執筆時点では Go とのログ統合は実装されていませんが、機能をリクエストすることはできます。Go の現在の代替方法は、トレーススパンに注釈で必要な情報を追加することです。

マイクロサービスへのリクエストを準備、送信、処理するためのテストアプリのメソッドは次のとおりです。

private void prepareSendProcess(
    HttpClient httpClient,
    HttpMethod method,
    Function<Integer[], Integer> downStreamFn,
    String fnName)
    throws InterruptedException {
  Tracer tracer = Tracing.getTracer();
  try (Scope scope = tracer.spanBuilder("main").startScopedSpan()) {
    StopWatch s = StopWatch.createStarted();
    byte[] content = new byte[0];
    if (method == HttpMethod.POST) {
      content = TestInstrumentation.getContent(testOptions.bucket());
    }
    byte[] payload = sendWithRetry(httpClient, method, content);
    TestInstrumentation.processPayload(payload, downStreamFn, fnName);
    TestInstrumentation.recordTaggedStat(
        method.toString(), s.getTime(TimeUnit.NANOSECONDS) / 1.0e6);
  }
}

このメソッドは、準備、HTTP リクエストのサーバーへの送信、およびダウンストリーム処理といったすべてのフェーズのコードをカバーするリクエストの最上位トレースとして、スコープ付きスパンを作成します。prepareSendProcess メソッドは、sendWithRetry を呼び出し、HTTP リクエストを再試行メカニズムで終了させます。

private byte[] sendWithRetry(HttpClient httpClient, HttpMethod method, byte[] content)
    throws InterruptedException {
  ExponentialBackOff backoff = new ExponentialBackOff.Builder()
    .setInitialIntervalMillis(500)
    .setMaxElapsedTimeMillis(5*60*1000)
    .setMultiplier(2.0)
    .setRandomizationFactor(0.5)
    .build();
  for (int i = 0; i < MAX_RETRIES; i++) {
    try {
      return sendRequest(httpClient, method, content);
    } catch (RetryableException e) {
      LOGGER.log(Level.WARNING, "RetryableException attempt: " + (i + 1) + " " + e.getMessage());
    } catch (InterruptedException e) {
      LOGGER.log(
          Level.WARNING, "InterruptedException attempt: " + (i + 1) + " " + e.getMessage());
    } catch (TimeoutException e) {
      LOGGER.log(Level.WARNING, "TimeoutException attempt: " + (i + 1) + " " + e.getMessage());
    } catch (ExecutionException e) {
      LOGGER.log(Level.WARNING, "ExecutionException attempt: " + (i + 1) + " " + e.getMessage());
    }
    try {
      Thread.sleep(backoff.nextBackOffMillis());
    } catch(IOException e) {
      throw new RuntimeException("MaxElapsedTime exceeded");
    }
  }
  throw new RuntimeException("Max retries exceeded");
}

次のメソッドは HTTP リクエストを送信します。

private byte[] sendRequest(HttpClient httpClient, HttpMethod method, byte[] content)
    throws InterruptedException, TimeoutException, ExecutionException, RetryableException {
  String targetURL = testOptions.targetURL();
  HttpRequest request = (HttpRequest) httpClient.newRequest(targetURL).method(method);
  if (request == null) {
    throw new RetryableException("Request is null");
  }
  if (method == HttpMethod.POST) {
    ContentProvider contentProvider =
        new StringContentProvider(new String(content, StandardCharsets.UTF_8));
    request.content(contentProvider, "application/json");
  }
  request.timeout(testOptions.httpTimeout(), TimeUnit.MILLISECONDS);
  ContentResponse response = request.send();
  int status = response.getStatus();
  LOGGER.info("Response status: " + status + ", " + method);
  if (HttpStatus.isSuccess(status)) {
    byte[] payload = response.getContent();
    LOGGER.info("Response payload: " + payload.length + " bytes");
    return payload;
  } else if (HttpStatus.isServerError(status)) {
    throw new RetryableException(response.getReason());
  }
  return new byte[0];
}

このメソッドは、HTTPRequest オブジェクトを作成し、POST リクエストが送信された場合にペイロードを追加します。以下にトレースの例を詳しく示します。

`HTTPRequest` オブジェクトのトレース例。

Monitoring で [Show Logs] をクリックすると、ログがトレース詳細ビューに表示されます。トレースの検索と表示で説明されているように、[Trace Detail] アイコンをクリックすると、トレース情報が表示されます。ログテキストをソースコードと照合し表示されたトレースを生成するために使用されたコードパスについて理解するとともに、HTTP のメソッドやレスポンスなどの他のパラメータについての詳細を確認できます。前の例では、このトレースでタイムアウトが発生しました。バックオフによるペナルティが課されるため、その後スパンが長くなります。再試行も 6 回行われますが、これが構成されている最大数です。

トレース イベントを表示するには、[Show Events] をクリックします。

レイテンシが長いイベントをトレースする。

レイテンシが長いのは、ペイロードが大きいためです。8 ミリ秒のタイムアウトは、この大きなペイロードを処理するには低すぎました。タイムアウトをより高い値にリセットする必要があります。

トレーススパンには、ログ ステートメントと同様の情報を注釈として追加できます。ただし、アプリのさまざまなコードパスに関する主要な情報をトレーススパンに追加するには、アプリのコードにトレーススパンのコードを追加する必要があります。開発チームがトレースに慣れていない場合は、JUL または Logback を使用してこれをログ ステートメントに追加し、Logging for Java を設定する方が簡単かもしれません。さらに、コードにすでにログ ステートメントが含まれている場合があります。

最も遅いリクエストを特定するために、次のスクリーンショットに示すように、さまざまなリクエスト パーセンタイルのサンプル トレースを含むトレース分析レポートを生成できます。

さまざまなリクエスト パーセンタイルのサンプル トレースを含むトレース分析レポート。

パーセンタイルがより高い詳細なトレースを表示するには、サンプル トレースをクリックします。

BigQuery でのログ ステートメントとトレース ID の組み合わせ

さらにログ情報を検索するには、ログフィルタを使用して Cloud Logging ログビューア上でログを直接クエリできます。

ログフィルタを使用したログクエリ。

このフィルタの便利な点の 1 つは、同じトレース ID を持つ 3 つのログエントリを接続できることです。トレース ID を使用すると、同じリクエストからのログエントリを接続できます。次に、resource.type="gce_instance" などのフィルタを使用して、ログエントリを BigQuery にエクスポートできます。

Compute Engine インスタンスのためのログフィルタ。

application_test_dataset というデータセットにログをエクスポートする場合、次のクエリを使用してログを探索できます。

SELECT
  TIME(timestamp) AS Time,
  SUBSTR(textPayload, 90) as Message,
  SUBSTR(trace, 31) as trace_id
FROM
  `application_test_dataset.java_log_20190328`
WHERE REGEXP_CONTAINS(textPayload, "attempt")
LIMIT 10;
...
Time             Message                            trace_id
10:59:11.782000  WARNING: TimeoutException attempt: 008a0ce...

サンプルデータの 1 行が表示されます。クエリの結果により、ログビューアにこれと同様の情報が表示されます。BigQuery にログデータが存在しているため、より強力なクエリが実行できます。次のクエリは、再試行回数が異なるリクエストの数を示しています。

SELECT
  RetryCount,
  COUNT(trace) AS RequestCount
FROM(
  SELECT
    COUNT(REGEXP_CONTAINS(textPayload, "attempt")) as RetryCount,
    trace
  FROM
    `application_test_dataset.java_log_20190328`
  WHERE NOT REGEXP_CONTAINS(trace, '00000000000000000000000000000000')
  Group BY trace
)
GROUP BY RetryCount
ORDER BY RetryCount DESC
LIMIT 10;
...
RetryCount RequestCount
8          13
7          180
6          2332
5          242
4          507
3          416605
1          1

このクエリの結果から、最大 8 回の再試行回数で 13 件のリクエストがあったことがわかります。このクエリの結果を使用して、再試行パラメータを調整できます。たとえば、タイムアウトを増やしたり、ペイロードのサイズに従ってタイムアウトの値を変えたり、再試行の最大回数を増やしたりできます。

次のステップ