Se usó la API de Cloud Translation para traducir esta página.
Switch to English

Estadísticas de transacciones

Cloud Spanner proporciona tablas integradas que almacenan estadísticas sobre transacciones. Puedes obtener estadísticas de estas tablas SPANNER_SYS.TXN_STATS* mediante instrucciones de SQL.

Cuándo usar las estadísticas de transacciones

Las estadísticas de transacciones son útiles cuando investigas problemas de rendimiento. Por ejemplo, puedes verificar si hay transacciones en ejecución lentas que podrían afectar el rendimiento o las consultas por segundo (QPS) en tu base de datos. Otro caso es cuando las aplicaciones cliente experimentan una latencia alta de ejecución de transacciones. Analizar las estadísticas de las transacciones puede ayudar a descubrir posibles cuellos de botella, como grandes volúmenes de actualizaciones de una columna específica, que pueden afectar la latencia.

Availability

Los datos SPANNER_SYS solo están disponibles a través de interfaces de SQL (por ejemplo, executeQuery y gcloud spanner databases execute-sql); otros métodos de lectura únicos que proporciona Cloud Spanner no son compatibles con SPANNER_SYS.

Estadísticas de latencia agrupadas por transacción

En las siguientes tablas, se realiza un seguimiento de las estadísticas de las transacciones que consumen recursos TOP durante un período específico.

  • SPANNER_SYS.TXN_STATS_TOP_MINUTE: Estadísticas de transacciones agregadas en intervalos de 1 minuto.

  • SPANNER_SYS.TXN_STATS_TOP_10MINUTE: Estadísticas de transacciones agregadas en intervalos de 10 minutos.

  • SPANNER_SYS.TXN_STATS_TOP_HOUR: Estadísticas de transacciones agregadas en intervalos de 1 hora.

Estas tablas tienen las siguientes propiedades:

  • Cada tabla contiene datos de intervalos de tiempo no superpuestos de la longitud que se especifica en el nombre de la tabla.

  • Los intervalos se basan en los tiempos del reloj. Los intervalos de 1 minuto finalizan en el minuto, los intervalos de 10 minutos finalizan cada 10 minutos a partir de la hora y los intervalos de 1 hora finalizan en la hora.

    Por ejemplo, a las 11:59:30 a.m., los intervalos más recientes disponibles para las consultas de SQL son los siguientes:

    • 1 minuto: de 11:58:00 a 11:58:59 a.m.
    • 10 minutos: de 11:40:00 a 11:49:59 a.m.
    • 1 hora: de 10:00:00 a 10:59:59 a.m.
  • Cloud Spanner agrupa las estadísticas por FPRINT (huella digital) de las transacciones. FPRINT es el hash calculado en función de las operaciones involucradas en la transacción.

  • Debido a que las estadísticas se agrupan según FPRINT, si la misma transacción se ejecuta varias veces dentro de cualquier intervalo de tiempo, aún veremos solo una entrada para esa transacción en estas tablas.

  • Cada fila contiene estadísticas de todas las ejecuciones de una transacción en particular que Cloud Spanner captura estadísticas durante el intervalo especificado.

Si Cloud Spanner no puede almacenar estadísticas de todas las transacciones ejecutadas durante el intervalo en estas tablas, el sistema prioriza las transacciones con la latencia más alta, los intentos de confirmación y los bytes escritos durante el intervalo especificado.

Esquema de la tabla

