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

Os dados do SPANNER_SYS estão disponíveis somente por meio de interfaces SQL. Por exemplo:

  • Página do Spanner Studio de um banco de dados no console do Google Cloud

  • O comando gcloud spanner databases execute-sql

  • Painel Insights da transação

  • A API executeQuery

Outros métodos de leitura única fornecidos pelo 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 nos horários do relógio. Os intervalos 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:00–11:58:59
    • 10 minutos: 11:40:00–11:49:59
    • 1 hora: 10:00:00–10:59:59
  • O Spanner agrupa as estatísticas por F referentes (impressão digital) às transações. Se uma tag de transação estiver presente, F referentes será o hash da tag. Caso contrário, será 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 para todas as execuções de uma transação específica em que o Spanner captura estatísticas durante o intervalo especificado.

Se o Spanner não puder armazenar as estatísticas de todas as transações executadas durante o intervalo nessas tabelas, o sistema priorizará 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.
TRANSACTION_TAG STRING Tag opcional da transação para esta operação de transação. Para mais informações sobre o uso de tags, consulte Solução de problemas com tags de transação. As estatísticas de várias transações que têm a mesma string de tag são agrupadas em uma única linha com "TRANSACTION_TAG" correspondente a essa string de tag.
FPRINT INT64 Hash de TRANSACTION_TAG, se houver. Caso contrário, o hash será 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.

Para fluxos de alterações, se a transação envolver gravações em colunas e tabelas monitoradas por um fluxo de alterações, WRITE_CONSTRUCTIVE_COLUMNS vai conter duas colunas, .data e ._exists 1, prefixadas com um nome de fluxo de alterações.
WRITE_DELETE_TABLES ARRAY<STRING> O conjunto de tabelas que tiveram linhas excluídas ou substituídas pela transação.
ATTEMPT_COUNT INT64 Número total de tentativas de transação, incluindo as tentativas de cancelamento antes de chamar "commit".
COMMIT_ATTEMPT_COUNT INT64 Número total de tentativas de confirmação da transação. Precisa corresponder ao número de chamadas para o método commit da transação.
COMMIT_ABORT_COUNT INT64 Número total de tentativas de transação que foram canceladas, incluindo aquelas que foram canceladas antes de chamar o método commit da transação.
COMMIT_RETRY_COUNT INT64 Número total de tentativas de tentativas canceladas anteriormente. Uma transação do Spanner pode ser testada várias vezes antes de ser confirmada devido a contenções de bloqueio ou eventos temporários. Um número alto de novas tentativas em relação às tentativas de confirmação indica que pode haver problemas que valem a pena investigar. Para mais informações, consulte Noções básicas sobre transações e contagens de confirmações nesta página.
COMMIT_FAILED_PRECONDITION_COUNT INT64 Número total de tentativas de confirmação de transação que retornaram erros de pré-condição com falha, como violações de índice UNIQUE, linha já existe, linha não encontrada e assim por diante.
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.
TOTAL_LATENCY_DISTRIBUTION ARRAY<STRUCT>

Um histograma da latência total de confirmação, que é o tempo desde o horário de início da primeira operação transacional até o momento de confirmação ou cancelamento, para todas as tentativas de uma transação.

Se uma transação é cancelada várias vezes e depois é confirmada com sucesso, a latência é medida para cada tentativa até a confirmação final bem-sucedida. Os valores são medidos em segundos.

A matriz contém um único elemento e tem o seguinte tipo:
ARRAY<STRUCT<
  COUNT INT64,
  MEAN FLOAT64,
  SUM_OF_SQUARED_DEVIATION FLOAT64,
  NUM_FINITE_BUCKETS INT64,
  GROWTH_FACTOR FLOAT64,
  SCALE FLOAT64,
  BUCKET_COUNTS ARRAY<INT64>>>

Para mais informações sobre os valores, consulte Distribuição.

Para calcular a latência do percentil desejado a partir da distribuição, use a função SPANNER_SYS.DISTRIBUTION_PERCENTILE(distribution, n FLOAT64), que retorna o n percentil estimado. Para ver um exemplo relacionado, consulte Encontrar a latência de 99o percentil para transações.

