Menghitung latensi permintaan streaming dan partisi Spanner

Halaman ini menjelaskan cara menghitung latensi permintaan Spanner API dari permintaan streaming dan partisi.

Anda dapat menghitung latensi permintaan streaming dan partisi Spanner API dengan kolom dalam objek struct metadata dari AuditLog. Metadata berjenis QueryPerformanceMetadata. Untuk permintaan streaming dan partisi, metadata tidak berisi kolom processingSecondsDuration. Untuk mengetahui informasi tentang cara menggunakan processingSecondsDuration untuk menghitung latensi permintaan untuk semua jenis permintaan lainnya, lihat Durasi pemrosesan.

Latensi permintaan untuk permintaan streaming

Saat klien mengirim permintaan streaming dan saat Spanner API menampilkan set hasil parsial, Cloud Audit Logs akan mencatat log audit untuk respons pertama dan terakhir. Latensi permintaan untuk permintaan streaming adalah waktu yang berlalu antara saat Spanner API menerima permintaan dan saat klien menerima respons terakhir.

Mengenali entri log audit permintaan streaming

Untuk menghitung latensi permintaan permintaan streaming, Anda perlu mengidentifikasi entri log yang terkait dengan permintaan. Entri log memiliki protoPayload.methodName yang ditetapkan ke google.spanner.v1.Spanner.ExecuteStreamingSql atau google.spanner.v1.Spanner.StreamingRead. Untuk setiap permintaan streaming, ada dua entri log, yang dikelompokkan menurut operation.id. Entri pertama memiliki operation.first yang ditetapkan ke true dan entri terakhir memiliki operation.last yang ditetapkan ke true. Objek protoPayload.metadata.responseTimestamp juga diisi.

Menghitung latensi permintaan untuk permintaan streaming

Untuk menghitung latensi permintaan permintaan streaming, filter log audit berdasarkan operation.id. Perbedaan antara protoPayload.metadata.responseTimestamp terbaru dan protoPayload.requestMetadata.requestAttributes.time paling awal adalah latensi permintaan.

Contoh log audit untuk permintaan streaming

Untuk menemukan semua entri log untuk permintaan streaming, jalankan kueri berikut di Logs Explorer, dengan mengganti variabel OPERATION_ID dengan nilai yang diinginkan:

operation.id="OPERATION_ID"

Contoh berikut menemukan entri log untuk permintaan streaming dengan operation.id dari 15327696495839874591:

operation.id="15327696495839874591"

Menampilkan log pertama

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

Menampilkan log terakhir

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

Latensi permintaan adalah metadata.responseTimestamp terbaru dikurangi requestAttributes.time paling awal. Hasilnya adalah 2023-02-27T16:57:40.556138125Z-2023-02 - 2023-02-27T16:57:40.552952297Z, yang sama dengan 0,003185828 detik.

Latensi permintaan untuk permintaan partisi

Saat klien mengirim permintaan yang dipartisi, Spanner akan membuat beberapa log audit. Untuk menghitung latensi permintaan permintaan partisi menyeluruh dan panggilan berikutnya ke partisi, identifikasi log audit yang terkait dengan permintaan induk.

Mengenali entri log audit permintaan partisi

Saat Anda membuat permintaan PartitionRead atau PartitionQuery, kumpulan partisi akan ditampilkan di PartitionResponse. Saat Anda melakukan panggilan Read, ExecuteSql, atau ExecuteStreaming untuk setiap partisi, Spanner akan mencatat log audit untuk metode ini. Setiap log ini berisi ID untuk mengelompokkan log tersebut, yang disebut protoPayload.metadata.partitionBatchIdentifier. Objek protoPayload.metadata.responseTimestamp juga diisi.

Menghitung latensi permintaan untuk permintaan partisi

Untuk menghitung latensi permintaan permintaan partisi, Anda dapat memfilter log audit menurut metadata.partitionBatchIdentifier. Perbedaan antara metadata.responseTimestamp terbaru dan protoPayload.requestMetadata.requestAttributes.time paling awal adalah latensi permintaan.

Contoh log audit untuk permintaan partisi

Untuk menemukan semua entri log untuk permintaan partisi, jalankan kueri berikut di Logs Explorer, dengan mengganti variabel PARTITION_BATCH_ID dengan nilai yang diinginkan:

metadata.partitionBatchIdentifier="PARTITION_BATCH_ID"

Contoh berikut menemukan entri log untuk permintaan partisi dengan metadata.partitionBatchIdentifier dari 15327696495839874591:

metadata.partitionBatchIdentifier="15327696495839874591"

Menampilkan log pertama

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

Menampilkan log kedua

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

Bergantung pada jumlah partisi, Spanner mungkin mencatat log lebih banyak daripada dalam contoh ini.

Menampilkan log terakhir

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

Latensi permintaan adalah metadata.responseTimestamp terbaru dikurangi requestAttributes.time paling awal. Hasilnya adalah 2023-02-15T18:13:39.441692339Z - 2023-02-15T18:13:39.341584693Z, yang sama dengan 0,100107646 detik.