Calcular a latência de streaming e de solicitação de partição do Spanner

Esta página descreve como calcular a latência da solicitação da API Spanner de streaming e de particionamento.

É possível calcular as latências de streaming e de solicitação de partição da API Spanner com os campos no objeto de estrutura metadata de um AuditLog. Os metadados são do tipo QueryPerformanceMetadata. Para solicitações de streaming e partição, o metadata não contém um campo processingSecondsDuration. Para saber como usar processingSecondsDuration para calcular latências de solicitação para todos os outros tipos de solicitação, consulte Duração do processamento.

Latências de solicitações para solicitações de streaming

Quando um cliente envia uma solicitação de streaming e a API Spanner retorna conjuntos de resultados parciais, os Registros de auditoria do Cloud registram registros de auditoria para a primeira e a última resposta. A latência de uma solicitação de streaming é o tempo decorrido entre o momento em que a API Spanner recebe a solicitação e o momento em que o cliente recebe a última resposta.

Reconhecer entradas de registro de auditoria de solicitações de streaming

Para calcular a latência de uma solicitação de streaming, é necessário identificar as entradas de registro relacionadas à solicitação. As entradas de registro têm o protoPayload.methodName definido como google.spanner.v1.Spanner.ExecuteStreamingSql ou google.spanner.v1.Spanner.StreamingRead. Para cada solicitação de streaming, há duas entradas de registro, que são agrupadas por operation.id. A primeira entrada tem operation.first definido como true, e a última tem operation.last definido como true. O objeto protoPayload.metadata.responseTimestamp também é preenchido.

Calcular a latência de solicitações de streaming

Para calcular a latência de uma solicitação de streaming, filtre os registros de auditoria por operation.id. A diferença entre o protoPayload.metadata.responseTimestamp mais recente e o protoPayload.requestMetadata.requestAttributes.time mais antigo é a latência da solicitação.

Exemplos de registros de auditoria para solicitações de streaming

Para encontrar todas as entradas de registro de uma solicitação de streaming, execute a seguinte consulta no Explorador de registros, substituindo a variável OPERATION_ID pelo valor desejado:

operation.id="OPERATION_ID"

O exemplo a seguir encontra entradas de registro para uma solicitação de streaming com o operation.id de 15327696495839874591:

operation.id="15327696495839874591"

Primeiro registro retornado

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

Último registro retornado

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

A latência da solicitação é a metadata.responseTimestamp mais recente menos a requestAttributes.time mais antiga. O resultado é 2023-02-27T16:57:40.556138125Z-2023-02 - 2023-02-27T16:57:40.552952297Z, que corresponde a 0,003185828 segundos.

Latências de solicitações para solicitações de partição

Quando um cliente envia uma solicitação particionada, o Spanner cria vários registros de auditoria. Para calcular a latência de uma solicitação de partição de ponta a ponta e chamadas subsequentes para as partições, identifique os registros de auditoria associados à solicitação principal.

Reconhecer entradas de registro de auditoria de solicitações de partição

Quando você faz uma solicitação PartitionRead ou PartitionQuery, um conjunto de partições é retornado no PartitionResponse. À medida que você faz chamadas Read, ExecuteSql ou ExecuteStreaming, respectivamente, para cada partição, o Spanner registra registros de auditoria para esses métodos. Cada um deles contém um identificador para agrupar os registros, chamado protoPayload.metadata.partitionBatchIdentifier. O objeto protoPayload.metadata.responseTimestamp também é preenchido.

Calcular a latência da solicitação para solicitações de partição

Para calcular a latência de uma solicitação de partição, filtre os registros de auditoria por metadata.partitionBatchIdentifier. A diferença entre a metadata.responseTimestamp mais recente e a protoPayload.requestMetadata.requestAttributes.time mais antiga é a latência da solicitação.

Exemplos de registros de auditoria para solicitações de partição

Para encontrar todas as entradas de registro de uma solicitação de partição, execute a consulta a seguir no Explorador de registros, substituindo a variável PARTITION_BATCH_ID pelo valor desejado:

metadata.partitionBatchIdentifier="PARTITION_BATCH_ID"

O exemplo a seguir encontra entradas de registro para uma solicitação de partição com o metadata.partitionBatchIdentifier de 15327696495839874591:

metadata.partitionBatchIdentifier="15327696495839874591"

Primeiro registro retornado

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

Segundo registro retornado

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

Dependendo do número de partições, o Spanner pode registrar mais registros do que neste exemplo.

Último registro retornado

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

A latência da solicitação é a metadata.responseTimestamp mais recente menos a requestAttributes.time mais antiga. O resultado é 2023-02-15T18:13:39.441692339Z - 2023-02-15T18:13:39.341584693Z, o que equivale a 0,100107646 segundos.