Nombre de la columna Tipo Descripción
INTERVAL_END TIMESTAMP Final del intervalo en el que ocurrieron las ejecuciones de transacciones incluidas.
FPRINT INT64 La huella digital es el hash calculado en función de las operaciones involucradas en la transacción. INTERVAL_END y FPRINT actúan como una clave única para estas tablas.
READ_COLUMNS ARRAY<STRING> Es el conjunto de columnas que leyó la transacción.
WRITE_CONSTRUCTIVE_COLUMNS ARRAY<STRING> El conjunto de columnas que se escribieron constructivamente (es decir, asignadas a valores nuevos) por la transacción.
WRITE_DELETE_TABLES ARRAY<STRING> El conjunto de tablas cuyas filas se borraron o reemplazaron mediante la transacción.
COMMIT_ATTEMPT_COUNT INT64 Cantidad total de intentos de confirmación para la transacción. Incluye el intento inicial y cualquier reintento posterior, si la transacción se anula debido a un error recuperable.
COMMIT_ABORT_COUNT INT64 Cantidad de veces que se anularon las confirmaciones de la transacción.
COMMIT_RETRY_COUNT INT64 Cantidad de intentos de confirmación que son reintentos de intentos anulados con anterioridad. Es posible que una transacción de Cloud Spanner se haya intentado varias veces antes de que se confirme debido a bloqueos de bloqueo o eventos transitorios. Un número alto de reintentos en relación con los intentos de confirmación indica que puede haber problemas relacionados con la investigación. Para obtener más información, consulta Información sobre las transacciones y los recuentos de confirmaciones en esta página.
COMMIT_FAILED_PRECONDITION_COUNT INT64 Cantidad total de fallas de condiciones previas (FAILED_PRECONDITION) para la transacción.
AVG_PARTICIPANTS FLOAT64 Cantidad promedio de participantes en cada intento de confirmación. Para obtener más información sobre los participantes, consulta la página sobre la vida de las operaciones de lectura y escritura de Cloud Spanner.
AVG_TOTAL_LATENCY_SECONDS FLOAT64 Promedio de segundos tomados de la primera operación de la transacción que se confirmarán o anularán.
AVG_COMMIT_LATENCY_SECONDS FLOAT64 Promedio de segundos necesarios para realizar la operación de confirmación.
AVG_BYTES FLOAT64 Cantidad promedio de bytes que escribió la transacción.

Consultas de ejemplo

Esta sección incluye varias instrucciones de SQL de ejemplo que recuperan estadísticas de transacciones. Puedes ejecutar estas instrucciones de SQL con las bibliotecas cliente, la herramienta de línea de comandos de gcloud o Cloud Console.

Genera una lista de las estadísticas básicas de cada transacción en un período determinado

La siguiente consulta muestra los datos sin procesar de las transacciones principales en el minuto anterior.

SELECT fprint,
       read_columns,
       write_constructive_columns,
       write_delete_tables,
       avg_total_latency_seconds,
       avg_commit_latency_seconds,
       avg_bytes
FROM spanner_sys.txn_stats_top_minute
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.txn_stats_top_minute);
Resultado de la consulta
fprint read_columns write_constructive_columns write_delete_tables avg_total_latency_seconds avg_commit_latency_seconds avg_bytes
40015598317 [] ["Routes"] ["Users"] 0.006578737 0.006547737 25286
20524969030 ["id", "no"] [] [] 0.001732442 0.000247442 0
77848338483 [] [] ["Cars", "Routes"] 0.033467418 0.000251418 0

Enumera las transacciones con la latencia de confirmación promedio más alta

En la siguiente consulta, se muestran las transacciones con latencia de confirmación promedio alta en la hora anterior, ordenadas desde la latencia de confirmación promedio más alta a la más baja.

SELECT fprint,
       read_columns,
       write_constructive_columns,
       write_delete_tables,
       avg_total_latency_seconds,
       avg_commit_latency_seconds,
       avg_bytes
FROM spanner_sys.txn_stats_top_hour
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.txn_stats_top_hour)
ORDER BY avg_commit_latency_seconds DESC;
Resultado de la consulta
fprint read_columns write_constructive_columns write_delete_tables avg_total_latency_seconds avg_commit_latency_seconds avg_bytes
40015598317 [] ["Routes"] ["Users"] 0.006578737 0.006547737 25286
77848338483 [] [] ["Cars", "Routes"] 0.033467418 0.000251418 0
20524969030 ["id", "no"] [] [] 0.001732442 0.000247442 0

Encuentra la latencia promedio de las transacciones que leen ciertas columnas

En la siguiente consulta, se muestra la información de latencia promedio para las transacciones que leen la columna ADDRESS de las estadísticas de 1 hora:

SELECT fprint,
       read_columns,
       write_constructive_columns,
       write_delete_tables,
       avg_total_latency_seconds
