计算 Spanner 流式传输和分区请求延迟时间

本页介绍了如何计算流式传输请求和分区请求的 Spanner API 请求延迟时间。

您可以使用 AuditLogmetadata 结构体对象中的字段计算 Spanner API 流式传输和分区请求延迟时间。元数据的类型为 QueryPerformanceMetadata。对于流式传输和分区请求,metadata 不包含 processingSecondsDuration 字段。如需了解如何使用 processingSecondsDuration 计算所有其他请求类型的请求延迟时间,请参阅处理时长

流式请求的请求延迟时间

当客户端发送流式请求且 Spanner API 返回部分结果集时,Cloud 审核日志会记录第一个和最后一个响应的审核日志。流式请求的请求延迟时间是指 Spanner API 收到请求到客户端收到最后一个响应之间的时间。

识别流式请求审核日志条目

如需计算流式传输请求的请求延迟时间,您需要识别与请求相关的日志条目。日志条目的 protoPayload.methodName 设置为 google.spanner.v1.Spanner.ExecuteStreamingSqlgoogle.spanner.v1.Spanner.StreamingRead。对于每个串流请求,都有两个日志条目,这些条目按 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.id15327696495839874591 的流式传输请求的日志条目:

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 会创建多个审核日志。如需计算端到端分区请求及其对分区的后续调用的请求延迟时间,请确定与父级请求关联的审核日志。

识别分区请求审核日志条目

当您发出 PartitionReadPartitionQuery 请求时,系统会在 PartitionResponse 中返回一组分区。当您分别针对每个分区调用 ReadExecuteSqlExecuteStreaming 时,Spanner 会为这些方法记录审核日志。这些日志中的每一个都包含一个用于将它们分组的标识符,称为 protoPayload.metadata.partitionBatchIdentifier。系统还会填充 protoPayload.metadata.responseTimestamp 对象。

计算分区请求的请求延迟时间

如需计算分区请求的请求延迟时间,您可以按 metadata.partitionBatchIdentifier 过滤审核日志。最新的 metadata.responseTimestamp 与最早的 protoPayload.requestMetadata.requestAttributes.time 之间的差值就是请求延迟时间。

分区请求的审核日志示例

如需查找分区请求的所有日志条目,请在日志浏览器中运行以下查询,并将 PARTITION_BATCH_ID 变量替换为所需的值:

metadata.partitionBatchIdentifier="PARTITION_BATCH_ID"

以下示例会查找 metadata.partitionBatchIdentifier15327696495839874591 的分区请求的日志条目:

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"
}

返回的第二个日志

{
  "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 秒。