Consulta de execução longa na réplica somente leitura que leva momentos no primário

Eu tenho uma configuração AG de 4 nós da seguinte maneira:

Configuração de hardware da VM de todos os nós:

• Microsoft SQL Server 2017 Enterprise Edition (RTM-CU14) (KB4484710)
• 16 vCPUs
• 356 GB de RAM (longa história desta ...)
• grau máximo de paralelismo: 1 (conforme exigido pelo fornecedor do aplicativo)
• limiar de custo para paralelismo: 50
• memória máxima do servidor (MB): 338944 (331 GB)

Configuração AG:

• Nó 1: Confirmação primária ou síncrona Secundária não legível, configurada para failover automático
• Nó 2: Confirmação primária ou síncrona Secundária não legível, configurada para failover automático
• Nó 3: Conjunto secundário legível com confirmação assíncrona, configurado para failover manual
• Nó 4: Conjunto secundário legível com confirmação assíncrona, configurado para failover manual

A consulta em questão:

Não há nada de louco nessa consulta, ela fornece um resumo dos itens de trabalho pendentes em várias filas no aplicativo. Você pode ver o código em um dos links do plano de execução abaixo.

Comportamento de execução no nó primário:

Quando executado no nó Primário, o tempo de execução geralmente fica em torno da marca de 1 segundo. Aqui está o plano de execução , e abaixo estão as estatísticas capturadas do STATISTICS IO e STATISTICS TIME do nó primário:

(347 rows affected)
Table 'Worktable'. Scan count 647, logical reads 2491, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'workitemlc'. Scan count 300, logical reads 7125, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Workfile'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulertask'. Scan count 1, logical reads 29, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'wfschedulertask'. Scan count 1, logical reads 9, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerservice'. Scan count 1, logical reads 12, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerworkerpool'. Scan count 1, logical reads 3, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'itemlc'. Scan count 1, logical reads 26372, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

(1 row affected)

 SQL Server Execution Times:
   CPU time = 500 ms,  elapsed time = 656 ms.
SQL Server parse and compile time: 
   CPU time = 0 ms, elapsed time = 0 ms.

Comportamento de execução no nó secundário somente leitura:

Ao executar no Nó Secundário Somente Leitura (ou seja, Nó 3 ou Nó 4), essa consulta usa o mesmo plano de execução (este é um link de plano diferente) e aproximadamente as mesmas estatísticas de execução são mostradas (por exemplo, pode haver mais algumas páginas varreduras, pois esses resultados estão sempre mudando), mas, com exceção do tempo de CPU, eles parecem muito semelhantes. Aqui estão as estatísticas capturadas do STATISTICS IO e STATISTICS TIME do nó secundário somente leitura:

(347 rows affected)
Table 'Worktable'. Scan count 647, logical reads 2491, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'workitemlc'. Scan count 300, logical reads 7125, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Workfile'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulertask'. Scan count 1, logical reads 29, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'wfschedulertask'. Scan count 1, logical reads 9, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerservice'. Scan count 1, logical reads 12, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'schedulerworkerpool'. Scan count 1, logical reads 3, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'itemlc'. Scan count 1, logical reads 26372, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

(1 row affected)

 SQL Server Execution Times:
   CPU time = 55719 ms,  elapsed time = 56335 ms.
SQL Server parse and compile time: 
   CPU time = 0 ms, elapsed time = 0 ms.

Outros detalhes:

Eu também tenho que correr tanto sp_WhoIsActivee de Paul RandalWaitingTasks.sql script no secundário, enquanto esta consulta está em execução, mas não estou a ver qualquer aguarda ocorrendo o que tão sempre, o que é francamente frustrante:

Isso também não parece ser um caso de latência de AG, pois o status de sincronização é realmente muito bom:

--https://sqlperformance.com/2015/08/monitoring/availability-group-replica-sync

SELECT 
       ar.replica_server_name, 
       adc.database_name, 
       ag.name AS ag_name, 
       drs.is_local, 
       drs.synchronization_state_desc, 
       drs.synchronization_health_desc, 
       --drs.last_hardened_lsn, 
       --drs.last_hardened_time, 
       drs.last_redone_time, 
       drs.redo_queue_size, 
       drs.redo_rate, 
       (drs.redo_queue_size / drs.redo_rate) / 60.0 AS est_redo_completion_time_min,
       drs.last_commit_lsn, 
       drs.last_commit_time
