Estatísticas de transação

O Cloud Spanner fornece tabelas integradas que armazenam estatísticas sobre transações. É possível recuperar estatísticas dessas tabelas SPANNER_SYS.TXN_STATS* usando instruções SQL.

Quando usar estatísticas de transação

As estatísticas de transação são úteis ao investigar problemas de desempenho. Por exemplo, é possível verificar se há transações de execução lenta que podem estar afetando o desempenho ou as consultas por segundo (QPS, na sigla em inglês) no banco de dados. Outro cenário é quando os aplicativos cliente estão com alta latência de execução de transações. A análise das estatísticas de transações pode ajudar a descobrir possíveis gargalos, como grandes volumes de atualizações em uma coluna específica, o que pode estar afetando a latência.

Disponibilidade

SPANNER_SYS os dados estão disponíveis somente por meio de interfaces SQL (por exemplo, executeQuery e gcloud spanner databases execute-sql); outros métodos de leitura única fornecidos pelo Cloud Spanner não são compatíveis com SPANNER_SYS.

Estatísticas de latência agrupadas por transação

As tabelas a seguir rastreiam as estatísticas de transações TOP com consumo intensivo de recursos durante um período específico.

  • SPANNER_SYS.TXN_STATS_TOP_MINUTE: estatísticas de transação agregadas em intervalos de 1 minuto.

  • SPANNER_SYS.TXN_STATS_TOP_10MINUTE: estatísticas de transação agregadas em intervalos de 10 minutos.

  • SPANNER_SYS.TXN_STATS_TOP_HOUR: estatísticas de transação agregadas em intervalos de 1 hora.

Essas tabelas têm as seguintes propriedades:

  • Cada uma contém dados para intervalos de tempo não sobrepostos do comprimento que o nome da tabela específica.

  • Os intervalos são baseados em tempos de relógio. Os de 1 minuto terminam no minuto, os de 10 minutos terminam a cada 10 minutos, começando na hora, e os intervalos de 1 hora terminam na hora.

    Por exemplo, às 11:59:30, os intervalos mais recentes disponíveis para as consultas SQL são:

    • 1 minuto: 11:58:01–11:59:00
    • 10 minutos: 11:40:01–11:50:00
    • 1 hora: 10:00:01–11:00:00
  • O Cloud Spanner agrupa as estatísticas por FPRINT (impressão digital) das transações. FPRINT é o hash calculado com base nas operações envolvidas na transação.

  • Como as estatísticas são agrupadas com base em FPRINT, se a mesma transação for executada várias vezes em qualquer intervalo de tempo, ainda veremos apenas uma entrada para a transação em questão nessas tabelas.

  • Cada linha contém estatísticas de todas as execuções de uma transação específica para a qual o Cloud Spanner captura estatísticas durante o intervalo especificado.

Se o Cloud Spanner não conseguir armazenar estatísticas para todas as transações executadas durante o intervalo nessas tabelas, o sistema priorizará as transações com a maior latência, tentativas de confirmação e bytes gravados durante o intervalo especificado.

Esquema de tabela

Nome da coluna Tipo Descrição
INTERVAL_END TIMESTAMP Fim do intervalo de tempo em que as execuções de transação incluídas ocorreram.
FPRINT INT64 A impressão digital é o hash calculado com base nas operações envolvidas na transação. Juntos, INTERVAL_END e FPRINT atuam como uma chave exclusiva para essas tabelas.
READ_COLUMNS ARRAY<STRING> O conjunto de colunas que foram lidas pela transação.
WRITE_CONSTRUCTIVE_COLUMNS ARRAY<STRING> O conjunto de colunas que foram gravadas construtivamente (ou seja, atribuídas a novos valores) pela transação.
WRITE_DELETE_TABLES ARRAY<STRING> O conjunto de tabelas que tiveram linhas excluídas ou substituídas pela transação.
COMMIT_ATTEMPT_COUNT INT64 Número total de tentativas de confirmação na transação.
COMMIT_FAILED_PRECONDITION_COUNT INT64 Número total de falhas de pré-condição (FAILED_PRECONDITION) para a transação.
COMMIT_ABORT_COUNT INT64 Número de vezes que as confirmações foram canceladas para a transação.
AVG_PARTICIPANTS FLOAT64 Número médio de participantes em cada tentativa de confirmação. Para saber mais sobre os participantes, consulte Vida útil das leituras e gravações do Cloud Spanner.
AVG_TOTAL_LATENCY_SECONDS FLOAT64 Média de segundos tomada da primeira operação da transação a ser confirmada/cancelada.
AVG_COMMIT_LATENCY_SECONDS FLOAT64 Média de segundos usados para executar a operação de confirmação.
AVG_BYTES FLOAT64 Número médio de bytes gravados pela transação.

