Estatísticas de transação

O 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

Observação: o Spanner Studio (anteriormente chamado de Query no console do Google Cloud ) oferece suporte a operações SQL, DML e DDL em um único editor. Para mais informações, consulte Gerenciar seus dados usando o console do Google Cloud .

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 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) das transações. Se uma tag de transação estiver presente, FPRINT será o hash da tag. Caso contrário, é 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 para a qual o Spanner captura estatísticas durante o intervalo especificado.

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

• 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 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, com prefixo de 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 vezes que a transação é tentada, incluindo as tentativas que são abortadas antes de chamar "commit".
COMMIT_ATTEMPT_COUNT	INT64	Número total de tentativas de confirmação de transações. Ele 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 abortadas, incluindo aquelas que foram abortadas antes de chamar o método commit da transação.
COMMIT_RETRY_COUNT	INT64	Número total de tentativas que são novas tentativas de tentativas anteriores de confirmação. Uma transação do Spanner pode ser tentada várias vezes antes de ser confirmada devido a contenções de bloqueio ou eventos transitórios. Um alto número de novas tentativas em relação às tentativas de confirmação indica que pode haver problemas que precisam ser investigados. 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á existente, 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 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 entre o início da primeira operação transacional e a confirmação ou interrupção, para todas as tentativas de uma transação. Observação sobre a interface do PostgreSQL:os bancos de dados com dialeto do PostgreSQL não oferecem suporte a essa coluna. Se uma transação for abortada várias vezes e depois confirmada, a latência será 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: 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 da distribuição, use a função SPANNER_SYS.DISTRIBUTION_PERCENTILE(distribution, n FLOAT64), que retorna o percentil n estimado. Para um exemplo relacionado, consulte Encontrar a latência do percentil 99 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. Observação sobre a interface do PostgreSQL:os bancos de dados com dialeto do PostgreSQL não oferecem suporte a essa coluna. Essa coluna ajuda a visualizar a carga nas tabelas e fornece insights sobre a taxa em que uma transação é gravada em tabelas. Especifique a matriz da seguinte maneira: ARRAY<STRUCT<   TABLE STRING(MAX),   INSERT_OR_UPDATE_COUNT INT64,   INSERT_OR_UPDATE_BYTES INT64>>

¹ _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, o gcloud spanner ou o Google Cloud console.

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 para as 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 incluir transações que o Spanner não capturou nas tabelas SPANNER_SYS.TXN_STATS_TOP_*.

• 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ção
  • 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 que são abortadas antes de chamar "commit".
COMMIT_ATTEMPT_COUNT	INT64	Número total de tentativas de confirmação de transações. Ele 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 abortadas, incluindo aquelas que foram abortadas 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 de ser confirmada devido a contenções de bloqueio ou eventos transitórios. Um alto número de novas tentativas em relação às tentativas de confirmação indica que pode haver problemas que precisam ser investigados. 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á existente, 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 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 entre o início da primeira operação transacional e a confirmação ou interrupção de todas as tentativas de transação. Observação sobre a interface do PostgreSQL:os bancos de dados do dialeto PostgreSQL não oferecem suporte a essa coluna. Se uma transação for abortada várias vezes e confirmada, a latência será 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: 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 da distribuição, use a função SPANNER_SYS.DISTRIBUTION_PERCENTILE(distribution, n FLOAT64), que retorna o percentil n estimado. Confira um exemplo em Encontrar a latência do percentil 99º 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 que as linhas são afetadas e pelo número de bytes gravados. Observação sobre a interface do PostgreSQL:os bancos de dados com dialeto do PostgreSQL não oferecem suporte a essa coluna. 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 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, o gcloud spanner ou o 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 no 99º percentil para transações

A consulta a seguir retorna a latência do percentil 99 para transações executadas 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 média e a latência do percentil 99. A latência do 99º percentil ajuda a identificar possíveis transações atípicas 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 duração.

Retenção de dados

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

Observação: não é possível impedir que o Spanner colete estatísticas de transações. Para excluir os dados nessas tabelas, exclua o banco de dados associado às tabelas ou aguarde até que o Spanner remova os dados automaticamente. Não é possível estender o período de armazenamento para essas tabelas.

As estatísticas de transações no 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.

Entender transações e confirmações

Uma transação do Spanner pode ter que ser tentada várias vezes antes de 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 de repetição automática. 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 não recuperável, como 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 Spanner. Durante um upgrade ou outras atividades de manutenção, os servidores do Spanner podem ser reiniciados, afetando a precisão dos números.

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

É possível usar o código SQL ou o painel Insights de transações para conferir as transações no seu banco de dados que podem causar altas latências devido a conflitos 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 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.

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.

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.

Identificar 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 a performance 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 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

• Saiba mais sobre outras ferramentas de introspecção.
• Saiba mais sobre outras informações que o Spanner armazena para cada banco de dados nas tabelas de esquema de informações do banco de dados.
• Saiba mais sobre as práticas recomendadas de SQL para o Spanner.
• Saiba mais sobre como investigar a alta utilização da CPU.