Para mais informações, consulte Percentis e métricas com valor de distribuição.

OPERATIONS_BY_TABLE ARRAY<STRUCT>

Impacto das operações INSERT ou UPDATE pela transação em cada tabela. Isso é indicado pelo número de vezes que as linhas são afetadas e pelo número de bytes gravados.

Essa coluna ajuda a visualizar a carga nas tabelas e fornece insights sobre a taxa com que uma transação é gravada.

Especifique a matriz da seguinte maneira:
ARRAY<STRUCT<
  TABLE STRING(MAX),
  INSERT_OR_UPDATE_COUNT INT64,
  INSERT_OR_UPDATE_BYTES INT64>>

1 _exists é um campo interno usado para verificar se uma determinada linha existe ou não.

Exemplo de consultas

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 Google 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,
       operations_by_table,
       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 operations_by_table avg_bytes
40015598317 [] ["Routes.name", "Cars.model"] ["Users"] 0.006578737 0.006547737 [["Cars",1107,30996],["Routes",560,26880]] 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.name", "Cars.model"] ["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 em que o 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 horas. Os intervalos 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:00–11:58:59
    • 10 minutos: 11:40:00–11:49:59
    • 1 hora: 10:00:00–10:59:59
  • 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 Spanner não capturou nas tabelas SPANNER_SYS.TXN_STATS_TOP_*.

  • Algumas colunas nestas tabelas são expostas como métricas no Cloud Monitoring. As métricas expostas são:

    • Contagem de tentativas de confirmação
    • Contagem de novas tentativas de confirmação
    • Participantes da transação
    • Latências de transações
    • Bytes gravados

    Para mais informações, consulte Métricas do Spanner.

Esquema de tabela

Nome da coluna Tipo Descrição
INTERVAL_END TIMESTAMP Fim do intervalo de tempo em que essa estatística foi capturada.
ATTEMPT_COUNT INT64 Número total de vezes que as transações são tentadas, incluindo as tentativas de cancelamento antes de chamar "commit".
COMMIT_ATTEMPT_COUNT INT64 Número total de tentativas de confirmação da transação. Precisa corresponder ao número de chamadas para o método commit da transação.
COMMIT_ABORT_COUNT INT64 Número total de tentativas de transação que foram canceladas, incluindo aquelas que foram canceladas antes de chamar o método commit da transação.
COMMIT_RETRY_COUNT INT64 Número de tentativas de confirmação que são tentativas anteriores de serem canceladas. Uma transação do Spanner pode ter sido testada várias vezes antes da confirmação devido a contenções de bloqueio ou eventos temporários. Um número alto de novas tentativas em relação às tentativas de confirmação indica que pode haver problemas que valem a pena investigar. Para mais informações, consulte Noções básicas sobre transações e contagens de confirmações nesta página.
COMMIT_FAILED_PRECONDITION_COUNT INT64 Número total de tentativas de confirmação de transação que retornaram erros de pré-condição com falha, como violações de índice UNIQUE, linha já existe, linha não encontrada e assim por diante.
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.
TOTAL_LATENCY_DISTRIBUTION ARRAY<STRUCT>

Um histograma da latência total de confirmação, que é o tempo desde o horário de início da primeira operação transacional até o horário de confirmação ou cancelamento de todas as tentativas de transação.

Se uma transação for cancelada várias vezes e, em seguida, for confirmada com êxito, a latência será medida para cada tentativa até a confirmação final bem-sucedida. Os valores são medidos em segundos.

A matriz contém um único elemento e tem o seguinte tipo:
ARRAY<STRUCT<
  COUNT INT64,
  MEAN FLOAT64,
  SUM_OF_SQUARED_DEVIATION FLOAT64,
  NUM_FINITE_BUCKETS INT64,
  GROWTH_FACTOR FLOAT64,
  SCALE FLOAT64,
  BUCKET_COUNTS ARRAY<INT64>>>

Para mais informações sobre os valores, consulte Distribuição.

Para calcular a latência do percentil desejado a partir da distribuição, use a função SPANNER_SYS.DISTRIBUTION_PERCENTILE(distribution, n FLOAT64), que retorna o n percentil estimado. Por exemplo, consulte Encontrar a latência de 99o percentil para transações.