FROM spanner_sys.txn_stats_top_hour
WHERE 'ADDRESS' IN UNNEST(read_columns)
ORDER BY avg_total_latency_seconds DESC;
Resultado de la consulta
fprint read_columns write_constructive_columns write_delete_tables avg_total_latency_seconds
77848338483 ["ID", "ADDRESS"] [] ["Cars", "Routes"] 0.033467418
40015598317 ["ID", "NAME", "ADDRESS"] [] ["Users"] 0.006578737

Enumera las transacciones según la cantidad promedio de bytes modificados

En la siguiente consulta, se observan las transacciones muestreadas en la última hora, ordenadas por la cantidad promedio de bytes modificados por la transacción.

SELECT fprint,
       read_columns,
       write_constructive_columns,
       write_delete_tables,
       avg_bytes
FROM spanner_sys.txn_stats_top_hour
ORDER BY avg_bytes DESC;
Resultado de la consulta
fprint read_columns write_constructive_columns write_delete_tables avg_bytes
40015598317 [] [] ["Users"] 25286
77848338483 [] [] ["Cars", "Routes"] 12005
20524969030 ["ID", "ADDRESS"] [] ["Users"] 10923

Estadísticas agregadas

SPANNER_SYS también contiene tablas a fin de almacenar datos agregados de todas las transacciones para las que Cloud Spanner capturó estadísticas en un período específico:

  • SPANNER_SYS.TXN_STATS_TOTAL_MINUTE: agrega estadísticas para todas las transacciones durante intervalos de 1 minuto
  • SPANNER_SYS.TXN_STATS_TOTAL_10MINUTE: agrega estadísticas para todas las transacciones durante intervalos de 10 minutos
  • SPANNER_SYS.TXN_STATS_TOTAL_HOUR: agrega estadísticas para todas las transacciones durante intervalos de 1 hora

Las tablas conjuntas de estadísticas tienen las siguientes propiedades:

  • Cada tabla contiene datos de intervalos de tiempo no superpuestos de la longitud que se especifica en el nombre de la tabla.

  • Los intervalos se basan en tiempos de reloj. Los intervalos de 1 minuto finalizan en el minuto, los intervalos de 10 minutos finalizan cada 10 minutos a partir de la hora y los intervalos de 1 hora finalizan en la hora.

    Por ejemplo, a las 11:59:30 a.m., los intervalos más recientes disponibles para las consultas de SQL sobre las estadísticas de transacciones agregadas son los siguientes:

    • 1 minuto: de 11:58:00 a 11:58:59 a.m.
    • 10 minutos: de 11:40:00 a 11:49:59 a.m.
    • 1 hora: de 10:00:00 a 10:59:59 a.m.
  • Cada fila contiene estadísticas para todas las transacciones ejecutadas en la base de datos durante el intervalo especificado, combinadas. Solo hay una fila por intervalo de tiempo.

  • Las estadísticas capturadas en las tablas SPANNER_SYS.TXN_STATS_TOTAL_* pueden incluir transacciones que Cloud Spanner no capturó en las tablas SPANNER_SYS.TXN_STATS_TOP_*.

Esquema de la tabla

Nombre de la columna Tipo Descripción
INTERVAL_END TIMESTAMP Fin del intervalo en el que se capturó esta estadística.
COMMIT_ATTEMPT_COUNT INT64 Cantidad total de intentos de confirmación para la transacción. Incluye el intento inicial y cualquier reintento posterior, si la transacción se anula debido a un error recuperable.
COMMIT_ABORT_COUNT INT64 Cantidad de veces que se anularon las confirmaciones de la transacción.
COMMIT_RETRY_COUNT INT64 Cantidad de intentos de confirmación que son reintentos de intentos anulados con anterioridad. Es posible que una transacción de Cloud Spanner se haya intentado varias veces antes de que se confirme debido a bloqueos de bloqueo o eventos transitorios. Un número alto de reintentos en relación con los intentos de confirmación indica que puede haber problemas relacionados con la investigación. Para obtener más información, consulta Información sobre las transacciones y los recuentos de confirmaciones en esta página.
COMMIT_FAILED_PRECONDITION_COUNT INT64 Cantidad total de fallas de condiciones previas (FAILED_PRECONDITION) para la transacción.
AVG_PARTICIPANTS FLOAT64 Cantidad promedio de participantes en cada intento de confirmación. Para obtener más información sobre los participantes, consulta la página sobre la vida de las operaciones de lectura y escritura de Cloud Spanner.
AVG_TOTAL_LATENCY_SECONDS FLOAT64 Promedio de segundos tomados de la primera operación de la transacción que se confirmarán o anularán.
AVG_COMMIT_LATENCY_SECONDS FLOAT64 Promedio de segundos necesarios para realizar la operación de confirmación.
AVG_BYTES FLOAT64 Cantidad promedio de bytes que escribió la transacción.

