Calcolare la latenza delle richieste di flusso e di partizione di Spanner

Questa pagina descrive come calcolare la latenza delle richieste dell'API Spanner per le richieste di streaming e di partizione.

Puoi calcolare le latenze delle richieste di streaming e di partizione dell'API Spanner con i campi nell'oggetto struct metadata di un AuditLog. I metadati sono di tipo QueryPerformanceMetadata. Per le richieste di streaming e di partizione, metadata non contiene un processingSecondsDuration. Per informazioni su come utilizzare processingSecondsDuration per calcolare le latenze delle richieste per tutte le altre tipi di richieste, consulta Durata di elaborazione.

Latenze di richiesta per le richieste di streaming

Quando un client invia una richiesta di streaming e l'API Spanner restituisce set di risultati parziali, Audit log di Cloud registra gli audit log per la prima e l'ultima risposta. La latenza della richiesta per una richiesta di flusso di dati è il tempo trascorso tra quando l'API Spanner riceve la richiesta e quando il client riceve l'ultima risposta.

Riconoscere le voci di audit log per le richieste di flussi di dati

Per calcolare la latenza della richiesta di una richiesta di streaming, devi identificare le voci di log relative alla richiesta. Le voci di log hanno protoPayload.methodName impostato su google.spanner.v1.Spanner.ExecuteStreamingSql o google.spanner.v1.Spanner.StreamingRead. Per ogni richiesta di streaming sono presenti due voci di log, raggruppate per operation.id. La prima voce contiene operation.first impostato su true e l'ultima voce è operation.last impostata su true. Viene compilato anche l'oggetto protoPayload.metadata.responseTimestamp.

Calcolare la latenza delle richieste per le richieste di streaming

Per calcolare la latenza di una richiesta in modalità flusso, filtra gli audit log entro il giorno operation.id. La differenza tra i modelli protoPayload.metadata.responseTimestamp e il primo protoPayload.requestMetadata.requestAttributes.time è la latenza della richiesta.

Log di controllo di esempio per le richieste di streaming

Per trovare tutte le voci di log per una richiesta di streaming, esegui la seguente query in Esplora log, sostituendo la variabile OPERATION_ID con il valore desiderato:

operation.id="OPERATION_ID"

L'esempio seguente trova le voci di log per una richiesta di streaming con il operation.id di 15327696495839874591:

operation.id="15327696495839874591"

Primo log restituito

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

Ultimo log restituito

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

La latenza della richiesta è l'ultima metadata.responseTimestamp meno la i primi requestAttributes.time. Il risultato è 2023-02-27T16:57:40.556138125Z-2023-02 - 2023-02-27T16:57:40.552952297Z, che è uguale a 0,003185828 secondi.

Latenze delle richieste per le richieste di partizione

Quando un client invia una richiesta partizionata, Spanner crea più controlli logaritmi. Per calcolare la latenza della richiesta di una partizione end-to-end e delle chiamate successive alle partizioni, identifica i log di controllo associati alla richiesta principale.

Riconoscere le voci dei log di controllo delle richieste di partizione

Quando effettui una richiesta PartitionRead o PartitionQuery, viene restituito un insieme di partizioni in PartitionResponse. Man mano che effettua Read, ExecuteSql o ExecuteStreaming rispettivamente per ogni Spanner registra gli audit log per questi metodi. Ciascuno di questi log contengono un identificatore per raggrupparli, protoPayload.metadata.partitionBatchIdentifier. La Viene compilato anche l'oggetto protoPayload.metadata.responseTimestamp.

Calcolare la latenza delle richieste per le richieste di partizione

Per calcolare la latenza di una richiesta di partizione, puoi filtrare log di controllo di metadata.partitionBatchIdentifier. La differenza tra il valore metadata.responseTimestamp più recente e quello più antico protoPayload.requestMetadata.requestAttributes.time è la latenza della richiesta.

Audit log di esempio per le richieste di partizione

Per trovare tutte le voci del log per una richiesta di partizione, esegui la seguente query in Esplora log, sostituendo la variabile PARTITION_BATCH_ID con il valore desiderato:

metadata.partitionBatchIdentifier="PARTITION_BATCH_ID"

L'esempio seguente trova le voci di log per una richiesta di partizione con il metadata.partitionBatchIdentifier di 15327696495839874591:

metadata.partitionBatchIdentifier="15327696495839874591"

Primo log restituito

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

Secondo log restituito

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

A seconda del numero di partizioni, Spanner potrebbe registrare rispetto a questo esempio.

Ultimo log restituito

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

La latenza della richiesta è l'ultimo metadata.responseTimestamp meno il primo requestAttributes.time. Il risultato è 2023-02-15T18:13:39.441692339Z - 2023-02-15T18:13:39.341584693Z, ovvero 0,100107646 secondi.