Recherche de magasin de requêtes sans fin

10

Je vais le dire dès le début que ma question / problème ressemble à ce précédent, mais comme je ne suis pas sûr si la cause ou l'information de départ est le même, j'ai décidé de poster ma question avec quelques détails.

Problème à résoudre:

  • à une heure étrange (vers la fin du jour ouvrable), une instance de production commence à se comporter de façon irrégulière:
    • CPU élevé pour l'instance (à partir d'une ligne de base d'environ 30%, il est passé à environ le double et continue de croître)
    • augmentation du nombre de transactions / s (bien que la charge de l'application n'ait vu aucun changement)
    • augmentation du nombre de sessions inactives
    • des événements de blocage étranges entre des sessions qui n'ont jamais affiché ce comportement (même la lecture de sessions non validées provoquait un blocage)
    • les premières attentes pour l'intervalle étaient le verrouillage de la page à la 1ère place, les verrous prenant la 2e place

Enquête initiale:

  • en utilisant sp_whoIsActive, nous avons vu qu'une requête exécutée par notre outil de surveillance décide de s'exécuter extrêmement lentement et de récupérer beaucoup de CPU, ce qui n'était pas arrivé auparavant;
  • son niveau d'isolement a été lu sans engagement;
  • nous avons regardé le plan, nous avons vu des nombres farfelus: StatementEstRows = "3.86846e + 010" avec quelque 150 To de données estimées à renvoyer
  • nous soupçonnions qu'une fonctionnalité de surveillance des requêtes de l'outil de surveillance en était la cause, nous avons donc désactivé la fonctionnalité (nous avons également ouvert un ticket avec notre fournisseur pour vérifier s'il est au courant d'un problème)
  • depuis ce premier événement, cela s'est produit quelques fois de plus, à chaque fois que nous tuons la session, tout revient à la normale;
  • nous réalisons que la requête est extrêmement similaire à l' une des requêtes utilisées par MS dans BOL pour la surveillance du magasin de requêtes - Requêtes qui ont récemment régressé en termes de performances (en comparant différents points dans le temps)
  • nous exécutons la même requête manuellement et voyons le même comportement (CPU utilisé toujours croissant, attente de verrouillage croissante, verrous inattendus, etc.)

Requête coupable:

Select qt.query_sql_text, 
    q.query_id, 
    qt.query_text_id, 
    rs1.runtime_stats_id AS runtime_stats_id_1,
    interval_1 = DateAdd(minute, -(DateDiff(minute, getdate(), getutcdate())), rsi1.start_time), 
    p1.plan_id AS plan_1, 
    rs1.avg_duration AS avg_duration_1, 
    rs2.avg_duration AS avg_duration_2,
    p2.plan_id AS plan_2, 
    interval_2 = DateAdd(minute, -(DateDiff(minute, getdate(), getutcdate())), rsi2.start_time), 
    rs2.runtime_stats_id AS runtime_stats_id_2
From sys.query_store_query_text AS qt 
Inner Join sys.query_store_query AS q 
    ON qt.query_text_id = q.query_text_id 
Inner Join sys.query_store_plan AS p1 
    ON q.query_id = p1.query_id 
Inner Join sys.query_store_runtime_stats AS rs1 
    ON p1.plan_id = rs1.plan_id 
Inner Join sys.query_store_runtime_stats_interval AS rsi1 
    ON rsi1.runtime_stats_interval_id = rs1.runtime_stats_interval_id 
 Inner Join sys.query_store_plan AS p2 
    ON q.query_id = p2.query_id 
Inner Join sys.query_store_runtime_stats AS rs2 
    ON p2.plan_id = rs2.plan_id 
Inner Join sys.query_store_runtime_stats_interval AS rsi2 
    ON rsi2.runtime_stats_interval_id = rs2.runtime_stats_interval_id
Where rsi1.start_time > DATEADD(hour, -48, GETUTCDATE()) 
    AND rsi2.start_time > rsi1.start_time 
    AND p1.plan_id <> p2.plan_id
    AND rs2.avg_duration > rs1.avg_duration * 2
Order By q.query_id, rsi1.start_time, rsi2.start_time

Paramètres et informations:

  • SQL Server 2016 SP1 CU4 Enterprise sur un cluster Windows Server 2012R2
  • Query Store activé et configuré par défaut (aucun paramètre modifié)
  • base de données importée à partir d'une instance SQL 2005 (et toujours au niveau de compatibilité 100)