Consultas de ejemplo

Esta sección incluye varias instrucciones de SQL de ejemplo que recuperan estadísticas de transacciones. Puedes ejecutar estas instrucciones de SQL con las bibliotecas cliente, la herramienta de línea de comandos de gcloud o Cloud Console.

Encuentra la cantidad total de intentos de confirmación para una transacción en un período determinado

En la siguiente consulta, se muestra la cantidad total de intentos de confirmación para todas las transacciones en el intervalo de 1 minuto completo más reciente:

SELECT interval_end,
       commit_attempt_count
FROM spanner_sys.txn_stats_total_minute
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.txn_stats_total_minute)
ORDER BY interval_end;
Resultado de la consulta
interval_end commit_attempt_count
2020-01-17 11:46:00-08:00 21

Ten en cuenta que solo hay una fila en el resultado porque las estadísticas agregadas tienen solo una entrada por interval_end para cualquier duración de tiempo.

Busca la latencia de confirmación total en todas las transacciones

La siguiente consulta muestra la latencia de confirmación total en todas las transacciones de los 10 minutos anteriores:

SELECT (avg_commit_latency_seconds * commit_attempt_count / 60 / 60)
  AS total_commit_latency_hours
FROM spanner_sys.txn_stats_total_10minute
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.txn_stats_total_10minute);
Resultado de la consulta
total_commit_latency_hours
0.8967

Ten en cuenta que solo hay una fila en el resultado porque las estadísticas agregadas tienen solo una entrada por interval_end para cualquier duración de tiempo.

Retención de datos

Como mínimo, Cloud Spanner conserva los datos para cada tabla durante los siguientes períodos:

  • SPANNER_SYS.TXN_STATS_TOP_MINUTE y SPANNER_SYS.TXN_STATS_TOTAL_MINUTE: Intervalos que abarcan las 6 horas anteriores.

  • SPANNER_SYS.TXN_STATS_TOP_10MINUTE y SPANNER_SYS.TXN_STATS_TOTAL_10MINUTE: Intervalos que abarcan los 4 días anteriores.

  • SPANNER_SYS.TXN_STATS_TOP_HOUR y SPANNER_SYS.TXN_STATS_TOTAL_HOUR: Intervalos que abarcan los 30 días anteriores.

Las estadísticas de transacciones en Cloud Spanner brindan información sobre cómo una aplicación usa la base de datos y son útiles para investigar problemas de rendimiento. Por ejemplo, puedes verificar si hay transacciones de ejecución lenta que podrían estar causando una contención, o puedes identificar posibles fuentes de carga alta, como grandes volúmenes de actualizaciones a una columna en particular. En los siguientes pasos, te mostraremos cómo usar las estadísticas de transacciones para investigar las relaciones en tu base de datos.

Comprende las transacciones y los recuentos de confirmaciones

Es posible que una transacción de Cloud Spanner se deba probar varias veces antes de que se confirme. Por lo general, esto ocurre cuando dos transacciones intentan trabajar en los mismos datos al mismo tiempo y una de las transacciones debe anularse para preservar la propiedad de aislamiento de la transacción. Estos son otros eventos transitorios que también pueden hacer que se anule una transacción:

  • Problemas transitorios de la red.

  • Los cambios en el esquema de la base de datos se aplican mientras una transacción está en proceso de confirmación.

  • La instancia de Cloud Spanner no tiene la capacidad de manejar todas las solicitudes que recibe.

En esas situaciones, un cliente debe volver a intentar la transacción anulada hasta que se confirme de manera correcta o se agote el tiempo de espera. Para los usuarios de las bibliotecas cliente oficiales de Cloud Spanner, cada biblioteca implementó un mecanismo de reintento automático. Si usas una versión personalizada del código de cliente, envuelve las confirmaciones de transacción en un bucle de intentos reiterados.

