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

Last reviewed 2019-08-28 UTC

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

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

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

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

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

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

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

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

このドキュメントは、OpenCensus、Cloud Monitoring、Cloud Trace、BigQuery の基本的な使用方法と 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 Java と Go で、HTTP リクエストの OpenCensus インストゥルメンテーションの詳細を確認できます。テストアプリは、この GitHub のサンプルコードに基づいています。

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

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

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

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

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

アプリの起動時、次の初期化が行われます。

クライアントの 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 ペイロードに使用されるファイルをダウンロードします。
アプリスレッドプールが、アプリへの負荷を駆動するために作成されます。複数のスレッドにより、単一のスレッドよりもサーバーに高い負荷がかかります。

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

OpenCensus ライブラリが、指標データとトレースデータを収集します。
OpenCensus が、指標データを定期的に集約し、Monitoring にエクスポートします。トレースデータは、集約されずに Trace にエクスポートされます。
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 パーセンタイルを表示するテールレイテンシチャート。

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

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

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

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

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

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

集計モデルの精度をランダム分布から取得した生のシミュレーションデータと比較して、バケットの境界がどの程度の違いをもたらすかを確認できます。この例では、ベータ分布により、実際のレイテンシ値の典型的な偏りのある分布をモデル化しています。これは、負の値がない連続的なランダム変数の分布であり、明確なピークと長く減少していくテールから成ります。このベータ分布では、NumPy の random.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 つで送信されるペイロードのサイズをランダムに増やしました。

client/src/main/java/com/google/cloud/solutions/opencensus/client/TestInstrumentation.java

GitHub で表示

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 の現在の代替方法は、トレーススパンに注釈で必要な情報を追加することです。

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

client/src/main/java/com/google/cloud/solutions/opencensus/client/JettyTestClient.java

GitHub で表示

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 リクエストを再試行メカニズムで終了させます。

client/src/main/java/com/google/cloud/solutions/opencensus/client/JettyTestClient.java

GitHub で表示

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 リクエストを送信します。

client/src/main/java/com/google/cloud/solutions/opencensus/client/JettyTestClient.java

GitHub で表示

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 の組み合わせ

さらにログ情報を検索するには、ログフィルタを使用して Logs Explorer でログを直接クエリします。

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

このフィルタの便利な点の 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 件のリクエストがあったことがわかります。このクエリの結果を使用して、再試行パラメータを調整できます。たとえば、タイムアウトを増やしたり、ペイロードのサイズに従ってタイムアウトの値を変えたり、再試行の最大回数を増やしたりできます。

次のステップ

次の点を見直す。
- OpenCensus のその他の統合と API。
- Monitoring のドキュメントに記された、サポートされているその他の指標および API。
OpenCensus の Java HTTP 統合の詳細を確認する。
OpenCensus GitHub プロジェクトでオープンソースのコードと例を確認する。
エクスポートしたログを使用するにあるとおり、BigQuery でログをクエリする。
Google Cloud に関するリファレンスアーキテクチャ、図、チュートリアル、ベストプラクティスを確認する。Cloud Architecture Center を確認します。

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

用語

背景

テストアプリの概要

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

Monitoring での指標時系列の表現

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

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

レイテンシの原因の特定

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

高い CPU 使用率の影響

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

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

次のステップ

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