Requête à exécution longue sur un réplica en lecture seule qui prend des instants sur le serveur principal

J'ai une configuration AG à 4 nœuds comme suit:

Configuration matérielle VM de tous les nœuds:

• Microsoft SQL Server 2017 Enterprise Edition (RTM-CU14) (KB4484710)
• 16 processeurs virtuels
• 356 Go de RAM (longue histoire à celle-ci ...)
• degré maximal de parallélisme: 1 (tel que requis par le fournisseur de l'application)
• seuil de coût pour le parallélisme: 50
• mémoire serveur maximale (Mo): 338944 (331 Go)

Configuration AG:

• Noeud 1: validation primaire ou synchrone secondaire non lisible, configuré pour le basculement automatique
• Noeud 2: validation primaire ou synchrone secondaire non lisible, configuré pour le basculement automatique
• Noeud 3: ensemble secondaire lisible avec validation asynchrone, configuré pour le basculement manuel
• Noeud 4: ensemble secondaire lisible avec validation asynchrone, configuré pour le basculement manuel

La requête en question:

Il n'y a rien de terriblement fou dans cette requête, elle fournit un résumé des éléments de travail en suspens dans diverses files d'attente au sein de l'application. Vous pouvez voir le code à partir de l'un des liens du plan d'exécution ci-dessous.

Comportement d'exécution sur le nœud principal:

Lorsqu'il est exécuté sur le nœud principal, le temps d'exécution se situe généralement autour de la marque 1 seconde. Voici le plan d'exécution , et ci-dessous sont les statistiques capturées à partir de STATISTICS IO et STATISTICS TIME à partir du nœud principal:

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

Comportement d'exécution sur le nœud secondaire en lecture seule:

Lors de l'exécution sur un nœud secondaire en lecture seule (c.-à-d. Nœud 3 ou nœud 4), cette requête utilise le même plan d'exécution (il s'agit d'un lien de plan différent) et à peu près les mêmes statistiques d'exécution sont affichées (par exemple, il peut y avoir quelques pages supplémentaires scans car ces résultats changent toujours), mais à l'exception du temps CPU, ils se ressemblent beaucoup. Voici les statistiques capturées à partir de STATISTICS IO et STATISTICS TIME à partir du nœud secondaire en lecture seule:

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

Autres détails:

J'ai également exécuté les deux sp_WhoIsActiveet leWaitingTasks.sql script de Paul Randal sur le secondaire pendant l'exécution de cette requête, mais je ne vois aucune attente se produire quoi que ce soit, ce qui est franchement frustrant:

Cela ne semble pas non plus être un cas de latence AG car l'état de synchronisation est en fait assez bon:

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

Cette requête semble être le pire délinquant. Les autres requêtes qui prennent également moins d'une seconde sur le nœud principal peuvent prendre de 1 à 5 secondes sur le nœud secondaire, et bien que le comportement ne soit pas aussi grave, il semble causer des problèmes.

Enfin, j'ai également regardé les serveurs et vérifié les processus externes tels que les analyses A / V, les travaux externes générant des E / S inattendues, etc. et je suis arrivé les mains vides. Je ne pense pas que cela soit causé par quoi que ce soit en dehors du processus SQL Server.

La question:

Il est seulement midi où je suis et la journée a déjà été longue, donc je soupçonne que je manque quelque chose d'évident ici. Soit cela, soit nous avons quelque chose de mal configuré, ce qui est possible car nous avons eu un certain nombre d'appels au fournisseur et à la MS liés à cet environnement.

Pour toute mon enquête, je n'arrive pas à trouver ce qui cause cette différence de performances. Je m'attendrais à voir une sorte d'attente se produire sur les nœuds secondaires, mais rien. Comment puis-je résoudre davantage ce problème pour identifier la cause première? Quelqu'un a-t-il déjà vu ce comportement et trouvé un moyen de le résoudre?

MISE À JOUR # 1 Après avoir échangé les états du troisième noeud (l'une des réplicas en lecture seule) sur non lisible, puis de nouveau sur lisible en tant que test, cette réplique est toujours bloquée par une transaction ouverte, toutes les requêtes des clients affichant le HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONINGattendre.

L'exécution d'une DBCC OPENTRANcommande donne les résultats suivants:

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.

Lorsque vous recherchez ce SPID dans sp_who2, il l'affiche comme un BACKGROUNDprocessus QUERY STORE BACKrépertorié comme commande.

Alors que nous sommes en mesure de prendre des sauvegardes tlogs, je pense que nous courons dans les mêmes fonctionnalités de ce bug résolu , donc je prévois d' ouvrir un ticket avec MS à propos de cette question aujourd'hui.

Selon le résultat de ce ticket, j'essaierai de capturer une trace de pile d'appels selon la suggestion de Joe et de voir où nous allons.

Mise à jour finale (problème auto-résolu)

Après avoir éclipsé la marque de 52 heures de l'ouverture de la transaction Query Store (comme identifié ci-dessus), l'AG a décidé de basculer automatiquement. Avant cela, j'ai extrait quelques mesures supplémentaires. Par ce lien , fourni par Sean, la base de données en question avait un très grand magasin de versions dédié à cette base de données, spécifiquement à un moment donné, j'avais enregistré 1651360 pages sur le reserved_page_countterrain et 13210880 pour la reserved_space_kbvaleur.

Selon les ERRORLOG, le basculement s'est produit après un déluge de 5 minutes d'échecs de durcissement des transactions liés aux transactions QDS base transactionet aux QDS nested transactiontransactions.

Le basculement a provoqué une panne d'environ 10 minutes dans mon cas. La base de données a une taille de ~ 6 To et est très active, donc c'était en fait assez bon à mon avis. Pendant que le nouveau nœud principal était en ligne pendant cette période, aucune requête client ne pouvait se terminer car ils attendaient tous sur le QDS_LOADDBtype d'attente.

Après le basculement, le nombre de magasins de versions a été réduit à 176 pour reserved_page_countet 1408 pour reserved_space_kb. Les requêtes sur les réplicas en lecture seule secondaires ont également commencé à s'exécuter aussi rapidement que si elles étaient exécutées à partir du serveur principal, il semble donc que le comportement ait complètement disparu à la suite du basculement.

Cette réponse s'ajoute à la réponse de Joe car je ne peux pas être sûr à 100% qu'il s'agit du magasin de versions, mais il y a suffisamment de preuves jusqu'à présent pour impliquer que cela fait partie du problème.

Lorsqu'un réplica secondaire est marqué comme lisible, un bon état stable pour les informations de version doit d'abord être atteint afin qu'il existe un bon point de départ connu pour toutes les opérations de lecture sur le secondaire. Lorsque cela attend la transition et qu'il y a encore des transactions ouvertes sur le primaire, cela se manifestera HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONINGet est également un bon indicateur que le primaire passe par un certain nombre de transactions de données (ou au moins quelqu'un a une transaction ouverte très longue qui n'est pas bon non plus). Plus les transactions sont ouvertes et plus il y a de changements de données, plus le versioning se produira.

Les réplicas secondaires atteignent un état lisible en utilisant l'isolement de cliché sous les couvertures de la session, même si si vous vérifiez les informations de votre session, vous verrez qu'elles apparaissent à la lecture par défaut validée. Étant donné que l'isolement des instantanés est optimiste et utilise le magasin de versions, toutes les modifications devront être versionnées. Ceci est exacerbé lorsqu'il y a de nombreuses requêtes en cours d'exécution (et potentiellement longues) sur le secondaire alors que le taux de désabonnement des données est élevé sur le primaire. Généralement, cela ne se manifeste que dans quelques tableaux pour un système OLTP, mais il dépend entièrement de l'application et de la charge de travail.

Le magasin de versions lui-même est mesuré en générations et lorsqu'une requête est exécutée qui nécessite l'utilisation du magasin de versions, le pointeur d'enregistrement de version est utilisé pour pointer vers la chaîne TempDB de cette ligne. Je dis chaîne, car c'est une liste de versions pour cette ligne et la chaîne entière doit être parcourue séquentiellement pour trouver la version appropriée en fonction de l'horodatage de début de la transaction afin que les résultats soient en ligne avec les données à ce moment donné.

Si le magasin de versions a plusieurs générations pour ces lignes en raison de transactions de longue durée sur les réplicas principal et secondaire, cela entraînera des délais d'exécution des requêtes plus longs que la moyenne et généralement sous la forme d'un processeur plus élevé, tandis que tous les autres éléments resteront exactement les mêmes. - tels que le plan d'exécution, les statistiques, les lignes retournées, etc. La marche de la chaîne est presque une opération purement CPU, donc lorsque les chaînes deviennent très longues et que le nombre de lignes retournées est très élevé, vous obtenez un (non linéaire, mais peut être proche) augmentation du temps pour la requête.

La seule chose qui peut être faite est de limiter la longueur des transactions sur le primaire et le secondaire pour s'assurer que le magasin de versions ne devient pas trop volumineux dans TempDB tout en ayant plusieurs générations. Les tentatives de nettoyage du magasin de versions se produisent environ une fois par minute, mais le nettoyage nécessite que toutes les versions de la même génération ne soient plus nécessaires avant de pouvoir être supprimées et que toutes les versions futures ne puissent pas être nettoyées tant que la version la plus ancienne n'est plus nécessaire. Ainsi, une requête de longue durée peut entraîner l'incapacité de nettoyer efficacement de nombreuses générations inutilisées.

Le basculement de la réplique en mode lisible va également effacer le magasin de versions car il n'est plus lisible.

Il existe d'autres éléments qui pourraient également être en jeu, mais cela semble le plus plausible compte tenu des données actuelles et de la réaction de la réplique.

TempDB Versioning DMVs (à ne pas confondre avec ADR versioning).

Avertissement: je ne sais rien des groupes de disponibilité, mais je connais un peu le dépannage des requêtes qui semblent utiliser plus de CPU qu'elles ne le devraient.

Vous avez un problème de processeur dans la mesure où vous en utilisez trop. Une chose importante à dire sur les attentes est que presque toutes ne sont pas occupées par le processeur. Lorsqu'un travailleur entre dans un état d'attente, il a cédé et ne s'exécute plus sur le planificateur dans SQLOS. Donc, si vous avez une requête MAXDOP 1 avec les statistiques d'exécution suivantes:

Temps CPU = 55719 ms, temps écoulé = 56335 ms.

Vous avez atteint près de 99% d'utilisation du processeur pour la requête. Pourquoi devrait-il y avoir des statistiques d'attente significatives pour cette requête? Vous pouvez en voir si vous avez certaines des attentes d'occupation du processeur telles que les attentes externes ou préemptives, mais ce n'est pas garanti non plus. L'essentiel est que les statistiques d'attente peuvent ne pas être très utiles ici.

Il y a certaines choses à vérifier dans un ordre approximatif (l'ordre dépend de ce que vous savez sur l'environnement):

• Le serveur secondaire a-t-il une surveillance coûteuse en cours, comme des événements étendus, des traces ou un profilage?
• Le matériel du serveur secondaire correspond-il à peu près au serveur principal?
• Y a-t-il des problèmes de configuration ou de logiciel avec le serveur secondaire?
• Des attentes ou des verrous importants? Peut ne pas être applicable à votre requête, mais peut néanmoins fournir des indices.
• Des verrous importants?
• Y a-t-il d'autres DMV ou choses que vous pouvez vérifier dans SQL Server qui pourraient donner des indices? Vous avez mentionné que les groupes de disponibilité sont probablement un élément clé du problème.
• Que vous dit le traçage ETW?
• Quel type d'accords de support avez-vous?

La plupart de ce qui précède est bien couvert divers articles de blog et documentation, mais je développerai le traçage ETW. Si vous voulez savoir pourquoi SQL Server utilise autant de CPU pour une requête particulière et que vous avez accès à l'hôte, vous pouvez toujours effectuer le suivi ETW pour afficher les piles d'appels et voir combien de CPU font différentes piles d'appels. En d'autres termes, le système d'exploitation hôte est heureux de vous dire à quoi sert le processeur si vous savez comment le demander. Les méthodes courantes de suivi ETW incluent l' enregistreur de performances Windows et PerfView .

Comprendre ces résultats nécessite une connaissance approfondie des internes et il est facile d'arriver à une conclusion erronée. Dans de nombreux cas, il est préférable de collecter les données brutes et de demander à des experts de les consulter. Lorsque vous effectuez une trace, vous souhaitez que le moins d'activité possible se poursuive dans SQL Server. Voici quelques réponses publiées ici qui utilisent le suivi ETW pour tirer des conclusions sur SQL Server:

• Comment diagnostiquer que try_parse est très lent?
• Pourquoi la création d'un groupe de lignes CCI simple peut prendre jusqu'à 30 secondes?
• Les lectures logiques dans la RAM apparaissent-elles dans les statistiques d'attente ou où?
• Pourquoi NOLOCK ralentit-il une analyse avec affectation variable?
• Quel est l'algorithme derrière l'opérateur EXCEPT?
• Commande ALTER TABLE sans valeur par défaut prenant pour toujours?
• Données implicitement ordonnées comme s'il s'agissait d'un index clusterisé; Puis-je en profiter?

Je soupçonne que dans votre cas, si vous êtes en mesure de collecter des piles d'appels pendant l'exécution de la requête de 45 secondes, vous obtiendrez des indices très utiles sur la nature du problème.

Comme le problème s'est résolu de lui-même, je me dois de spéculer sur sa cause (rimes non intentionnelles). Sur la base de la publication de Sean et du fait qu'une transaction de magasin de requêtes ouverte semble avoir été la cause principale de l'augmentation de la taille du magasin de versions (par exemple, la cause des HADR_DATABASE_WAIT_FOR_TRANSITION_TO_VERSIONINGattentes), je ne peux que supposer que le magasin de requêtes avait une part dans le comportement qui était présenté. Cette base de données est plus grande (~ 6 To), assez active, et la majorité des requêtes qui la frappent sont générées par le client et non paramétrées (c'est-à-dire des requêtes ad hoc), donc je ne pense pas que le magasin de requêtes se prête à fournir beaucoup d'utilisation dans ce scénario. Pour cette raison, nous désactiverons le magasin de requêtes dans cet environnement lors d'une future fenêtre de maintenance, après quoi je pense que nous ne verrons plus ce comportement.

Nous avons ouvert un ticket avec Microsoft, mais le timing n'était pas en notre faveur car le problème a été résolu avant que nous puissions effectuer une analyse détaillée via une trace PSSDIAG ou similaire. J'espère qu'ils seront en mesure de faire des tests localisés et de reproduire ce problème au cas où il s'agirait d'un bogue que nous avons rencontré. Si d'autres mises à jour sur une résolution plus permanente sont identifiées, je serai sûr de mettre à jour cette réponse également.