Una transacción de Cloud Spanner también se puede anular debido a un error no recuperable, como un tiempo de espera de transacción, problemas de permisos o un nombre de tabla/columna no válido. No es necesario volver a intentar esas transacciones, y la biblioteca cliente de Cloud Spanner mostrará el error de inmediato.

En la siguiente tabla, se describen algunos ejemplos de cómo COMMIT_ATTEMPT_COUNT, COMMIT_ABORT_COUNT y COMMIT_RETRY_COUNT se registran en situaciones diferentes.

Situación COMMIT_INTENT_COUNT COMMIT_ABORT_COUNT COMMIT_RETRY_COUNT
La transacción se confirmó correctamente en el primer intento. 1 0 0
Se anuló la transacción debido a un error en el tiempo de espera. 1 1 0
Se anuló la transacción debido a un problema de red transitorio y se confirmó de manera correcta después de un reintento. 2 1 1
5 transacciones con la misma FPRINT se ejecutan en un intervalo de 10 minutos. 3 de las transacciones se confirmaron correctamente en el primer intento, mientras que se anularon 2 transacciones y se confirmaron correctamente en el primer intento. 7 2 2

Los datos en las tablas de estadísticas de transacciones son datos agregados para un intervalo de tiempo. Para un intervalo en particular, es posible que la transacción y la anulación de una transacción suceda alrededor de los límites y se encuentren dentro de diferentes depósitos. Como resultado, en un intervalo de tiempo en particular, los anulaciones y los reintentos pueden no ser iguales.

Estas estadísticas están diseñadas para la solución de problemas y la introspección, y no se garantiza que sean 100% precisas. Las estadísticas se agregan en la memoria antes de almacenarse en las tablas de Cloud Spanner. Durante una actualización o cualquier otra actividad de mantenimiento, los servidores de Cloud Spanner pueden reiniciarse y esto afecta la precisión de los números.

Soluciona problemas de bases de datos de bases de datos mediante estadísticas de transacciones

Selecciona un período de tiempo para investigar

Esto se puede encontrar en la aplicación que usa Cloud Spanner.

A los fines de este ejercicio, supongamos que el problema comenzó a ocurrir alrededor de las 5:20 p.m. del 17 de mayo de 2020.

Recopila estadísticas de transacciones para el período seleccionado

Para comenzar la investigación, consultaremos la tabla TXN_STATS_TOTAL_10MINUTE durante el inicio del problema. Los resultados de esta consulta nos mostrarán cómo cambiaron la latencia y otras estadísticas de transacciones durante ese período.

Por ejemplo, la siguiente consulta muestra las estadísticas de transacciones agregadas de 4:30 pm a 7:40 pm (inclusive).

SELECT
  interval_end,
  ROUND(avg_total_latency_seconds,4) as avg_total_latency_seconds,
  commit_attempt_count,
  commit_abort_count
FROM SPANNER_SYS.TXN_STATS_TOTAL_10MINUTE
WHERE
  interval_end >= "2020-05-17T16:40:00"
  AND interval_end <= "2020-05-17T19:40:00"
ORDER BY interval_end;

En la siguiente tabla, se muestran datos de ejemplo de nuestra consulta.

interval_end avg_total_latency_seconds commit_attempt_count commit_abort_count
2020-05-17 16:40:00-07:00 0.0284 315691 5170
2020-05-17 16:50:00-07:00 0.0250 302124 3828
2020-05-17 17:00:00-07:00 0.0460 346087 11382
2020-05-17 17:10:00-07:00 0.0864 379964 33826
2020-05-17 17:20:00-07:00 0.1291 390343 52549
2020-05-17 17:30:00-07:00 0.1314 456455 76392
2020-05-17 17:40:00-07:00 0.1598 507774 121458
2020-05-17 17:50:00-07:00 0.1641 516587 115875
2020-05-17 18:00:00-07:00 0.1578 552711 122626
2020-05-17 18:10:00-07:00 0.1750 569460 154205
2020-05-17 18:20:00-07:00 0.1727 613571 160772
2020-05-17 18:30:00-07:00 0.1588 601994 143044
2020-05-17 18:40:00-07:00 0.2025 604211 170019
2020-05-17 18:50:00-07:00 0.1615 601622 135601
2020-05-17 19:00:00-07:00 0.1653 596804 129511
2020-05-17 19:10:00-07:00 0.1414 560023 112247
2020-05-17 19:20:00-07:00 0.1367 570864 100596
2020-05-17 19:30:00-07:00 0.0894 539729 65316
2020-05-17 19:40:00-07:00 0.0820 479151 40398

