Estatísticas de transação

O Spanner tem 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:

  • A 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 têm suporte 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: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 FPRINT (impressão digital) do transações. Se uma tag de transação estiver presente, FPRINT é o hash da tag. Caso contrário, é o hash calculada 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. para o qual o Spanner captura estatísticas durante o intervalo especificado.

  • Se o Spanner não conseguir armazenar as estatísticas de todas as transações executadas durante intervalo nessas tabelas, o sistema prioriza transações com o maior latência, tentativas de confirmação e bytes gravados durante o período intervalo.

  • Todas as colunas nas tabelas são anuláveis.

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 fluxo de alterações, se a transação envolve gravações em colunas e tabelas monitoradas por um fluxo de alterações, WRITE_CONSTRUCTIVE_COLUMNS conterá duas colunas: .data e ._exists 1, prefixado 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 O número total de vezes que ocorre uma tentativa de transação, incluindo de tentativas que são canceladas antes de chamar `commit`.
COMMIT_ATTEMPT_COUNT INT64 Número total de tentativas de confirmação de transação. Precisa corresponder ao número de chamadas para o método commit da transação.
COMMIT_ABORT_COUNT INT64 O número total de tentativas de transação 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 canceladas anteriormente de tentativas. Uma transação do Spanner pode ser tentada várias vezes antes da confirmação devido a contenções de bloqueio ou eventos temporários. Uma alta o número de novas tentativas em relação às tentativas de confirmação indica que pode haver que vale 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 uma pré-condição com falha erros, como UNIQUE violações de índice, 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 de Leituras e leituras do Spanner Gravações.
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 do horário de início da primeira operação transacional para o commit ou abortar horário, para todas as tentativas de uma transação.

Se uma transação for cancelada várias vezes e realiza a confirmação, a latência é medida para cada 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:
e 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 o percentil de latência desejado da distribuição, use a função SPANNER_SYS.DISTRIBUTION_PERCENTILE(distribution, n FLOAT64), que retorna o no percentil estimado. Para um exemplo relacionado, consulte Encontrar a latência do 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 pelo transação por tabela. Isso é indicado pelo número de vezes que as linhas são afetadas e o número de bytes gravados.

Essa coluna ajuda a visualizar a carga nas tabelas e fornece insights na taxa em que uma transação grava em tabelas.

Especifique a matriz da seguinte forma:
e 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 o bibliotecas de cliente, a gcloud spanner ou a 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 de quais 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 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: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 incluem transações que o Spanner não capturou SPANNER_SYS.TXN_STATS_TOP_* tabelas.

  • Algumas colunas nessas 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 O número total de vezes que as transações são tentadas, incluindo o de tentativas que são canceladas antes de chamar `commit`.
COMMIT_ATTEMPT_COUNT INT64 Número total de tentativas de confirmação de transação. Precisa corresponder ao número de chamadas para o método commit da transação.
COMMIT_ABORT_COUNT INT64 O número total de tentativas de transação canceladas, incluindo aquelas que são 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 tentada várias vezes antes da confirmação devido a contenções de bloqueio ou eventos temporários. Uma alta o número de novas tentativas em relação às tentativas de confirmação indica que pode haver que vale 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 uma pré-condição com falha erros, como UNIQUE violações de índice, 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 de Leituras e leituras do Spanner Gravações.
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 do horário de início da primeira operação transacional para o horário de confirmação ou cancelamento para todas as tentativas de transação.

Se uma transação cancelar várias vezes e, em seguida, realiza a confirmação, a latência é medida para cada tentativa até a confirmação final. Os valores são medidos em segundos.

A matriz contém um único elemento e tem o seguinte tipo:
e 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 o percentil de latência desejado da distribuição, use a função SPANNER_SYS.DISTRIBUTION_PERCENTILE(distribution, n FLOAT64), que retorna o no percentil estimado. Para conferir um exemplo, consulte Encontrar o 99o percentil latência 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 para todos transações por tabela. Isso é indicado pelo número vezes que as linhas são afetadas e o número de bytes gravados.

Essa coluna ajuda a visualizar a carga nas tabelas e fornece insights sobre a taxa de gravação das transações nas tabelas.

Especifique a matriz da seguinte forma:
e 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 o bibliotecas de cliente, a gcloud spanner ou a Console do Google Cloud.

Encontrar o número total de tentativas de confirmação para todas as transações

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 para transações

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

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 do 99o percentil. A latência do 99o percentil ajuda a identificar possíveis transações atípicas com latência alta.

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

Retenção de dados

No mínimo, o Spanner mantém os dados de cada tabela pelo período a seguir períodos:

  • 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 na investigação de 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

Uma transação do Spanner pode ter que ser testada várias vezes antes commits. 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 lidar solicitações que recebe.

Nesses cenários, um cliente precisa repetir a transação cancelada até que ele seja confirmado ou expire. Para usuários da interface oficial bibliotecas de cliente, cada biblioteca tem implementaram um mecanismo automático de nova tentativa. 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 permite novas tentativas como tempo limite da transação, problemas de permissão ou uma tabela/coluna inválida nome. Não é necessário repetir essas transações, e o Spanner biblioteca de cliente 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 armazenados nas tabelas do Spanner. Durante um upgrade ou outra de manutenção, os servidores do Spanner podem ser reiniciados, afetando e a precisão dos números.

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

Use o código SQL ou os Insights sobre transações para exibir as transações em seu banco de dados que podem causar altas latências de rede devido a contenções de bloqueio.

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

Selecione um período para investigar

Isso pode ser encontrado no aplicativo que usa 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.

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.

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

Identifique as transações em que não foram feitas novas tentativas 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