Consulta de longa execução na réplica somente leitura que demora alguns instantes no primário

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

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

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

Configuração AG:

• Nó 1: Secundário não legível de confirmação primária ou síncrona, configurado para failover automático
• Nó 2: Secundário não legível de confirmação primária ou síncrona, configurado 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 muito louco nessa consulta, ela fornece um resumo dos itens de trabalho pendentes em várias filas dentro do 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 em torno da marca de 1 segundo. Aqui está o plano de execução e abaixo estão as estatísticas capturadas de 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 em um nó secundário somente leitura (ou seja, nó 3 ou nó 4), esta 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 verificações, pois esses resultados estão sempre mudando), mas com exceção do tempo de CPU, eles são muito semelhantes. Aqui estão as estatísticas capturadas de 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:

Também executei o script sp_WhoIsActivede Paul RandalWaitingTasks.sql no secundário enquanto essa consulta está sendo executada, mas não vejo nenhuma espera ocorrendo, 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;

Esta consulta parece ser o pior ofensor. Outras consultas que também levam menos de um segundo no nó primário 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 varreduras de A/V, trabalhos externos gerando E/S inesperadas, etc. e cheguei de mãos vazias. Não acho que isso esteja sendo causado por algo fora do processo do SQL Server.

A questão:

É apenas meio-dia onde estou e já foi 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 MS relacionadas a esse ambiente.

Para toda a minha investigação, eu simplesmente não consigo encontrar o que está causando essa diferença no desempenho. Eu esperaria ver algum tipo de espera ocorrendo nos nós secundários, mas nada. Como posso solucionar ainda 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ível e depois de volta para legível como um teste, essa réplica ainda está sendo mantida por uma transação aberta, com todas as consultas do 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 pesquisar este SPID em sp_who2, ele o mostra como um BACKGROUNDprocesso QUERY STORE BACKlistado como o comando.

Embora possamos fazer backups do TLog, suspeito que estamos enfrentando uma funcionalidade semelhante a esse bug resolvido , então pretendo abrir um tíquete com a MS sobre esse problema específico 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 (conforme identificado acima), o AG decidiu fazer o failover automaticamente. Antes que isso acontecesse, eu puxei algumas métricas adicionais. Por este link , fornecido por Sean, o banco de dados em questão tinha um armazenamento de versão muito grande dedicado a este banco de dados, especificamente em um ponto eu havia registrado 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, então isso foi realmente muito bom na minha opinião. Enquanto o novo nó primário estava online durante esse período, nenhuma consulta de cliente pôde ser concluída, pois todos estavam aguardando 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 nas réplicas somente leitura secundárias 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.