Para mais informações, consulte Percentis e métricas com valor de distribuição.

OPERATIONS_BY_TABLE ARRAY<STRUCT>

Impacto das operações INSERT ou UPDATE por todas as transações em cada tabela. Isso é indicado pelo número de vezes em que as linhas são afetadas e pelo número de bytes gravados.

Essa coluna ajuda a visualizar a carga nas tabelas e fornece insights sobre a taxa em que as transações gravam nas tabelas.

Especifique a matriz da seguinte maneira:
ARRAY<STRUCT<
  TABLE STRING(MAX),
  INSERT_OR_UPDATE_COUNT INT64,
  INSERT_OR_UPDATE_BYTES INT64>>

Exemplo de consultas

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 Google Cloud.

Encontrar o número total de tentativas de confirmação para uma transação

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.

Encontrar a latência do 99o percentil das transações

A consulta a seguir retorna a latência do 99o percentil das transações executadas nos 10 minutos anteriores:

SELECT interval_end, avg_total_latency_seconds,
       SPANNER_SYS.DISTRIBUTION_PERCENTILE(total_latency_distribution[OFFSET(0)], 99.0)
  AS percentile_latency
FROM spanner_sys.txn_stats_total_10minute
WHERE interval_end =
  (SELECT MAX(interval_end)
   FROM spanner_sys.txn_stats_total_10minute)
ORDER BY interval_end;

Saída da consulta
interval_end avg_total_latency_seconds percentile_latency
2022-08-17 11:46:00-08:00 0.34576998305986395 9.00296190476190476

Observe a grande diferença entre a latência média e a latência do 99o percentil. A latência do 99o percentil ajuda a identificar possíveis transações de outliers com alta latência.

Há apenas uma linha no resultado porque as estatísticas agregadas têm apenas uma entrada por interval_end para qualquer período.

Retenção de dados

O Spanner mantém dados de cada tabela, no mínimo, para os 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ção no Spanner oferecem insights sobre como um aplicativo está usando o banco de dados e são úteis ao 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.

Entender transações e contagens de confirmações

Pode ser necessário tentar várias vezes uma transação do Spanner para ser confirmada. Isso geralmente ocorre quando duas transações tentam trabalhar nos mesmos dados ao mesmo tempo, e uma das transações precisa ser cancelada para preservar a propriedade de isolamento de transação. Outros eventos transitórios que também podem cancelar uma transação incluem:

  • Problemas temporários de rede.

  • Alterações no esquema do banco de dados que estão sendo aplicadas enquanto uma transação está em processo de confirmação.

  • A instância do Spanner não tem capacidade para processar todas as solicitações que está recebendo.

Nesses cenários, um cliente precisa repetir a transação cancelada até que ele seja confirmado ou expire. Para usuários das bibliotecas de cliente oficiais do Spanner, cada biblioteca implementou um mecanismo automático de repetição. Se você estiver usando uma versão personalizada do código do cliente, una as confirmações de transação em um loop de repetição.

Uma transação do Spanner também pode ser cancelada devido a um erro que não pode ser repetido, como um tempo limite da transação, problemas de permissão ou um nome de tabela/coluna inválido. Não é necessário repetir essas transações, e a biblioteca de cliente do Spanner retornará o erro imediatamente.

A tabela a seguir descreve alguns exemplos de como COMMIT_ATTEMPT_COUNT, COMMIT_ABORT_COUNT e COMMIT_RETRY_COUNT são registrados em diferentes cenários.

Cenário COMMIT_ATTEMPT_COUNT COMMIT_ABORT_COUNT COMMIT_RETRY_COUNT
Transação confirmada na primeira tentativa. 1 0 0
Transação cancelada devido a um erro de tempo limite. 1 1 0
Transação cancelada devido a um problema de rede temporário e confirmada após uma nova tentativa. 2 1 1
Cinco transações com o mesmo FPRINT são executadas em um intervalo de 10 minutos. 3 das transações foram confirmadas na primeira tentativa, e 2 foram canceladas e confirmadas na primeira tentativa. 7 2 2