Aquí vemos que la latencia agregada y el recuento de anulaciones son superiores en los períodos destacados. Podemos elegir cualquier intervalo de 10 minutos en el que la latencia agregada o el recuento de anulaciones sean altos. Elige un intervalo que finalice en 2020-05-17T18:40:00 y úsalo en el siguiente paso para identificar qué transacciones contribuyen a la latencia alta y al recuento de anulaciones.

Identifica transacciones que experimentan una latencia alta

Ahora consultaremos la tabla TXN_STATS_TOP_10MINUTE para el intervalo que se seleccionó en el paso anterior. Con estos datos, podemos comenzar a identificar qué transacciones experimentan una latencia o un recuento de anulación atos.

Ejecuta la siguiente consulta para obtener las principales transacciones con impacto en el rendimiento en orden descendente de latencia total de nuestro intervalo de ejemplo que finaliza en 2020-05-17T18:40:00.

SELECT
  interval_end,
  fprint,
  ROUND(avg_total_latency_seconds,4) as avg_total_latency_seconds,
  ROUND(avg_commit_latency_seconds,4) as avg_commit_latency_seconds,
  commit_attempt_count,
  commit_abort_count,
  commit_retry_count
FROM SPANNER_SYS.TXN_STATS_TOP_10MINUTE
WHERE
  interval_end = "2020-05-17T18:40:00"
ORDER BY avg_total_latency_seconds DESC;
interval_end fprint avg_total_latency_seconds avg_commit_latency_seconds commit_attempt_count commit_abort_count commitment_retry_count
2020-05-17 18:40:00-07:00 15185072816865185658 0.3508 0.0139 278802 142205 129884
2020-05-17 18:40:00-07:00 15435530087434255496 0.1633 0.0142 129012 27177 24559
2020-05-17 18:40:00-07:00 14175643543447671202 0.1423 0.0133 5357 636 433
2020-05-17 18:40:00-07:00 898069986622520747 0.0198 0.0158 6 0 0
2020-05-17 18:40:00-07:00 10510121182038036893 0.0168 0.0125 7 0 0
2020-05-17 18:40:00-07:00 9287748709638024175 0.0159 0.0118 4269 1 0
2020-05-17 18:40:00-07:00 7129109266372596045 0.0142 0.0102 182227 0 0
2020-05-17 18:40:00-07:00 15630228555662391800 0.0120 0.0107 58 0 0
2020-05-17 18:40:00-07:00 7907238229716746451 0.0108 0.0097 65 0 0
2020-05-17 18:40:00-07:00 10158167220149989178 0.0095 0.0047 3454 0 0
2020-05-17 18:40:00-07:00 9353100217060788102 0.0093 0.0045 725 0 0
2020-05-17 18:40:00-07:00 9521689070912159706 0.0093 0.0045 164 0 0
2020-05-17 18:40:00-07:00 11079878968512225881 0.0064 0.0019 65 0 0

Podemos ver claramente que la primera fila (highlighted) en la tabla anterior muestra una transacción que experimenta una latencia alta debido a una gran cantidad de anulaciones de confirmación. También podemos ver una gran cantidad de reintentos de confirmación, que indica que se volvieron a intentar con las confirmaciones anuladas. En el siguiente paso, investigaremos con más profundidad para ver qué está causando este problema.

Descubre qué columnas están involucradas en una transacción que tiene una latencia alta

En este paso, comprobaremos si las transacciones de latencia alta funcionan en el mismo conjunto de columnas mediante la recuperación de datos read_columns, write_constructive_columns y write_delete_tables para transacciones con un gran recuento de anulaciones. El valor FPRINT también será útil en el siguiente paso.

