このページでは、ストリーミング リクエストとパーティション リクエストの Spanner API リクエスト レイテンシを計算する方法について説明します。
Spanner API ストリーミングとパーティションのリクエストのレイテンシは、AuditLog の metadata 構造体オブジェクトのフィールドを使用して計算できます。メタデータの型は QueryPerformanceMetadata です。ストリーミング リクエストとパーティション リクエストの場合、metadata には processingSecondsDuration フィールドは含まれません。processingSecondsDuration を使用して他のすべてのリクエスト タイプのリクエストのレイテンシを計算する方法については、処理期間をご覧ください。
ストリーミング リクエストのリクエスト レイテンシ
クライアントがストリーミング リクエストを送信し、Spanner API が部分的な結果セットを返すと、Cloud 監査ログ最初と最後のレスポンスの監査ログを記録します。ストリーミング リクエストのリクエスト レイテンシは、Spanner API がリクエストを受信してからクライアントが最後のレスポンスを受信するまでの経過時間です。
ストリーミング リクエストの監査ログエントリを認識する
ストリーミング リクエストのリクエスト レイテンシを計算するには、リクエストに関連するログエントリを特定する必要があります。ログエントリの protoPayload.methodName が google.spanner.v1.Spanner.ExecuteStreamingSql または google.spanner.v1.Spanner.StreamingRead に設定されています。ストリーミング リクエストごとに 2 つのログエントリがあり、operation.id でグループ化されます。最初のエントリの operation.first は true に、最後のエントリの operation.last は true に設定されています。protoPayload.metadata.responseTimestamp オブジェクトにも値が入力されます。
ストリーミング リクエストのリクエスト レイテンシを計算する
ストリーミング リクエストのリクエスト レイテンシを計算するには、監査ログを operation.id でフィルタリングします。最新の protoPayload.metadata.responseTimestamp と最古の protoPayload.requestMetadata.requestAttributes.time の差は、リクエスト レイテンシです。
ストリーミング リクエストの監査ログの例
ストリーミング リクエストのすべてのログエントリを検索するには、ログ エクスプローラで次のクエリを実行します。OPERATION_ID 変数は目的の値に置き換えます。
operation.id="OPERATION_ID"
次の例では、operation.id が 15327696495839874591 であるストリーミング リクエストのログエントリを検索します。
operation.id="15327696495839874591"
返された最初のログ
{
"protoPayload": {
"@type": "type.googleapis.com/google.cloud.audit.AuditLog",
"authenticationInfo": {...},
"requestMetadata": {
"requestAttributes": {
"time": "2023-02-27T16:57:40.552952297Z",
},
"destinationAttributes": {}
},
"serviceName": "spanner.googleapis.com",
"methodName": "google.spanner.v1.Spanner.ExecuteStreamingSql",
"authorizationInfo": [{...}],
"resourceName": "projects/example-project/instances/example-instance/databases/example-database/sessions/example-session",
"request": {
"session": "projects/example-project/instances/example-instance/databases/example-database/sessions/example-session",
"requestOptions": {},
"sql": "SELECT COUNT(*) as count FROM Example_table WHERE Example_Column > @timestamp",
"@type": "type.googleapis.com/google.spanner.v1.ExecuteSqlRequest",
"queryOptions": {}
},
"metadata": {
"@type": "type.googleapis.com/spanner.cloud.instance_v1.QueryPerformanceMetadata",
"responseTimestamp": "2023-02-27T16:57:40.555730699Z"
}
},
"insertId": "h7fj0jei6597",
"resource": {...},
"timestamp": "2023-02-27T16:57:40.552391554Z",
"severity": "INFO",
"logName": "projects/example-project/logs/cloudaudit.googleapis.com%2Fdata_access",
"operation": {
"id": "15327696495839874591",
"producer": "spanner.googleapis.com",
"first": true
},
"receiveTimestamp": "2023-02-27T16:57:41.507770020Z"
}
返された最後のログ
{
"protoPayload": {
"@type": "type.googleapis.com/google.cloud.audit.AuditLog",
"authenticationInfo": {...},
"requestMetadata": {
"requestAttributes": {
"time": "2023-02-27T16:57:40.552952297Z",
},
"destinationAttributes": {}
},
"serviceName": "spanner.googleapis.com",
"methodName": "google.spanner.v1.Spanner.ExecuteStreamingSql",
"authorizationInfo": [{...}],
"resourceName": "projects/example-project/instances/example-instance/databases/example-database/sessions/example-session",
"metadata": {
"responseTimestamp": "2023-02-27T16:57:40.556138125Z",
"@type": "type.googleapis.com/spanner.cloud.instance_v1.QueryPerformanceMetadata"
}
},
"insertId": "h7fj0jei6598",
"resource": {...},
"timestamp": "2023-02-27T16:57:40.552391554Z",
"severity": "INFO",
"logName": "projects/example-project/logs/cloudaudit.googleapis.com%2Fdata_access",
"operation": {
"id": "15327696495839874591",
"producer": "spanner.googleapis.com",
"last": true
},
"receiveTimestamp": "2023-02-27T16:57:41.507770020Z"
}
リクエストのレイテンシは、最新の metadata.responseTimestamp から最古の requestAttributes.time を引いたものです。結果は 2023-02-27T16:57:40.556138125Z-2023-02 ～ 2023-02-27T16:57:40.552952297Z になります。これは 0.003185828 秒に相当します。
パーティション リクエストのリクエスト レイテンシ
クライアントがパーティション分割リクエストを送信すると、Spanner は複数の監査ログを作成します。エンドツーエンドのパーティション リクエストと、パーティションに対する後続の呼び出しのリクエスト レイテンシを計算するには、親リクエストに関連付けられた監査ログを特定します。
パーティション リクエストの監査ログエントリを認識する
PartitionRead または PartitionQuery リクエストを行うと、PartitionResponse に一連のパーティションが返されます。パーティションごとに Read、ExecuteSql、ExecuteStreaming のいずれかを呼び出すと、Spanner によってこれらのメソッドの監査ログが記録されます。これらの各ログには、それらを一緒にグループ化する protoPayload.metadata.partitionBatchIdentifier という識別子が含まれています。protoPayload.metadata.responseTimestamp オブジェクトにも値が入力されます。
パーティション リクエストのリクエスト レイテンシを計算する
パーティション リクエストのリクエスト レイテンシを計算するには、監査ログを metadata.partitionBatchIdentifier でフィルタリングします。最新の metadata.responseTimestamp と最古の protoPayload.requestMetadata.requestAttributes.time の差がリクエスト レイテンシです。
パーティション リクエストの監査ログの例
パーティション リクエストのすべてのログエントリを検索するには、ログ エクスプローラで次のクエリを実行します。PARTITION_BATCH_ID 変数は目的の値に置き換えます。
metadata.partitionBatchIdentifier="PARTITION_BATCH_ID"
次の例では、metadata.partitionBatchIdentifier が 15327696495839874591 であるパーティション リクエストのログエントリを検索します。
metadata.partitionBatchIdentifier="15327696495839874591"
返された最初のログ
{
"protoPayload": {
"@type": "type.googleapis.com/google.cloud.audit.AuditLog",
"authenticationInfo": {...},
"requestMetadata": {
"requestAttributes": {
"time": "2023-02-15T18:13:39.341584693Z",
},
},
"serviceName": "spanner.googleapis.com",
"methodName": "google.spanner.v1.Spanner.ExecuteStreamingSql",
"authorizationInfo": [{...}],
"resourceName": "projects/example-project/instances/example-instance/databases/example-db/sessions/example-session",
"request": {...},
"metadata": {
"@type": "type.googleapis.com/spanner.cloud.instance_v1.QueryPerformanceMetadata",
"partitionBatchIdentifier": "4841471066190013455",
"responseTimestamp": "2023-02-15T18:13:39.343693061Z"
}
},
"insertId": "4fug42dqke5",
"resource": {...},
"timestamp": "2023-02-15T18:13:39.341069413Z",
"severity": "INFO",
"logName": "projects/example-project/logs/cloudaudit.googleapis.com%2Fdata_access",
"operation": {...},
"receiveTimestamp": "2023-02-15T18:13:39.983812511Z"
}
返された 2 番目のログ
{
"protoPayload": {
"@type": "type.googleapis.com/google.cloud.audit.AuditLog",
"authenticationInfo": {...},
"requestMetadata": {
"requestAttributes": {
"time": "2023-02-15T18:13:39.341584693Z",
},
},
"serviceName": "spanner.googleapis.com",
"methodName": "google.spanner.v1.Spanner.ExecuteStreamingSql",
"authorizationInfo": [{...}],
"resourceName": "projects/example-project/instances/example-instance/databases/example-db/sessions/example-session",
"metadata": {
"responseTimestamp": "2023-02-15T18:13:39.344256101Z",
"partitionBatchIdentifier": "4841471066190013455",
"@type": "type.googleapis.com/spanner.cloud.instance_v1.QueryPerformanceMetadata"
}
},
"insertId": "4fug42dqke6",
"resource": {...},
"timestamp": "2023-02-15T18:13:39.341069413Z",
"severity": "INFO",
"logName": "projects/example-project/logs/cloudaudit.googleapis.com%2Fdata_access",
"operation": {...},
"receiveTimestamp": "2023-02-15T18:13:39.983812511Z"
}
パーティションの数によっては、Spanner がこの例よりも多くのログを記録する場合があります。
返された最後のログ
{
"protoPayload": {
"@type": "type.googleapis.com/google.cloud.audit.AuditLog",
"authenticationInfo": {...},
"requestMetadata": {
"requestAttributes": {
"time": "2023-02-15T18:13:39.439207331Z",
},
},
"serviceName": "spanner.googleapis.com",
"methodName": "google.spanner.v1.Spanner.ExecuteStreamingSql",
"authorizationInfo": [{...}],
"resourceName": "projects/example-project/instances/example-instance/databases/example-db/sessions/example-session",
"metadata": {
"partitionBatchIdentifier": "4841471066190013455",
"@type": "type.googleapis.com/spanner.cloud.instance_v1.QueryPerformanceMetadata",
"responseTimestamp": "2023-02-15T18:13:39.441692339Z"
}
},
"insertId": "4fug42dqkec",
"resource": {...},
"timestamp": "2023-02-15T18:13:39.438607931Z",
"severity": "INFO",
"logName": "projects/example-project/logs/cloudaudit.googleapis.com%2Fdata_access",
"operation": {...},
"receiveTimestamp": "2023-02-15T18:13:39.983812511Z"
}
リクエストのレイテンシは、最新の metadata.responseTimestamp から最古の requestAttributes.time を引いたものです。結果は 2023-02-15T18:13:39.441692339Z ～ 2023-02-15T18:13:39.341584693Z になります。これは 0.100107646 秒に相当します。