Os dados nas tabelas de estatísticas da transação são dados agregados de um intervalo de tempo. Para um intervalo específico, é possível que um cancelamento de transação e uma nova tentativa ocorra em torno dos limites e caia em buckets diferentes. Como resultado, em um intervalo de tempo específico, as tentativas e cancelamentos podem não ser iguais.

Elas são projetadas para solucionar problemas e apresentar introspecção, mas não têm garantia de que sejam 100% precisas. As estatísticas são agregadas na memória antes de serem armazenadas nas tabelas do Cloud Spanner. Durante um upgrade ou outras atividades de manutenção, os servidores do Cloud Spanner podem ser reiniciados, afetando a precisão dos números.

Resolver problemas de contenções do banco de dados usando estatísticas de transação

Use o código SQL ou o painel de insights da transação para visualizar as transações no seu banco de dados que podem causar altas latências devido a contenções de bloqueio.

Os tópicos a seguir mostram como investigar essas transações usando código SQL.

Selecione um período para a investigação

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

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

Você pode usar as tags de transação para identificar a origem da transação e correlacionar as tabelas de estatísticas de transação e de estatísticas de bloqueio para uma solução de problemas eficiente para a contenção de bloqueios. Leia mais sobre como resolver problemas com tags de transação.

Reunir 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.

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,
  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 commit_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 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. Também podemos ver um alto número de novas tentativas de confirmação, o que indica que as confirmações canceladas foram repetidas. Na próxima etapa, investigaremos mais a causa do problema.

Identifique as colunas envolvidas em uma transação com latência alta

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_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 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.

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_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 commit_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.248 0.013 103151 30220 28483 0 91
2020-05-17 17:20:00-07:00 0.310 0.012 130078 45655 41966 0 91
2020-05-17 17:30:00-07:00 0.294 0.012 160064 64930 59933 0 91
2020-05-17 17:40:00-07:00 0.315 0.013 209614 104949 96770 0 91
2020-05-17 17:50:00-07:00 0.322 0.012 215682 100408 95867 0 90
2020-05-17 18:00:00-07:00 0.310 0.012 230932 106728 99462 0 91
2020-05-17 18:10:00-07:00 0.309 0.012 259645 131049 125889 0 91
2020-05-17 18:20:00-07:00 0.315 0.013 272171 137910 129411 0 90
2020-05-17 18:30:00-07:00 0,292 0.013 258944 121475 115844 0 91
2020-05-17 18:40:00-07:00 0,350 0.013 278802 142205 134229 0 91
2020-05-17 18:50:00-07:00 0,302 0.013 256259 115626 109756 0 91
2020-05-17 19:00:00-07:00 0.315 0.014 250560 110662 100322 0 91
2020-05-17 19:10:00-07:00 0.271 0.014 238384 99025 90187 0 91
2020-05-17 19:20:00-07:00 0.273 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

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, commit_abort_count e commit_retry_count 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.

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.

Identificar as transações que não foram repetidas corretamente

A consulta a seguir retorna as transações amostradas nos últimos dez minutos que têm uma alta contagem de cancelamento de confirmação, mas sem novas tentativas.

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_commit_attempt_count total_commit_abort_count total_commit_retry_count
1557557373282541312 3367894 44232 0
5776062322886969344 13566 14 0

Vemos que a transação com fprint 1557557373282541312 foi cancelada 44232 vezes, mas nunca foi repetida. Isso parece suspeito, porque a contagem de cancelamentos é alta e é improvável que cada cancelamento tenha sido causado por um erro que não pode ser recuperado. Por outro lado, para a transação com fprint 5776062322886969344, é menos suspeita, porque a contagem total de cancelamentos não é tão alta.

A consulta a seguir retorna mais detalhes sobre a transação com fprint 1557557373282541312,incluindo read_columns, write_constructive_columns e write_delete_tables. Essas informações ajudam a identificar a transação no código do cliente, em que a lógica de repetição pode ser analisada para esse cenário.

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 commit_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

A transação envolve uma leitura na coluna oculta Singers._exists para verificar a existência de uma linha. A transação também grava nas colunas Singers.FirstName e Singer.LastName. Essas informações podem ajudar a determinar se o mecanismo de repetição de transação implementado na sua biblioteca de cliente personalizada está funcionando conforme o esperado.

A seguir