SELECT
  fprint,
  read_columns,
  write_constructive_columns,
  write_delete_tables
FROM SPANNER_SYS.TXN_STATS_TOP_10MINUTE
WHERE
  interval_end = "2020-05-17T18:40:00"
ORDER BY avg_total_latency_seconds DESC LIMIT 3;
fprint read_columns write_constructive_columns write_delete_tables
15185072816865185658 [TestHigherLatency._exists,TestHigherLatency.lang_status,TestHigherLatency.score,globalTagAffinity.shares] [TestHigherLatency._exists,TestHigherLatency.shares,TestHigherLatency_lang_status_score_index.shares] []
15435530087434255496 [TestHigherLatency._exists,TestHigherLatency.lang_status,TestHigherLatency.likes,globalTagAffinity.score] [TestHigherLatency._exists,TestHigherLatency.likes,TestHigherLatency_lang_status_score_index.likes] []
14175643543447671202 [TestHigherLatency._exists,TestHigherLatency.lang_status,TestHigherLatency.score,globalTagAffinity.ugcCount] [TestHigherLatency._exists,TestHigherLatency.ugcCount,TestHigherLatency_lang_status_score_index.ugcCount] []

Como se muestra en la tabla anterior, las transacciones con la latencia total promedio más alta leen las mismas columnas. También podemos observar que hay contención de escritura, ya que las transacciones escriben en la misma columna, es decir, TestHigherLatency._exists.

Determina cómo cambió el rendimiento de las transacciones a lo largo del tiempo

Podemos ver cómo cambiaron las estadísticas asociadas con esta forma de transacción durante un período de tiempo. Usa la siguiente consulta, en la que $FPRINT es la huella digital de la transacción de alta latencia del paso anterior.

SELECT
  interval_end,
  ROUND(avg_total_latency_seconds, 3) AS latency,
  ROUND(avg_commit_latency_seconds, 3) AS commit_latency,
  commit_attempt_count,
  commit_abort_count,
  commit_retry_count,
  commit_failed_precondition_count,
  avg_bytes
FROM SPANNER_SYS.TXN_STATS_TOP_10MINUTE
WHERE
  interval_end >= "2020-05-17T16:40:00"
  AND interval_end <= "2020-05-17T19:40:00"
  AND fprint = $FPRINT
ORDER BY interval_end;
interval_end latency commit_latency commit_attempt_count commit_abort_count commitment_retry_count commit_failed_precondition_count avg_bytes
2020-05-17 16:40:00-07:00 0.095 0.010 53230 4752 4330 0 91
2020-05-17 16:50:00-07:00 0.069 0.009 61264 3589 3364 0 91
2020-05-17 17:00:00-07:00 0.150 0.010 75868 10557 9322 0 91
2020-05-17 17:10:00-07:00 0,48 0.013 103151 30220 28483 0 91
17-05-20-17:20:00-07:00 0,10 0.012 130078 45655 41966 0 91
17-05-20-17:30:00-07:00 0.294 0.012 160064 64930 59933 0 91
17-05-20-17:40:00-07:00 0,15 0.013 209614 104949 96770 0 91
17-05-20-17:50:00-07:00 0,222 0.012 215682 100408 95867 0 90
17-05-20-18:00:00-07:00 0,10 0.012 230932 106,728 99462 0 91
17-05-20-18:10:00-07:00 0,39 0.012 259645 131049 125889 0 91
17-05-20-18:20:00-07:00 0,15 0.013 272171 137910 129411 0 90
17-05-20-18:30:00-07:00 0,292 0.013 258944 121475 115844 0 91
2020-05-17 18:40:00-07:00 0,50 0.013 278802 142205 134229 0 91
17-05-20-18:50:00-07:00 0,32 0.013 256259 115626 109756 0 91
17-05-20-19:00:00-07:00 0,15 0.014 250560 110662 100322 0 91
17-05-20-19:10:00-07:00 0,711 0.014 238384 99025 90187 0 91
17-05-20-19:20:00-07:00 0,2773 0.014 219687 84019 79874 0 91
2020-05-17 19:30:00-07:00 0.198 0.013 195357 59370 55909 0 91
2020-05-17 19:40:00-07:00 0.181 0.013 167514 35705 32885 0 91

