Azure Cosmos DB .NET SDK の遅延要求を診断してトラブルシューティングする
適用対象: 
NoSQL
Azure Cosmos DB では、要求が遅くなることがあります。 遅延は、要求の調整やアプリケーションの設計方法など、複数の理由で発生する可能性があります。 この記事では、この問題のさまざまな根本原因について説明します。
要求率が大きすぎる
要求の調整は、遅延要求の最も一般的な理由です。 Azure Cosmos DB では、データベースまたはコンテナーに割り当てられた要求単位を超えた場合に要求は調整されます。 SDK には、これらの要求を再試行するロジックが組み込まれています。 要求率が大きすぎる場合のトラブルシューティングに関する記事では、要求が調整されているかどうかを確認する方法についてしています。 また、この記事では、今後これらの問題を回避するためにアカウントを拡張する方法についても説明します。
アプリケーションの設計
アプリケーションを設計するときは、最適なパフォーマンスを得るために、 .NET SDK のベストプラクティスに従っ てください。 アプリケーションが SDK のベスト プラクティスに従っていない場合、要求が遅くなったり、失敗したりする可能性があります。
アプリケーションを開発する場合は、次の点を考慮してください。
- アプリケーションが Azure Cosmos DB アカウントと同じリージョンにある必要があります。
- ApplicationRegion または ApplicationPreferredRegions は、リージョンの設定を反映し、アプリケーションがデプロイされているリージョンを指している必要があります。
- 大量のトラフィックが原因で、ネットワーク インターフェイスにボトルネックが発生している可能性がある。 アプリケーションが Azure Virtual Machines で実行されている場合は、次のような回避策が考えられます。
- 高速ネットワークを有効にした仮想マシンを使用することを検討します。
- 既存の仮想マシンで高速ネットワークを有効にします。
- よりハイエンドな仮想マシンを使用することを検討します。
- 直接接続モードを優先します。
- 高 CPU 使用率を避けてください。 平均ではなく最大 CPU 使用率を確認してください。これは、ほとんどのログ システムの既定値です。 約 40% を超える場合は、待機時間が長くなる可能性があります。
メタデータ操作
データベースまたはコンテナーが存在することを確認する必要がある場合は、Create...IfNotExistsAsync または Read...Async を呼び出して項目操作を行う前に、を呼び出さないでください。 検証は、削除されていることが予想される場合に、必要に応じてアプリケーションの起動時にのみ行う必要があります。 これらのメタデータ操作では、追加の待機時間が発生し、サービス レベルア グリーメント (SLA) はなく、独自の 制限があります。 データ操作のようにスケーリングされません。
一括モードで要求の処理が遅い
一括モードは、待機時間最適化モードではなく、大量データ ボリュームを操作するためのスループット最適化モードです。その目的は、使用可能なスループットを飽和状態にすることです。 一括モードの使用時に要求の処理が遅くなっている場合は、次のことを確認してください。
- アプリケーションがリリース構成でコンパイルされている。
- アプリケーションのデバッグ中に待機時間を測定していない (デバッガーがアタッチされていない)。
- 操作の量が多く、1000 回未満の操作には一括モードを使用していない。 プロビジョニングされたスループットにより、1 秒間に処理できる操作数が決定される。一括モードの目標は、それを最大限に使用することである。
- スロットリングのシナリオでコンテナーを監視する。 コンテナーが大量にスロットリングされている場合は、プロビジョニングされたスループットよりもデータのボリュームが大きいことを意味するため、コンテナーをスケールアップするか、データの量を減らす (一回のデータのバッチを小さくするなど) 必要があります。
async/awaitパターンを正しく使用して、すべての同時タスクを処理しており、非同期操作をブロックしていない。
診断をキャプチャする
CosmosException を含む SDK のすべての応答には、Diagnostics プロパティがあります。 このプロパティでは、再試行または一時的な失敗があるかどうかなど、1 つの要求に関連するすべての情報が記録されます。
診断は文字列として返されます。 文字列は、さまざまなシナリオのトラブルシューティングに対応するために改良されるので、バージョンによって異なります。 SDK の各バージョンでは、文字列の書式設定に重大な変更が加えられる予定です。 破壊的変更を避けるために、文字列を解析しないでください。 次のコード サンプルは、.NET SDK を使用して診断ログを読み取る方法を示しています。
try
{
ItemResponse<Book> response = await this.Container.CreateItemAsync<Book>(item: testItem);
if (response.Diagnostics.GetClientElapsedTime() > ConfigurableSlowRequestTimeSpan)
{
// Log the response.Diagnostics.ToString() and add any additional info necessary to correlate to other logs
}
}
catch (CosmosException cosmosException)
{
// Log the full exception including the stack trace with: cosmosException.ToString()
// The Diagnostics can be logged separately if required with: cosmosException.Diagnostics.ToString()
}
// When using Stream APIs
ResponseMessage response = await this.Container.CreateItemStreamAsync(partitionKey, stream);
if (response.Diagnostics.GetClientElapsedTime() > ConfigurableSlowRequestTimeSpan || !response.IsSuccessStatusCode)
{
// Log the diagnostics and add any additional info necessary to correlate to other logs with: response.Diagnostics.ToString()
}
バージョン 3.19 以降の診断
JSON 構造体では、SDK のバージョンごとに重大な変更が加えられています。 このため、これを解析するのは安全ではありません。 JSON では、SDK を通過する要求がツリー構造で表されます。 以下のセクションでは、いくつかの重要な点について説明します。
CPU の履歴
高い CPU 使用率は、要求遅延の最も一般的な理由です。 最適な待機時間を実現するには、CPU 使用率は 40% ほどである必要があります。 CPU 使用率の (平均ではなく) 最大値を監視するには、間隔として 10 秒を使用します。 CPU スパイクは、要求で 1 つのクエリに対して複数の接続を実行する可能性があるクロスパーティション クエリでは、より一般的です。
タイムアウトには、次のような診断が含まれます。
"systemHistory": [
{
"dateUtc": "2021-11-17T23:38:28.3115496Z",
"cpu": 16.731,
"memory": 9024120.000,
"threadInfo": {
"isThreadStarving": "False",
....
}
},
{
"dateUtc": "2021-11-17T23:38:38.3115496Z",
"cpu": 16.731,
"memory": 9024120.000,
"threadInfo": {
"isThreadStarving": "False",
....
}
},
...
]
cpuの値が 70% を超える場合、タイムアウトは CPU の枯渇が原因である可能性があります。 この場合の解決策は、CPU 使用率が高いソースを調査してそれを減らすか、マシンをより大きなリソース サイズにスケーリングすることです。threadInfo/isThreadStarvingノードの値がTrueになっている場合、原因は使用できるスレッドがないことです。 この場合の解決策は、スレッドの枯渇 (ロックされている可能性のあるスレッド) のソースを調査するか、マシンをより大きなリソース サイズにスケーリングすることです。- 測定間の
dateUtc時間が約 10 秒でない場合、スレッド プールでの競合も示しています。 CPU は、10秒ごとにスレッドプールにエンキューされる独立したタスクとして測定されます。 測定値の間隔が長い場合は、非同期タスクを適切なタイミングで処理できないことを示します。 最も一般的なシナリオは、アプリケーションコードが 非同期コードに対する呼び出しをブロックしている場合です。
解決策
SDK を使用するクライアント アプリケーションをスケールアップまたはスケールアウトする必要があります。
HttpResponseStats
HttpResponseStats は、ゲートウェイに送られる要求です。 直接モードでも、SDK ではゲートウェイからすべてのメタデータ情報が取得されます。
要求の処理速度が遅い場合は、まず、前の提案によって目的の結果が得られないことを確認します。 それでも遅い場合は、パターンによってさまざまな問題が示されます。 次の表で詳細に説明します。
| [要求の数] | シナリオ | 説明 |
|---|---|---|
| 1 つ - すべて | [要求のタイムアウト または HttpRequestExceptions] |
SNAT ポートの枯渇または時間内に要求を処理するマシン上のリソースの不足を示しています。 |
| 1 つまたは少ない割合 (SLA に違反していない) | すべて | 1 つまたは少ない割合の遅延要求は、いくつかの一時的な問題が原因で発生する可能性があり、これは予想されたものです。 |
| すべて | すべて | インフラストラクチャまたはネットワークに関する問題を示しています。 |
| SLA 違反 | アプリケーションと SLA に対する変更は削除されない。 | Azure Cosmos DB サービスに関する問題を示しています。 |
"HttpResponseStats": [
{
"StartTimeUTC": "2021-06-15T13:53:09.7961124Z",
"EndTimeUTC": "2021-06-15T13:53:09.7961127Z",
"RequestUri": "https://127.0.0.1:8081/dbs/347a8e44-a550-493e-88ee-29a19c070ecc/colls/4f72e752-fa91-455a-82c1-bf253a5a3c4e",
"ResourceType": "Collection",
"HttpMethod": "GET",
"ActivityId": "e16e98ec-f2e3-430c-b9e9-7d99e58a4f72",
"StatusCode": "OK"
}
]
StoreResult
StoreResult は、TCP プロトコルによる直接モードを使用した、Azure Cosmos DB への 1 つの要求を表します。
それでも遅い場合は、パターンによってさまざまな問題が示されます。 次の表で詳細に説明します。
| [要求の数] | シナリオ | 説明 |
|---|---|---|
| 1 つ - すべて | StoreResult contains TransportException |
SNAT ポートの枯渇または時間内に要求を処理するマシン上のリソースの不足を示しています。 |
| 1 つまたは少ない割合 (SLA に違反していない) | すべて | 1 つまたは少ない割合の遅延要求は、いくつかの一時的な問題が原因で発生する可能性があり、これは予想されたものです。 |
| すべて | すべて | インフラストラクチャまたはネットワークの問題。 |
| SLA 違反 | 要求に 410 のようなエラー コードが複数含まれている。 |
Azure Cosmos DB サービスまたはクライアント コンピューターに関する問題を示しています。 |
| SLA 違反 | StorePhysicalAddressが同じで、エラー状態コードがない。 |
Azure Cosmos DB に問題がある可能性があります。 |
| SLA 違反 | StorePhysicalAddress のパーティション ID は同じである一方で、レプリカ ID は異なり、エラー状態コードがない。 |
Azure Cosmos DB に問題がある可能性があります。 |
| SLA 違反 | StorePhysicalAddress がランダムで、エラー状態コードがない。 |
マシンの問題を示しています。 |
1 つの要求に対する複数のストアの結果については、次の点に注意してください。
- 強固な整合性と有界整合性制約の整合性には、常に少なくとも 2 つのストア結果があります。
- 各
StoreResultで状態コードを確認します。 SDK では、複数の異なる一時的な障害で自動的に再試行されます。 SDK は、より多くのシナリオに対応するため、頻繁に改良されています。
RequestTimeline
トランスポート層で要求を送受信するさまざまな段階の時間を表示します。
ChannelAcquisitionStarted: 新しい接続を取得または作成する時間。 接続は、CosmosClientOptions.IdleTcpConnectionTimeout を使用して非アクティブであるため以前の接続が閉じられたり、同時実行要求の量が CosmosClientOptions.MaxRequestsPerTcpConnection を超えたり、ネットワーク エラーが原因で接続が閉じられたり、アプリケーションがシングルトン パターンに従っておらず、新しいインスタンスが常に作成されたりする場合など、さまざまな理由で作成できます。 接続が確立されると、後続の要求に再利用されるため、前述の問題が発生しない限り、P99 待機時間には影響しません。Pipelined: TCP ソケットへの要求の書き込みに費やされた時間。 要求は一度に 1 つずつ TCP ソケットでのみ書き込むことができます。大きな値は、アプリケーション コードまたは大きな要求サイズによってロックされたスレッドに一般的に関連付けられている TCP ソケットのボトルネックを示します。Transit time: TCP ソケットで要求が書き込まれた後にネットワークで費やされた時間。 この数値をBELatencyInMsと比較します。BELatencyInMsが小さい場合、その時間は Azure Cosmos DB サービスではなく、ネットワーク上で費やされています。 要求がタイムアウトで失敗した場合は、クライアントが応答なしで待機した時間を示し、その原因はネットワーク待機時間です。Received: 応答が受信されてから SDK によって処理されるまでの時間。 通常、大きな値は、スレッドの枯渇またはロックされたスレッドによって発生します。
ServiceEndpointStatistics
特定のバックエンド サーバーに関する情報。 この SDK では、保留中の要求の数と MaxConcurrentRequestsPerConnection に応じて、1 つのバックエンド サーバーに対して複数の接続を開くことができます。
inflightRequests: バックエンド サーバーに対する保留中の要求の数 (複数の異なるパーティションから送信される場合があります)。 数値が大きければ、トラフィックが増え、待機時間が長くなる可能性があります。openConnectionsは、1 つのバックエンド サーバーに対して開かれている接続の合計数です。 この数値が非常に大きい場合、SNAT ポートが枯渇していることがわかります。
ConnectionStatistics
要求が割り当てられている特定の接続 (新規または以前のもの) に関する情報。
waitforConnectionInit: 現在の要求は、新しい接続の初期化が完了するのを待機していました。 これにより、待機時間が長くなります。callsPendingReceive: この呼び出しが送信される前に受信が保留されていた呼び出しの数。 数値が大きいと、この呼び出しの前に多数の呼び出しがあって、待機時間が長くなっている可能性があることがわかります。 数値が大きい場合、処理に時間がかかっているクエリやフィード操作などの別の要求によって発生する可能性のある、ヘッドオブライン ブロッキングの問題を指しています。 CosmosClientOptions.MaxRequestsPerTcpConnection を下げてみて、チャネルの数を増やしてください。LastSentTime: このサーバーに送信された最後の要求の時刻。 これを LastReceivedTime と共に使用すると、接続またはエンドポイントの問題を確認できます。 たとえば、受信タイムアウトが多い場合、送信時刻が受信時刻よりはるかに大きい値になります。lastReceive: このサーバーから受信した最後の要求の時刻lastSendAttempt: 最後の送信試行の時刻
要求と応答のサイズ
requestSizeInBytes: Azure Cosmos DB に送信された要求の合計サイズresponseMetadataSizeInBytes: Azure Cosmos DB から返されたヘッダーのサイズresponseBodySizeInBytes: Azure Cosmos DB から返されたコンテンツのサイズ
"StoreResult": {
"ActivityId": "bab6ade1-b8de-407f-b89d-fa2138a91284",
"StatusCode": "Ok",
"SubStatusCode": "Unknown",
"LSN": 453362,
"PartitionKeyRangeId": "1",
"GlobalCommittedLSN": 0,
"ItemLSN": 453358,
"UsingLocalLSN": true,
"QuorumAckedLSN": -1,
"SessionToken": "-1#453362",
"CurrentWriteQuorum": -1,
"CurrentReplicaSetSize": -1,
"NumberOfReadRegions": 0,
"IsValid": true,
"StorePhysicalAddress": "rntbd://127.0.0.1:10253/apps/DocDbApp/services/DocDbServer92/partitions/a4cb49a8-38c8-11e6-8106-8cdcd42c33be/replicas/1s/",
"RequestCharge": 1,
"RetryAfterInMs": null,
"BELatencyInMs": "0.304",
"transportRequestTimeline": {
"requestTimeline": [
{
"event": "Created",
"startTimeUtc": "2022-05-25T12:03:36.3081190Z",
"durationInMs": 0.0024
},
{
"event": "ChannelAcquisitionStarted",
"startTimeUtc": "2022-05-25T12:03:36.3081214Z",
"durationInMs": 0.0132
},
{
"event": "Pipelined",
"startTimeUtc": "2022-05-25T12:03:36.3081346Z",
"durationInMs": 0.0865
},
{
"event": "Transit Time",
"startTimeUtc": "2022-05-25T12:03:36.3082211Z",
"durationInMs": 1.3324
},
{
"event": "Received",
"startTimeUtc": "2022-05-25T12:03:36.3095535Z",
"durationInMs": 12.6128
},
{
"event": "Completed",
"startTimeUtc": "2022-05-25T12:03:36.8621663Z",
"durationInMs": 0
}
],
"serviceEndpointStats": {
"inflightRequests": 1,
"openConnections": 1
},
"connectionStats": {
"waitforConnectionInit": "False",
"callsPendingReceive": 0,
"lastSendAttempt": "2022-05-25T12:03:34.0222760Z",
"lastSend": "2022-05-25T12:03:34.0223280Z",
"lastReceive": "2022-05-25T12:03:34.0257728Z"
},
"requestSizeInBytes": 447,
"responseMetadataSizeInBytes": 438,
"responseBodySizeInBytes": 604
},
"TransportException": null
}
エラー率が Azure Cosmos DB の SLA に違反している
Azure サポートに問い合わせる。
次の手順
- Azure Cosmos DB .NET SDK 使用時の問題を診断してトラブルシューティングする。
- .NET SDK のパフォーマンス ガイドラインを確認する。
- .NET SDK のベスト プラクティスを確認する。