Consultas de exemplo

Nesta seção, há várias instruções SQL de exemplo que recuperam estatísticas de transação. É possível executar essas instruções SQL usando as bibliotecas de cliente, a ferramenta de linha de comando gcloud ou o Console do Cloud.

Listar as estatísticas básicas de cada transação em um determinado período

A consulta a seguir retorna os dados brutos das principais transações no 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);
Saída da 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

Listar as transações com a maior latência média de confirmação

A consulta a seguir retorna as transações com alta latência média de confirmação na hora anterior, ordenadas da latência média mais alta para a mais baixa.

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;
Saída da 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

Encontrar a latência média de transações que leem determinadas colunas

A consulta a seguir retorna as informações de latência média das transações que leem a coluna ADDRESS das estatí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;
Saída da 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

Listar transações pelo número médio de bytes modificados

A consulta a seguir retorna as transações de amostra na última hora, ordenadas pelo número médio de bytes modificados pela transação.

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

Agregar estatísticas

SPANNER_SYS também contém tabelas para armazenar dados agregados de todas as transações para as quais o Cloud Spanner capturou estatísticas em um período específico:

  • SPANNER_SYS.TXN_STATS_TOTAL_MINUTE: agregar estatísticas de todas as transações durante intervalos de 1 minuto
  • SPANNER_SYS.TXN_STATS_TOTAL_10MINUTE: agregar estatísticas de todas as transações durante intervalos de 10 minutos
  • SPANNER_SYS.TXN_STATS_TOTAL_HOUR: agregar estatísticas de todas as transações durante intervalos de 1 hora

As tabelas de estatísticas agregadas têm as seguintes propriedades:

  • Cada uma contém dados para intervalos de tempo não sobrepostos do comprimento que o nome da tabela específica.

  • Os intervalos são baseados em tempos de relógio. Os de 1 minuto terminam no minuto, os de 10 minutos terminam a cada 10 minutos, começando na hora, e os intervalos de 1 hora terminam na hora.

    Por exemplo, às 11h59m30s, os intervalos mais recentes disponíveis para consultas SQL em estatísticas de transação agregadas são:

    • 1 minuto: 11:58:01–11:59:00
    • 10 minutos: 11:40:01–11:50:00
    • 1 hora: 10:00:01–11:00:00
  • Cada linha contém estatísticas de todas as transações agregadas executadas no banco de dados durante o intervalo especificado. Há apenas uma linha por intervalo de tempo.

  • As estatísticas capturadas nas tabelas SPANNER_SYS.TXN_STATS_TOTAL_* podem incluir transações que o Cloud Spanner não capturou nas tabelas SPANNER_SYS.TXN_STATS_TOP_*.

Esquema de tabela

Nome da coluna Tipo Descrição
INTERVAL_END TIMESTAMP Fim do intervalo de tempo em que essa estatística foi capturada.
COMMIT_ATTEMPT_COUNT INT64 Número total de tentativas de confirmação na transação.
COMMIT_FAILED_PRECONDITION_COUNT INT64 Número total de falhas de pré-condição (FAILED_PRECONDITION) para a transação.
COMMIT_ABORT_COUNT INT64 Número de vezes que as confirmações foram canceladas para a transação.
AVG_PARTICIPANTS FLOAT64 Número médio de participantes em cada tentativa de confirmação. Para saber mais sobre os participantes, consulte Vida útil das leituras e gravações do Cloud Spanner.
AVG_TOTAL_LATENCY_SECONDS FLOAT64 Média de segundos tomada da primeira operação da transação a ser confirmada/cancelada.
AVG_COMMIT_LATENCY_SECONDS FLOAT64 Média de segundos necessários para executar a operação de confirmação.
AVG_BYTES FLOAT64 Número médio de bytes gravados pela transação.

Consultas de exemplo

Nesta seção, há várias instruções SQL de exemplo que recuperam estatísticas de transação. É possível executar essas instruções SQL usando as bibliotecas de cliente, a ferramenta de linha de comando gcloud ou o Console do Cloud.