FROM sys.dm_hadr_database_replica_states AS drs
INNER JOIN sys.availability_databases_cluster AS adc 
       ON drs.group_id = adc.group_id AND 
       drs.group_database_id = adc.group_database_id
INNER JOIN sys.availability_groups AS ag
       ON ag.group_id = drs.group_id
INNER JOIN sys.availability_replicas AS ar 
       ON drs.group_id = ar.group_id AND 
       drs.replica_id = ar.replica_id
ORDER BY 
       ag.name, 
       ar.replica_server_name, 
       adc.database_name;

Essa consulta parece ser o pior infrator. Outras consultas que também levam segundos de segundos no nó principal podem levar de 1 a 5 segundos no nó secundário e, embora o comportamento não seja tão grave, parece estar causando problemas.

Por fim, também examinei os servidores e verifiquei processos externos, como verificações de A / V, trabalhos externos que geram E / S inesperadas etc., e saí de mãos vazias. Eu não acho que isso esteja sendo causado por algo fora do processo do SQL Server.

A questão:

É só meio-dia em que estou e já faz um longo dia, então suspeito que estou perdendo algo óbvio aqui. Ou isso, ou temos algo mal configurado, o que é possível, pois tivemos várias chamadas para o fornecedor e a MS relacionadas a esse ambiente.

Durante toda a minha investigação, não consigo encontrar o que está causando essa diferença de desempenho. Eu esperaria ver algum tipo de espera ocorrendo nos nós secundários, mas nada. Como posso solucionar mais isso para identificar a causa raiz? Alguém já viu esse comportamento antes e encontrou uma maneira de resolvê-lo?

ATUALIZAÇÃO # 1 Depois de trocar os estados do terceiro nó (uma das réplicas somente leitura) para não legíveis e depois voltar a legíveis como teste, essa réplica ainda está sendo mantida por uma transação aberta, com qualquer consulta de cliente exibindo o HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONINGesperar.

A execução de um DBCC OPENTRANcomando produz os seguintes resultados:

Oldest active transaction:
    SPID (server process ID): 420s
    UID (user ID) : -1
    Name          : QDS nested transaction
    LSN           : (941189:33148:8)
    Start time    : May  7 2019 12:54:06:753PM
    SID           : 0x0
DBCC execution completed. If DBCC printed error messages, contact your system administrator.

Ao procurar esse SPID sp_who2, ele é mostrado como um BACKGROUNDprocesso QUERY STORE BACKlistado como o comando.

Enquanto nós são capazes de tirar backups tlog, eu suspeito que estamos executando em funcionalidade semelhante de este erro seja resolvido , então estou pensando em abrir um ticket com o MS sobre esta questão em particular hoje.

Dependendo do resultado desse ticket, tentarei capturar um rastreamento de pilha de chamadas de acordo com a sugestão de Joe e ver para onde vamos.

Atualização final (problema resolvido automaticamente)

Depois de eclipsar a marca de 52 horas da transação do Query Store sendo aberta (como identificado acima), o AG decidiu fazer failover automaticamente. Antes disso, eu puxei algumas métricas adicionais. Por esse link , fornecido por Sean, o banco de dados em questão tinha um repositório de versões muito grande dedicado a esse banco de dados, especificamente em um ponto em que gravei 1651360 páginas no reserved_page_countcampo e 13210880 para o reserved_space_kbvalor.

De acordo com os ERRORLOGs, o failover ocorreu após um dilúvio de 5 minutos de falhas de proteção de transações relacionadas a QDS base transactione QDS nested transactiontransações.

O failover causou uma interrupção de cerca de 10 minutos no meu caso. O banco de dados tem ~ 6 TB de tamanho e é muito ativo, o que foi realmente muito bom na minha opinião. Enquanto o novo nó principal estava online durante esse período, nenhuma consulta do cliente pôde ser concluída, pois todos aguardavam o QDS_LOADDBtipo de espera.

