Java クライアント ライブラリのレイテンシのトラブルシューティング

はじめに

Java Datastore クライアントで通常よりもレイテンシが高くなったり、スループットが低下したり、タイムアウトが発生したりする場合は、Firestore/Datastore バックエンドではなく、クライアントサイドの gRPC 構成に問題がある可能性があります。このガイドは、一般的なクライアントサイドのスロットリングの問題、チャネル プールの不適切な設定、過剰なチャネル チャーンの診断と解決に役立ちます。

診断

Java クライアントを使用する場合は、チャネル プールの動的モニタリング、スロットリングの診断、接続の再利用に関する問題の診断、過剰なチャネル チャーンの特定に、詳細な gRPC と gax-java のロギングを有効にすることが重要です。

Java クライアントのロギングを有効にする

詳細なロギングを有効にするには、logging.properties ファイルを次のように変更します。

## This tracks the lifecycle events of each grpc channel 
io.grpc.ChannelLogger.level=FINEST
## Tracks channel pool events(resizing, shrinking) from GAX level
com.google.api.gax.grpc.ChannelPool.level=FINEST

また、これらのログをキャプチャするように、logging.properties の出力ロギング レベルを更新します。


# This could be changed to a file or other log output
handlers=java.util.logging.ConsoleHandler
java.util.logging.ConsoleHandler.level=FINEST
java.util.logging.ConsoleHandler.formatter=java.util.logging.SimpleFormatter

構成を適用する

logging.properties ファイルは、次の 2 つの方法のいずれかを使用して適用できます。

1. JVM システム プロパティを使用する

Java アプリケーションを起動するときに、この引数を追加します。

-Djava.util.logging.config.file=/path/to/logging.properties

2. プログラムで読み込む

このメソッドは、ログ構成がコード内で管理されている統合テストやアプリケーションで役立ちます。このコードがアプリのライフサイクルの早い段階で実行されるようにします。

LogManager logManager = LogManager.getLogManager();
  try (final InputStream is = Main.class.getResourceAsStream("/logging.properties")) {
logManager.readConfiguration(is);
}

ロギングの例

詳細ロギングを有効にすると、com.google.api.gax.grpc.ChannelPool と io.grpc.ChannelLogger のメッセージが混在して表示されます。

チャンネルのプロビジョニング不足によりチャンネル プールの拡張がトリガーされた:

09:15:30.123 [pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 40, expanding channel pool size: 4 -> 6. 
09:15:30.124 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] Entering IDLE state 
09:15:30.124 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] Entering IDLE state 
09:15:30.125 [grpc-nio-worker-ELG-1-5] TRACE io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] newCall() called 
09:15:30.126 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] Entering CONNECTING state 09:15:30.127 [grpc-nio-worker-ELG-1-5] DEBUG io.grpc.ChannelLogger - [Channel<5>: (datastore.googleapis.com:443)] Entering READY state with picker: Picker{result=PickResult{subchannel=Subchannel<7>: (datastore.googleapis.com:443), streamTracerFactory=null, status=Status{code=OK, description=null, cause=null}, drop=false, authority-override=null}} 
09:15:31.201 [grpc-nio-worker-ELG-1-6] TRACE io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] newCall() called 
09:15:31.202 [grpc-nio-worker-ELG-1-6] DEBUG io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] Entering CONNECTING state 09:15:31.203 [grpc-nio-worker-ELG-1-6] DEBUG io.grpc.ChannelLogger - [Channel<6>: (datastore.googleapis.com:443)] Entering READY state with picker: Picker{result=PickResult{subchannel=Subchannel<8>: (datastore.googleapis.com:443), streamTracerFactory=null, status=Status{code=OK, description=null, cause=null}, drop=false, authority-override=null}}

チャンネルがオーバー プロビジョニングされ、チャンネル プールの縮小がトリガーされた:

09:13:59.609 [grpc-nio-worker-ELG-1-4] DEBUG io.grpc.ChannelLogger - [Channel<21>: (datastore.googleapis.com:443)] Entering READY state with picker: Picker{result=PickResult{subchannel=Subchannel<23>: (datastore.googleapis.com:443), streamTracerFactory=null, status=Status{code=OK, description=null, cause=null}, drop=false, authority-override=null}}
09:14:01.998 [pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput drop to 0, shrinking channel pool size: 8 -> 6.
09:14:01.999 [pool-1-thread-1] TRACE io.grpc.ChannelLogger - [Channel<13>: (datastore.googleapis.com:443)] shutdown() called
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<13>: (datastore.googleapis.com:443)] Entering SHUTDOWN state
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<13>: (datastore.googleapis.com:443)] Terminated
09:14:01.999 [pool-1-thread-1] TRACE io.grpc.ChannelLogger - [Channel<15>: (datastore.googleapis.com:443)] shutdown() called
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<15>: (datastore.googleapis.com:443)] Entering SHUTDOWN state
09:14:01.999 [pool-1-thread-1] DEBUG io.grpc.ChannelLogger - [Channel<15>: (datastore.googleapis.com:443)] Terminated