Encontrar o número total de tentativas de confirmação para uma transação em um determinado período

A consulta a seguir retorna o número total de tentativas de confirmação para todas as transações no intervalo completo de 1 minuto mais recente:

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;
Saída da consulta
interval_end commit_attempt_count
2020-01-17 11:46:00-08:00 21

Há apenas uma linha no resultado porque as estatísticas agregadas têm apenas uma entrada por interval_end para qualquer duração.

Encontrar a latência total de confirmação em todas as transações

A consulta a seguir retorna a latência total de confirmação em todas as transações nos últimos 10 minutos:

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);
Saída da consulta
total_commit_latency_hours
0.8967

Há apenas uma linha no resultado porque as estatísticas agregadas têm apenas uma entrada por interval_end para qualquer duração.

Retenção de dados

O Cloud Spanner mantém dados para cada tabela, no mínimo, pelos períodos a seguir:

  • SPANNER_SYS.TXN_STATS_TOP_MINUTE e SPANNER_SYS.TXN_STATS_TOTAL_MINUTE: intervalos que abrangem as seis horas anteriores.

  • SPANNER_SYS.TXN_STATS_TOP_10MINUTE e SPANNER_SYS.TXN_STATS_TOTAL_10MINUTE: intervalos abrangendo os quatro dias anteriores.

  • SPANNER_SYS.TXN_STATS_TOP_HOUR e SPANNER_SYS.TXN_STATS_TOTAL_HOUR: intervalos que abrangem os últimos 30 dias.

As estatísticas de transações no Cloud Spanner fornecem insights sobre como um aplicativo está usando o banco de dados e são úteis para investigar problemas de desempenho. Por exemplo, é possível verificar se há transações de execução lenta que possam estar causando contenção ou identificar possíveis origens de alta carga, como grandes volumes de atualizações em uma coluna específica. Usando as etapas a seguir, mostraremos como usar as estatísticas de transação para investigar contenções no seu banco de dados.

Solução de problemas de contenção de banco de dados usando estatísticas de transação

Etapa 1: selecionar um período para investigar

Isso pode ser encontrado no aplicativo que está usando o Cloud Spanner.

Para os fins deste exercício, digamos que o problema começou a ocorrer às 17h20 do dia 17 de maio de 2020.

Etapa 2: coletar estatísticas de transações para o período selecionado

Para iniciar nossa investigação, consultaremos a tabela TXN_STATS_TOTAL_10MINUTE em torno do início do problema. Os resultados dessa consulta mostrarão como a latência e outras estatísticas de transação foram alteradas durante esse período.

Por exemplo, a consulta a seguir retorna as estatísticas de transações agregadas de 4:30 pm para 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;

A tabela a seguir lista exemplos de dados retornados da nossa 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

Aqui, vemos que a latência agregada e a contagem de cancelamentos são maiores nos períodos destacados. Podemos escolher qualquer intervalo de 10 minutos em que a latência agregada e/ou a contagem de cancelamentos sejam altas. Vamos escolher o intervalo que termina em 2020-05-17T18:40:00 e usá-lo na próxima etapa para identificar quais transações contribuem para a alta latência e a contagem de cancelamentos.

Etapa 3: identificar transações com alta latência

Agora, consultaremos a tabela TXN_STATS_TOP_10MINUTE em busca do intervalo escolhido na etapa anterior. Usando esses dados, podemos começar a identificar quais transações apresentam alta latência e/ou alta contagem de cancelamentos.

Execute a consulta a seguir para receber as principais transações que afetam o desempenho em ordem decrescente de latência total para nosso intervalo de exemplo que termina em 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
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
2020-05-17 18:40:00-07:00 15185072816865185658 0,3508 0,0139 278802 142205
2020-05-17 18:40:00-07:00 15435530087434255496 0,1633 0,0142 129012 27177
2020-05-17 18:40:00-07:00 14175643543447671202 0,1423 0,0133 5357 636
2020-05-17 18:40:00-07:00 898069986622520747 0,0198 0,0158 6 0
2020-05-17 18:40:00-07:00 10510121182038036893 0,0168 0,0125 7 0
2020-05-17 18:40:00-07:00 9287748709638024175 0,0159 0,0118 4269 1
2020-05-17 18:40:00-07:00 7129109266372596045 0,0142 0,0102 182227 0
2020-05-17 18:40:00-07:00 15630228555662391800 0,0120 0,0107 58 0
2020-05-17 18:40:00-07:00 7907238229716746451 0,0108 0,0097 65 0
2020-05-17 18:40:00-07:00 10158167220149989178 0,0095 0,0047 3454 0
2020-05-17 18:40:00-07:00 9353100217060788102 0,0093 0,0045 725 0
2020-05-17 18:40:00-07:00 9521689070912159706 0,0093 0,0045 164 0
2020-05-17 18:40:00-07:00 11079878968512225881 0,0064 0,0019 65 0