En el resultado anterior, podemos observar que la latencia total es alta en el período destacado. Mientras que la latencia total es alta, commit_attempt_count commit_abort_count y commit_retry_count también son altos, aunque la latencia de confirmación (commit_latency) no cambió mucho. Dado que las confirmaciones de transacción se anulan con más frecuencia, los intentos de confirmación también son altos debido a los reintentos de confirmación.

Conclusión

En este ejemplo, notamos que el recuento alto de anulaciones de confirmaciones fue la causa de la latencia alta. El siguiente paso es mirar los mensajes de error de anulación de confirmaciones que recibe la aplicación para conocer el motivo de la anulación. Cuando inspeccionamos registros en la aplicación, vemos que la app cambió su carga de trabajo durante este período, es decir, otra forma de transacción se mostró con un valor de attempts_per_second alto y esa transacción diferente (tal vez un trabajo de limpieza nocturno) fue responsable de los conflictos de bloqueo adicionales.

Cómo identificar transacciones que no se reintentan correctamente

La siguiente consulta muestra las transacciones de muestra de los últimos diez minutos que tienen un recuento de anulación de confirmación alto, pero sin reintentos.

SELECT
  *
FROM (
  SELECT
    fprint,
    SUM(commit_attempt_count) AS total_commit_attempt_count,
    SUM(commit_abort_count) AS total_commit_abort_count,
    SUM(commit_retry_count) AS total_commit_retry_count
  FROM
    SPANNER_SYS.TXN_STATS_TOP_10MINUTE
  GROUP BY
    fprint )
WHERE
  total_commit_retry_count = 0
  AND total_commit_abort_count > 0
ORDER BY
  total_commit_abort_count DESC;
fprint total_commitment_attempt_count total_commit_abort_count total_commit_retry_count
1557557373282541312 3367894 44232 0
5776062322886969344 13566 14 0

Podemos ver que la transacción con el fprint 1557557373282541312 se anuló en 4232 veces, pero nunca se volvió a intentar. Esto parece sospechoso porque el conteo de anulación es alto y es poco probable que cada anulación sea causada por un error no recuperable. Por otro lado, para la transacción con fprint 5776062322886969344, es menos sospechosa porque el recuento total de anulaciones no es tan alto.

La siguiente consulta muestra más detalles sobre la transacción con fprint 1557557373282541312,incluidos read_colums, write_constructive_columns y write_delete_tables. Esta información ayuda a identificar la transacción en el código del cliente, en la que se puede revisar la lógica de reintento para esta situación.

SELECT
  interval_end,
  fprint,
  read_columns,
  write_constructive_columns,
  write_delete_tables,
  commit_attempt_count,
  commit_abort_count,
  commit_retry_count
FROM
  SPANNER_SYS.TXN_STATS_TOP_10MINUTE
WHERE
  fprint = 1557557373282541312
ORDER BY
  interval_end DESC;
interval_end fprint read_columns write_constructive_columns write_delete_tables commit_attempt_count commit_abort_count commitment_retry_count
2021-01-27T18:30:00Z 1557557373282541312 ["Singers._exists'] ["Singers.FirstName", "Singers.LastName", "Singers._exists'] [] 805228 1839 0
2021-01-27T18:20:00Z 1557557373282541312 ["Singers._exists'] ["Singers.FirstName", "Singers.LastName", "Singers._exists'] [] 1034429 38779 0
2021-01-27T18:10:00Z 1557557373282541312 ["Singers._exists'] ["Singers.FirstName", "Singers.LastName", "Singers._exists'] [] 833677 2266 0
2021-01-27T18:00:00Z 1557557373282541312 ["Singers._exists'] ["Singers.FirstName", "Singers.LastName", "Singers._exists'] [] 694560 1348 0

Podemos ver que la transacción implica una lectura en la columna oculta Singers._exists para verificar la existencia de una fila. La transacción también escribe en las columnas Singers.FirstName y Singer.LastName. Esta información puede ayudar a determinar si el mecanismo de reintento de transacción implementado en tu biblioteca cliente personalizada funciona como se esperaba.

¿Qué sigue?