Após o failover, os números de armazenamento de versão foram reduzidos para 176 reserved_page_counte 1408 para reserved_space_kb. As consultas contra as réplicas secundárias somente leitura também começaram a ser executadas tão rapidamente quanto se fossem executadas a partir do primário, portanto, parece que o comportamento desapareceu completamente, como resultado do failover.

Essa resposta é uma adição à resposta de Joe, já que não posso ter 100% de certeza de que é a loja de versões. No entanto, existem evidências suficientes até agora para sugerir que isso seja parte do problema.

Quando uma réplica secundária é marcada como legível, é necessário primeiro obter um bom estado estacionário para obter informações sobre versão, para que haja um ponto de partida conhecido e bom para todas as operações de leitura no secundário. Quando isso está aguardando a transição e ainda existem transações abertas no primário, isso se manifesta como HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONINGtambém é um bom indicador de que o primário passa por uma grande quantidade de rotatividade de dados (ou pelo menos alguém tem uma transação aberta muito longa que também não é bom). Quanto mais tempo as transações estiverem abertas e mais dados forem alterados, mais versões ocorrerão.

As réplicas secundárias atingem o status legível usando o isolamento de instantâneo sob as capas da sessão, mesmo que, se você verificar as informações da sessão, elas aparecerão na leitura padrão confirmada. Como o isolamento de snapshots é otimista e usa o armazenamento de versão, todas as alterações precisam ser versionadas. Isso é exacerbado quando há muitas consultas em execução (e potencialmente demoradas) no secundário, enquanto a rotatividade de dados é alta no primário. Geralmente, isso se manifesta apenas em algumas tabelas para um sistema OLTP, mas é completamente dependente de aplicativo e carga de trabalho.

O próprio armazenamento de versão é medido em gerações e, quando uma consulta é executada, exigindo o uso do armazenamento de versão, o ponteiro do registro de versão é usado para apontar para a cadeia TempDB dessa linha. Eu digo cadeia, porque é uma lista de versões para essa linha e a cadeia inteira deve ser percorrida sequencialmente para encontrar a versão correta com base no carimbo de data / hora inicial da transação, para que os resultados estejam alinhados com os dados naquele momento.

Se o armazenamento de versão tiver muitas gerações para essas linhas devido a transações demoradas nas réplicas primária e secundária, isso causará tempos mais longos do que a média para que as consultas sejam executadas e geralmente na forma de CPU mais alta, enquanto todos os outros itens permanecerão exatamente iguais. - como plano de execução, estatísticas, linhas retornadas, etc. A caminhada da cadeia é quase uma operação puramente da CPU; portanto, quando as cadeias se tornam muito longas e a quantidade de linhas retornadas é muito alta, você recebe um (não linear, mas pode estar próximo) aumentar o tempo para a consulta.

A única coisa que pode ser feita é limitar a duração das transações no primário e no secundário para garantir que o armazenamento de versão não esteja se tornando muito grande no TempDB e tenha muitas gerações. As tentativas de limpar o armazenamento de versões acontecem aproximadamente uma vez por minuto, no entanto, a limpeza exige que todas as versões da mesma geração não sejam mais necessárias antes que possam ser removidas e que todas as versões futuras não possam ser limpas até que a versão mais antiga não seja mais necessária. Assim, uma consulta de longa execução pode causar a incapacidade de efetivamente limpar muitas gerações não utilizadas.

Alternar a réplica para dentro e para fora do modo legível também limpará o armazenamento de versões, pois não será mais legível.

Há outros itens que também podem estar em jogo, mas isso parece o mais plausível, dados os dados atuais e a maneira como a réplica estava reagindo.

DMVs de versão do TempDB (não confunda com a versão do ADR).

Isenção de responsabilidade: não sei nada sobre grupos de disponibilidade, mas sei um pouco sobre como solucionar problemas de consultas que parecem usar mais CPU do que deveriam.

Você tem um problema de CPU porque está usando muito dele. Uma coisa importante a dizer sobre as esperas é que quase todas elas não estão ocupadas com a CPU. Quando um trabalhador entra em um estado de espera, ele produz e não está mais sendo executado no planejador no SQLOS. Portanto, se você tiver uma consulta MAXDOP 1 com as seguintes estatísticas de execução:

Tempo de CPU = 55719 ms, tempo decorrido = 56335 ms.

Você atinge quase 99% de utilização da CPU para a consulta. Por que deveria haver estatísticas de espera significativas para essa consulta? Você pode ver alguns se tiver algumas das esperas ocupadas da CPU, como esperas externas ou preventivas, mas isso também não é garantido. A conclusão é que as estatísticas de espera podem não ser tão úteis aqui.

Há algumas coisas para verificar em ordem aproximada (a ordem depende do que você sabe sobre o meio ambiente):

• O servidor secundário possui algum monitoramento caro, como eventos estendidos, rastreios ou criação de perfil?
• O hardware do servidor secundário corresponde aproximadamente ao primário?
• Há algum problema de configuração ou software com o servidor secundário?
• Alguma espera ou trava significativa? Pode não ser aplicável à sua consulta, mas ainda pode fornecer pistas.
• Algum spinlocks significativo?
• Existem outras DMVs ou coisas que você pode verificar no SQL Server que possam fornecer pistas? Você mencionou que os Grupos de Disponibilidade provavelmente são uma parte essencial do problema.
• O que o rastreamento ETW diz a você?
• Que tipo de acordos de suporte você possui?

A maioria das opções acima é bem abordada em várias postagens e documentação do blog, mas vou expandir o rastreamento ETW. Se você quiser saber por que o SQL Server está usando tanta CPU para uma consulta específica e você tiver acesso ao host, sempre poderá fazer o rastreamento ETW para visualizar as pilhas de chamadas e para ver quanto de CPU estão usando várias pilhas de chamadas. Em outras palavras, o sistema operacional host terá prazer em dizer para que CPU está sendo usada, se você souber perguntar. Os métodos comuns de rastreamento de ETW incluem o Windows Performance Recorder e o PerfView .

Compreender esses resultados requer profundo conhecimento interno e é fácil chegar a uma conclusão errada. Em muitos casos, é melhor coletar os dados brutos e solicitar aos especialistas que os analisem. Ao executar um rastreamento, você deseja que o mínimo de atividade possível ocorra no SQL Server. Abaixo estão algumas respostas postadas aqui que usam o rastreamento ETW para tirar conclusões sobre o SQL Server:

• Como diagnosticar o try_parse como muito lento?
• Por que leva até 30 segundos para criar um simples grupo de linhas CCI?
• As leituras lógicas na RAM aparecem nas estatísticas de espera ou onde?
• Por que o NOLOCK faz uma digitalização com atribuição de variável mais lenta?
• Qual é o algoritmo por trás do operador EXCEPT?
• Comando ALTER TABLE sem valor padrão demorando para sempre?
• Dados implicitamente ordenados como se fosse um índice em cluster; Posso tirar proveito disso?

Eu suspeito que, no seu caso, se você puder coletar pilhas de chamadas enquanto a consulta de 45 segundos for executada, obterá algumas dicas muito úteis sobre a natureza do problema.

Como o problema foi resolvido, resta especular sua causa (rimando não intencional). Com base na postagem de Sean e no fato de que uma transação aberta do Query Store parece ter sido a causa raiz do tamanho aumentado do meu armazenamento de versão (por exemplo, a causa das HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONINGesperas), só posso assumir que o Query Store teve parte no comportamento que foi apresentado. Esse banco de dados é maior (~ 6 TB), bastante ativo e a maioria bruta das consultas que o atingem é gerada no cliente e não é parametrizada (ou seja, consultas ad-hoc), portanto, não acredito que o Query Store se presta a fornecer muito uso neste cenário. Por isso, desativaremos o Query Store nesse ambiente durante uma janela de manutenção futura, após a qual suspeito que não veremos esse comportamento novamente.

Abrimos um ticket com a Microsoft, mas o tempo não estava a nosso favor, pois o problema foi resolvido antes que pudéssemos fazer uma análise detalhada por meio de um rastreamento PSSDIAG ou algo semelhante. Espero que eles possam fazer alguns testes localizados e replicar esse problema, caso este seja um bug que encontramos. Se forem identificadas outras atualizações em uma resolução mais permanente, também atualizaremos esta resposta.