Podemos ver claramente que a primeira linha (destacada) na tabela anterior mostra uma transação com alta latência devido a um grande número de cancelamentos de confirmação. Na próxima etapa, investigaremos mais a causa do problema.

Etapa 4: descobrir quais colunas estão envolvidas em uma transação com alta latência

Nesta etapa, verificaremos se as transações de alta latência estão operando no mesmo conjunto de colunas, buscando dados read_columns, write_constructive_columns e write_delete_tables para transações com alta contagem de cancelamentos. O valor FPRINT também será útil na próxima etapa.

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
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 mostrado na tabela anterior, as transações com a latência média total mais alta são lidas pelas mesmas colunas. Também é possível observar alguma contenção de gravação porque as transações estão gravando na mesma coluna, ou seja, TestHigherLatency._exists.

Etapa 5: determinar como o desempenho da transação mudou ao longo do tempo

Podemos ver como as estatísticas associadas a essa forma de transação foram alteradas ao longo de um período. Use a consulta a seguir, em que $FPRINT é a impressão digital da transação de alta latência da etapa 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_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 commit_failed_precondition_count avg_bytes
2020-05-17 16:40:00-07:00 0,095 0,010 53230 4752 0 91
2020-05-17 16:50:00-07:00 0,069 0,009 61264 3589 0 91
2020-05-17 17:00:00-07:00 0,150 0,010 75868 10557 0 91
2020-05-17 17:10:00-07:00 0,248 0,013 103151 30220 0 91
2020-05-17 17:20:00-07:00 0,310 0,012 130078 45655 0 91
2020-05-17 17:30:00-07:00 0,294 0,012 160064 64930 0 91
2020-05-17 17:40:00-07:00 0,315 0,013 209614 104949 0 91
2020-05-17 17:50:00-07:00 0,322 0,012 215682 100408 0 90
2020-05-17 18:00:00-07:00 0,310 0,012 230932 106728 0 91
2020-05-17 18:10:00-07:00 0,309 0,012 259645 131049 0 91
2020-05-17 18:20:00-07:00 0,315 0,013 272171 137910 0 90
2020-05-17 18:30:00-07:00 0,292 0,013 258944 121475 0 91
2020-05-17 18:40:00-07:00 0,350 0,013 278802 142205 0 91
2020-05-17 18:50:00-07:00 0,302 0,013 256259 115626 0 91
2020-05-17 19:00:00-07:00 0,315 0,014 250560 110662 0 91
2020-05-17 19:10:00-07:00 0,271 0,014 238384 99025 0 91
2020-05-17 19:20:00-07:00 0,273 0,014 219687 84019 0 91
2020-05-17 19:30:00-07:00 0,198 0,013 195357 59370 0 91
2020-05-17 19:40:00-07:00 0,181 0,013 167514 35705 0 91

Na saída acima, podemos observar que a latência total é alta para o período destacado. E, sempre que a latência total for alta, commit_attempt_count e commit_abort_coun também serão altos, mesmo que a latência de confirmação (commit_latency) não tenha mudado muito. Como as confirmações de transação são canceladas com mais frequência, as tentativas de confirmação também são altas devido a novas tentativas de confirmação.

Etapa 6: conclusão

Neste exemplo, vemos que a alta contagem de cancelamentos de confirmação foi a causa da alta latência. A próxima etapa é analisar as mensagens de erro de cancelamento de confirmação recebidas pelo aplicativo para saber o motivo dos cancelamentos. Ao inspecionar registros no aplicativo, vemos que ele realmente alterou a carga de trabalho durante esse período, ou seja, outra forma de transação foi mostrada com attempts_per_second alto, e essa transação diferente (talvez um job de limpeza noturna) foi responsável pelos conflitos de bloqueio adicionais.

A seguir