Observation empirique:

  • en raison de statistiques extrêmement loufoques, nous avons pris tous les objets * plan_persist ** utilisés dans le mauvais plan estimé (pas encore de plan réel, car la requête n'est jamais terminée) et vérifié les statistiques, certains des index utilisés dans le plan n'avaient pas de statistiques (DBCC SHOWSTATISTICS n'a rien retourné, sélectionnez dans sys.stats la fonction NULL stats_date () pour certains index

Solution rapide et sale:

  • créer manuellement des statistiques manquantes sur les objets système liés au magasin de requêtes ou
  • forcer la requête à s'exécuter en utilisant le nouveau CE (traceflag) - qui créera / mettra également à jour les statistiques nécessaires ou
  • changer le niveau de compatibilité de la base de données à 130 (il utilisera donc par défaut le nouveau CE)

Donc, ma vraie question serait:

Pourquoi une requête sur le magasin de requêtes entraînerait-elle des problèmes de performances sur l'instance entière? Sommes-nous dans un territoire de bogues avec Query Store?

PS: je vais télécharger quelques fichiers (écrans d'impression, statistiques IO et plans) dans un court instant.

Fichiers ajoutés sur Dropbox .

Plan 1 - Plan initial loufoque estimé en production

Plan 2 - plan réel, ancien CE, dans un environnement de test (même comportement, mêmes statistiques loufoques)

Plan 3 - plan actuel, nouveau CE, dans un environnement de test

Marian
la source
1
Nous avons fini par désactiver le magasin de requêtes, nous ne savons pas quelle était la cause principale (nous avons eu plus d'un problème à coup sûr). De mon côté, le processeur augmenterait tout ce que nous avons cliqué pour afficher les statistiques du magasin de requêtes.
A_V

Réponses:

6

Comme je l'ai dit dans la réponse, le test empirique a montré qu'il y avait des index sur les objets système sys.plan_persisted * sans aucune (aucune) statistique créée sur eux. Je soupçonne que cela est dû au fait que la base de données est migrée à partir d'une instance SQL 2005 et maintenue pendant un certain temps au niveau de compatibilité 100, donc le nouveau CE n'a pas pu être utilisé.

Vérification du nombre de lignes:

Select count(1) from NoNameDB.sys.plan_persist_runtime_stats with (nolock) --60362   
Select count(1) from NoNameDB.sys.plan_persist_plan with (nolock) --1853    
Select count(1) from NoNameDB.sys.plan_persist_runtime_stats_interval with (nolock) --671    
Select count(1) from NoNameDB.sys.plan_persist_query with (nolock) --1091    
Select count(1) from NoNameDB.sys.plan_persist_query_text with (nolock) --911

Cela a montré que les estimations initiales étaient fausses. Terminé avec une connexion DAC, sinon les tables ne sont pas disponibles pour interroger.

Vérification des statistiques:

DBCC SHOW_STATISTICS ('sys.plan_persist_runtime_stats_interval', plan_persist_runtime_stats_interval_cidx);    
DBCC SHOW_STATISTICS ('sys.plan_persist_runtime_stats', plan_persist_runtime_stats_idx1);    
DBCC SHOW_STATISTICS ('sys.plan_persist_runtime_stats', plan_persist_runtime_stats_cidx);    
DBCC SHOW_STATISTICS ('sys.plan_persist_plan', plan_persist_plan_cidx);    
DBCC SHOW_STATISTICS ('sys.plan_persist_plan', plan_persist_plan_idx1);    
DBCC SHOW_STATISTICS ('sys.plan_persist_query', plan_persist_query_cidx)    
DBCC SHOW_STATISTICS ('sys.plan_persist_query_text', plan_persist_query_text_cidx);

Cela a montré que certains index avaient des statistiques vides (manquant, aucun, zéro).

Correction initiale:

UPDATE STATISTICS sys.plan_persist_runtime_stats WITH fullscan;
UPDATE STATISTICS sys.plan_persist_plan WITH fullscan;
UPDATE STATISTICS sys.plan_persist_runtime_stats_interval WITH fullscan;
UPDATE STATISTICS sys.plan_persist_query WITH fullscan;
UPDATE STATISTICS sys.plan_persist_query_text WITH fullscan;

Ce type de correction des statistiques permettait de terminer la requête en 10 à 12 secondes.

Deuxième correctif :

(vérifié uniquement sur un environnement de test) et probablement le bon, car il montrait les meilleures statistiques pour la requête, était de changer le niveau de compatibilité de la base de données à 130. Le résultat final était que la requête se terminait en environ 10-12 secondes avec statistiques de nombre normal (10k lignes).

Correction intermédiaire :

DBCC TRACEON (2312) -- new CE

Aide relative aux statistiques sur les tables cachées du système.

Marian
la source
3

Le problème sous-jacent, qui est visible si vous ouvrez le plan réel dans SSMS et examinez l'utilisation du processeur (ou examinez XML), est le nœud 32, un TVF. L' accès répété aux TVF en mémoire est à l'origine des requêtes lentes du magasin de requêtes .

Coût TVF

Peu importe le nombre de lignes renvoyées par ces TVF, seul le nombre de fois où elles sont consultées. Le correctif sera tout ce que vous pouvez faire pour décourager vos plans de les lire plusieurs fois.

Sur la base de mon débogage limité (à la fois en compétences et en temps passé), mon hypothèse est que l'intégralité de la mémoire affectée au composant en mémoire particulier des données du magasin de requêtes est analysée à chaque exécution de TVF. Je n'ai pas pu affecter cette allocation de mémoire avec sp_query_store_flush_dbou DBCC FREESYSTEMCACHE.

Les solutions de contournement réussies jusqu'à présent incluent les guides de plan, les conseils (qui OPTION(HASH JOIN, LOOP JOIN)ont assez bien fonctionné pour moi jusqu'à présent) et l'exécution des requêtes du magasin de requêtes sur un nœud en lecture seule d'un AG.

Forrest
la source