このページでは、ストリーミング リクエストとパーティション リクエストの Spanner API リクエスト レイテンシを計算する方法について説明します。
AuditLog の metadata 構造体オブジェクトのフィールドを使用して、Spanner API のストリーミング リクエストとパーティション リクエストのレイテンシを計算できます。メタデータのタイプは QueryPerformanceMetadata です。ストリーミング リクエストとパーティション リクエストの場合、metadata に processingSecondsDuration フィールドは含まれません。processingSecondsDuration を使用して他のすべてのリクエスト タイプのリクエスト レイテンシを計算する方法については、処理期間をご覧ください。
ストリーミング リクエストのレイテンシ
クライアントがストリーミング リクエストを送信し、Spanner API が部分的な結果セットを返すと、Cloud Audit Logs は最初と最後のレスポンスの監査ログを記録します。ストリーミング リクエストのレイテンシは、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 秒に相当します。