これらのログエントリは、次の用途に役立ちます。

  1. チャンネル サイズ変更の決定をモニタリングする
  2. チャンネルの再利用の識別。解約
  3. Transport 接続の問題を特定する

症状の診断のためのログの解釈

レイテンシが高い、エラーが発生するなどのパフォーマンスの問題のトラブルシューティングを行う場合は、まず com.google.api.gax.grpc.ChannelPool と io.grpc.ChannelLogger のロギングを有効にします。次に、このガイドの一般的なシナリオと観察された症状を照合して、ログを解釈し、解決策を見つけます。

症状 1: 起動時またはトラフィックの急増時にレイテンシが高い

アプリケーションの起動直後のリクエストが遅い場合や、トラフィックが急増するたびにレイテンシが大幅に増加する場合があります。

考えられる原因

このレイテンシは、チャネル プールのプロビジョニングが不足している場合によく発生します。各 gRPC チャネルで処理できる同時リクエストの数には上限があります（Google ミドルウェアによって 100 に制限されています）。この上限に達すると、新しい RPC はクライアント側でキューに登録され、利用可能なスロットを待ちます。このキューイングがレイテンシの主な原因です。

チャネル プールは負荷の変化に適応するように設計されていますが、サイズ変更ロジックは定期的に（デフォルトでは 1 分ごと）実行され、徐々に拡張されます（デフォルトでは、一度に最大 2 つのチャネルを追加します）。そのため、最初のトラフィックの急増とプールの拡張の間には、固有の遅延があります。この期間中、新しいリクエストは、飽和状態のチャネルがクリアされるか、プールが次のサイズ変更サイクルで新しいチャネルを追加するまで待機するため、レイテンシが発生します。

確認するログ

チャネル プールが拡大していることを示すログを探します。これは、クライアントが現在の容量を超えたトラフィックのピークに反応していることを示す主な証拠です。

チャネル プール拡張ログ:

[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 40, expanding channel pool size: 4 -> 6.

解釈: プールでトラフィックの急増が検出され、負荷の増加に対応するために新しい接続が開かれています。頻繁な拡張（特に起動時）は、初期構成が一般的なワークロードに十分でないことを明確に示しています。

解決方法

目標は、トラフィックが到着する前に十分なチャネルを準備し、クライアントがプレッシャーの中でチャネルを作成する必要がないようにすることです。

initialChannelCount を増やす（起動時のレイテンシが高い）:

起動時にレイテンシが高い場合は、ChannelPoolSettings の initialChannelCount を増やすのが最も効果的な解決策です。デフォルトでは、この値は 10 に設定されています。起動時に大量のトラフィックを処理するアプリケーションの場合、この値は小さすぎる可能性があります。

アプリケーションに適した値を見つけるには、次の手順を行います。

  1. com.google.api.gax.grpc.ChannelPool の FINEST レベルのロギングを有効にします。
  2. 一般的な起動ワークロードまたはトラフィック スパイクでアプリケーションを実行します。
  3. チャネル プールの拡張ログを観察して、プールが安定するサイズを確認します。

たとえば、次のようなログが表示された場合:
[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 80, expanding channel pool size: 4 -> 6.

1 分後にログが表示されます。

[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - Detected throughput peak of 95, expanding channel pool size: 6 -> 8.

拡張されたチャネル プール サイズが 8 チャネルで安定し、拡張ログが見つからない場合は、アプリケーションがワークロードを処理するために 8 チャネルを必要としていたことを示します。initialChannelCount を 8 に設定することをおすすめします。これにより、接続が事前に確立され、オンザフライ スケーリングによるレイテンシが軽減または解消されます。

この目標は、リクエストをキューに登録することなくピーク時の負荷を処理するのに十分な容量をプールに確保することです。

minChannelCount の増加（トラフィックの急増）:

トラフィック スパイクの開始時にレイテンシが高くなる場合は、トラフィックの増加速度がチャネルプールの新しい接続の作成速度よりも速いことを示しています。これは、トラフィックの急増が予測可能なアプリケーションでよく見られます。

プールは、通常のトラフィックでは少数のチャネルで安定し、トラフィックが増加すると、飽和を防ぐためにチャネルを積極的に追加します。このスケーリング プロセスには時間がかかるため、バーストの最初のリクエストがキューに登録され、レイテンシが高くなります。

minChannelCount を増やすと、永続的に開いているチャネルのベースラインが高くなります。これにより、初期バーストを処理するのに十分な容量がすでに確保され、スケーリングの遅延と関連するレイテンシの急増が解消されます。

maxChannelCount の増加（トラフィックの急増）:

トラフィックの急増時にレイテンシが高く、ログにチャネル プールが常に最大サイズ（maxChannelCount）であることが示されている場合は、現在の上限がピーク トラフィックに対して低すぎる可能性があります。デフォルトでは、maxChannelCount は 200 に設定されています。より適切な値を決定するには、接続プール構成ガイドを使用して、アプリケーションのピーク時の秒間クエリ数（QPS）と平均リクエスト レイテンシに基づいて最適な接続数を計算します。

症状 2: 断続的なタイムアウトまたは RPC エラー

アプリケーションは通常は正常に動作しますが、通常のトラフィック期間でも、断続的なタイムアウトや RPC エラーが発生することがあります。

考えられる原因: ネットワークが不安定

クライアントと Datastore サービス間の接続が切断されている。gRPC クライアントは自動的に再接続を試みますが、このプロセスにより一時的な障害やレイテンシが発生する可能性があります。

確認するログ

ネットワークの問題の診断に最も重要なログは TRANSIENT_FAILURE です。

  • 一時的なエラーログ:
[grpc-nio-worker-ELG-1-7] DEBUG io.grpc.ChannelLogger - [Channel<9>: (datastore.googleapis.com:443)] Entering TRANSIENT_FAILURE state
  • 解釈: このログは、チャンネルの接続が失われたことを示す重大な警告です。単一の分離された障害は、ネットワークの小さな一時的な障害である可能性があります。ただし、これらのメッセージが頻繁に表示される場合や、チャンネルがこの状態から抜け出せない場合は、根本的な重大な問題があることを示しています。

解決方法

ネットワーク環境を調査します。アプリケーションと datastore.googleapis.com の間のファイアウォール、プロキシ、ルーター、または一般的なネットワークの不安定さに関する問題を確認します。

症状 3: クライアントあたり 20,000 件を超える同時リクエストによる高レイテンシ

この特定の症状は、非常に大規模に実行されているアプリケーションに当てはまります。通常、単一のクライアント インスタンスが 20,000 件を超える同時リクエストを処理する必要がある場合に発生します。アプリケーションは通常の条件下では良好に動作しますが、クライアントあたりの同時リクエスト数が 20,000 を超えると、パフォーマンスが急激に低下します。レイテンシが大幅に増加し、トラフィックのピーク期間全体にわたって高い状態が続きます。これは、クライアントの接続プールが最大サイズに達し、それ以上スケールアウトできないために発生します。

考えられる原因

チャネルプールが構成済みの maxChannelCount に達したため、クライアントでチャネル飽和が発生しています。デフォルトでは、プールは 200 チャンネルの上限で構成されています。各 gRPC チャネルで同時に処理できるリクエストは最大 100 件であるため、この上限に達するのは、単一のクライアント インスタンスが約 20,000 件のリクエストを同時に処理している場合のみです。

プールがこの上限に達すると、それ以上の接続を作成できなくなります。200 個のチャネルがすべて過負荷になり、新しいリクエストがクライアント側でキューに登録されるため、レイテンシが急増します。

次のログは、maxChannelCount に到達したことを確認するのに役立ちます。

確認するログ

重要な指標は、負荷が継続しているにもかかわらず、チャネル プールが構成された上限で拡張を停止することです。

  • ログ: プールの拡張に関する以前のログが表示されます。デフォルト設定では、レイテンシの急増前に表示される最後の拡張ログは、プールが 200 チャンネルに達したログになります。
[pool-1-thread-1] DEBUG com.google.api.gax.grpc.ChannelPool - ... expanding channel pool size: 198 -> 200.
  • 指標: レイテンシが高い期間中は、「チャネルプールサイズの拡大」ログが記録されません。これらのログがない場合、レイテンシが高いと、maxChannelCount の上限に達した可能性が高いことを示します。

解決方法

この目標は、リクエストをキューに登録することなくピーク時の負荷を処理するのに十分な容量をプールに確保することです。

  • maxChannelCount を増やす: 主な解決策は、アプリケーションのピーク トラフィックをサポートできる値に maxChannelCount 設定を増やすことです。接続プール構成ガイドを参照して、アプリケーションのピーク時の秒間クエリ数（QPS）とリクエストの平均レイテンシに基づいて、最適な接続数を計算します。

付録

以降のセクションでは、トラブルシューティングに役立つ補足情報を提供します。

チャンネルの状態について

ログには次のチャネル状態が表示され、接続の動作に関する分析情報が得られます。

状態 説明
IDLE チャンネルは作成されていますが、アクティブな接続や RPC はありません。トラフィックを待機しています。
接続中 チャネルは、gRPC サーバーへの新しいネットワーク トランスポート（接続）の確立を積極的に試みています。
READY チャネルには確立された正常なトランスポートがあり、RPC を送信する準備ができています。
TRANSIENT_FAILURE チャンネルで復元可能な障害（ネットワークの不具合、サーバーの一時的な利用不可など）が発生しました。自動的に再接続を試みます。
SHUTDOWN チャンネルが手動で（shutdown() が呼び出された場合、またはアイドル タイムアウトが原因で切断されます。新しい RPC を開始できません。

ヒント

  • SLF4J や Logback などの構造化ロギング フレームワークを使用する場合は、logback.xml または他のロガー構成ファイルで同等のログレベルを構成する必要があります。java.util.logging レベルはロギング ファサードによってマッピングされます。