Est-ce le symptôme d'un serveur surchargé?

12

J'ai essayé de diagnostiquer des ralentissements dans une application. Pour cela, j'ai enregistré les événements étendus SQL Server .

  • Pour cette question, je regarde une procédure stockée particulière.
  • Mais il existe un ensemble de base d'une douzaine de procédures stockées qui peuvent également être utilisées comme enquête de pomme à pomme.
  • et chaque fois que j'exécute manuellement l'une des procédures stockées, elle s'exécute toujours rapidement
  • et si un utilisateur réessaye: il s'exécutera rapidement.

Les temps d'exécution de la procédure stockée varient énormément. Beaucoup d'exécutions de cette procédure stockée retournent en <1s:

entrez la description de l'image ici

Et pour ce seau "rapide" , c'est beaucoup moins que 1s. Il s'agit en fait d'environ 90 ms:

entrez la description de l'image ici

Mais il y a une longue queue d'utilisateurs qui doivent attendre 2s, 3s, 4s secondes. Certains doivent attendre 12, 13, 14 ans. Ensuite, il y a les âmes vraiment pauvres qui doivent attendre 22, 23, 24.

Et après 30 ans, l'application cliente abandonne, abandonne la requête et l'utilisateur doit attendre 30 secondes .

Corrélation pour trouver la causalité

J'ai donc essayé de corréler:

  • durée vs lectures logiques
  • durée vs lectures physiques
  • durée vs temps cpu

Et aucun ne semble donner de corrélation; aucun ne semble être la cause

  • durée vs lectures logiques : que ce soit un peu ou beaucoup de lectures logiques, la durée fluctue encore énormément :

    entrez la description de l'image ici

  • durée vs lectures physiques : même si la requête n'a pas été servie à partir du cache et que de nombreuses lectures physiques ont été nécessaires, cela n'affecte pas la durée:

    entrez la description de l'image ici

  • duration vs cpu time : que la requête prenne 0s de temps CPU ou 2,5s de temps CPU, les durées ont la même variabilité:

    entrez la description de l'image ici

Bonus : j'ai remarqué que la durée v lectures physiques et la durée v temps CPU semblent très similaires. Cela est prouvé si j'essaie de corréler le temps CPU avec les lectures physiques:

entrez la description de l'image ici

Il s'avère que beaucoup d'utilisation du processeur provient des E / S. Qui savait!

Donc, s'il n'y a rien dans le fait d' exécuter la requête qui peut expliquer les différences de temps d'exécution, cela signifie-t-il que c'est quelque chose de non lié au CPU ou au disque dur?

Si le CPU ou le disque dur étaient le goulot d'étranglement; ne serait-ce pas le goulot d'étranglement?

Si nous émettons l'hypothèse que c'est le CPU qui était le goulot d'étranglement; que le CPU est sous-alimenté pour ce serveur:

  • alors les exécutions utilisant plus de temps CPU ne prendraient-elles pas plus de temps?
  • car ils doivent compléter avec d'autres en utilisant le processeur surchargé?

De même pour les disques durs. Si nous émettons l'hypothèse que le disque dur était un goulot d'étranglement; que les disques durs n'ont pas assez de débit aléatoire pour ce serveur:

  • alors les exécutions utilisant plus de lectures physiques ne prendraient-elles pas plus de temps?
  • car ils doivent compléter avec d'autres en utilisant les E / S de disque dur surchargées?

La procédure stockée elle-même n'effectue ni n'exige aucune écriture.

  • Habituellement, il renvoie 0 lignes (90%).
  • Parfois, il renvoie 1 ligne (7%).
  • Il renverra rarement 2 lignes (1,4%).
  • Et dans le pire des cas, il a renvoyé plus de 2 lignes (une fois renvoyant 12 lignes)

Ce n'est donc pas comme s'il retournait un volume fou de données.

Utilisation du processeur du serveur

L' utilisation du processeur du serveur est en moyenne d'environ 1,8%, avec un pic occasionnel allant jusqu'à 18% - il ne semble donc pas que la charge du processeur soit un problème:

entrez la description de l'image ici

Ainsi, le processeur du serveur ne semble pas surchargé.

Mais le serveur est virtuel ...

Quelque chose en dehors de l'univers?

La seule chose qu'il me reste à imaginer est quelque chose qui existe en dehors de l'univers du serveur.

  • si ce n'est pas des lectures logiques
  • et ce ne sont pas des lectures physiques
  • et ce n'est pas l'utilisation du processeur
  • et ce n'est pas une charge CPU

Et ce n'est pas comme si c'était les paramètres de la procédure stockée (car émettre la même requête manuellement et cela ne prend pas 27 secondes - cela prend ~ 0 seconde).

Quoi d'autre pourrait expliquer que le serveur prenne parfois 30 secondes, au lieu de 0 seconde, pour exécuter la même procédure stockée compilée.

  • points de contrôle?

C'est un serveur virtuel

  • l'hôte surchargé?
  • une autre VM sur le même hôte?

Passer en revue les événements étendus du serveur; il ne se passe rien d'autre en particulier lorsqu'une requête prend soudainement 20 secondes. Il fonctionne bien, puis décide de ne pas fonctionner correctement:

  • 2 secondes
  • 1 seconde
  • 30 secondes
  • 3 secondes
  • 2 secondes

Et je ne trouve aucun autre élément particulièrement pénible. Ce n'est pas pendant la sauvegarde du journal des transactions toutes les 2 heures.

Que pourrait- il être d'autre?

Y a-t-il autre chose que je peux dire en plus: "le serveur" ?

Modifier : corréler selon l'heure de la journée

J'ai réalisé que j'avais corrélé les durées avec tout:

  • lectures logiques
  • lectures physiques
  • l'utilisation du processeur

Mais la seule chose à laquelle je n'ai pas corrélé c'était l' heure de la journée . La sauvegarde du journal des transactions toutes les 2 heures est peut-être un problème.

Ou peut - être les ralentissements ne se produisent dans les postes de contrôle au cours mandrins?

Nan:

entrez la description de l'image ici

Intel Xeon Gold Quad-core 6142.

Modifier - Les gens font l'hypothèse du plan d'exécution des requêtes

Les gens émettent l'hypothèse que les plans d'exécution des requêtes doivent être différents entre "rapide" et "lent". Ils ne sont pas.

Et nous pouvons le voir immédiatement après inspection.

Nous savons que la plus longue durée des questions n'est pas due à un "mauvais" plan d'exécution:

  • celui qui a pris des lectures plus logiques
  • celui qui a consommé plus de CPU à partir de plus de jointures et de recherches de clés

Parce que si une augmentation des lectures, ou une augmentation du processeur, était une cause de l'augmentation de la durée des requêtes, nous l'aurions déjà vu ci-dessus. Il n'y a pas de corrélation.

Mais essayons de corréler la durée avec la métrique du produit de la zone de lecture du processeur:

entrez la description de l'image ici

Il y a encore moins de corrélation - ce qui est un paradoxe.

Modifier : mise à jour des diagrammes de dispersion pour contourner un bogue dans les diagrammes de dispersion Excel avec un grand nombre de valeurs.

Prochaines étapes

Mes prochaines étapes seront de demander à quelqu'un d'avoir à générer des événements sur le serveur pour les requêtes bloquées - après 5 secondes:

EXEC sp_configure 'blocked process threshold', '5';
RECONFIGURE

Cela n'explique pas si les requêtes sont bloquées pendant 4 secondes. Mais peut-être que tout ce qui bloque une requête pendant 5 secondes en bloque également certains pendant 4 secondes.

Les plans lents

Voici le plan lent des deux procédures stockées en cours d'exécution:

  • `EXECUTE FindFrob @CustomerID = 7383, @StartDate = '20190725 04: 00: 00.000', @EndDate = '20190726 04: 00: 00.000'
  • `EXECUTE FindFrob @CustomerID = 7383, @StartDate = '20190725 04: 00: 00.000', @EndDate = '20190726 04: 00: 00.000'

La même procédure stockée, avec les mêmes paramètres, s'exécute dos à dos:

| Duration (us) | CPU time (us) | Logical reads | Physical reads | 
|---------------|---------------|---------------|----------------|
|    13,984,446 |        47,000 |         5,110 |            771 |
|     4,603,566 |        47,000 |         5,126 |            740 |

Appel 1:

|--Nested Loops(Left Semi Join, OUTER REFERENCES:([Contoso2].[dbo].[Frobs].[FrobGUID]) OPTIMIZED)
    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]))
    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[RowNumber]) OPTIMIZED)
    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[TransactionPatronInfo].[IX_TransactionPatronInfo_CustomerID_TransactionGUID] AS [tpi]), SEEK:([tpi].[CustomerID]=[@CustomerID]) ORDERED FORWARD)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[Transactions].[IX_Transactions_TransactionGUIDTransactionDate]), SEEK:([Contoso2].[dbo].[Transactions].[TransactionGUID]=[Contoso2].[dbo
    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions2_MoneyAppearsOncePerTransaction]), SEEK:([Contoso2].[dbo].[FrobTransactions].[TransactionGUID]=[Contos
    |    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions_RowNumber]), SEEK:([Contoso2].[dbo].[FrobTransactions].[RowNumber]=[Contoso2].[dbo].[Fin
    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[Frobs].[PK_Frobs_FrobGUID]), SEEK:([Contoso2].[dbo].[Frobs].[FrobGUID]=[Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]),  WHERE:([Contos
    |--Filter(WHERE:([Expr1009]>(1)))
     |--Compute Scalar(DEFINE:([Expr1009]=CONVERT_IMPLICIT(int,[Expr1012],0)))
          |--Stream Aggregate(DEFINE:([Expr1012]=Count(*)))
           |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactins_OnFrobGUID]), SEEK:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]=[Contoso2].[dbo].[Frobs].[LC

Appel 2

|--Nested Loops(Left Semi Join, OUTER REFERENCES:([Contoso2].[dbo].[Frobs].[FrobGUID]) OPTIMIZED)
    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]))
    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[RowNumber]) OPTIMIZED)
    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[TransactionPatronInfo].[IX_TransactionPatronInfo_CustomerID_TransactionGUID] AS [tpi]), SEEK:([tpi].[CustomerID]=[@CustomerID]) ORDERED FORWARD)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[Transactions].[IX_Transactions_TransactionGUIDTransactionDate]), SEEK:([Contoso2].[dbo].[Transactions].[TransactionGUID]=[Contoso2].[dbo
    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions2_MoneyAppearsOncePerTransaction]), SEEK:([Contoso2].[dbo].[FrobTransactions].[TransactionGUID]=[Contos
    |    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions_RowNumber]), SEEK:([Contoso2].[dbo].[FrobTransactions].[RowNumber]=[Contoso2].[dbo].[Fin
    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[Frobs].[PK_Frobs_FrobGUID]), SEEK:([Contoso2].[dbo].[Frobs].[FrobGUID]=[Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]),  WHERE:([Contos
    |--Filter(WHERE:([Expr1009]>(1)))
     |--Compute Scalar(DEFINE:([Expr1009]=CONVERT_IMPLICIT(int,[Expr1012],0)))
          |--Stream Aggregate(DEFINE:([Expr1012]=Count(*)))
           |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactins_OnFrobGUID]), SEEK:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]=[Contoso2].[dbo].[Frobs].[LC

Il est logique que les plans soient identiques; il exécute la même procédure stockée, avec les mêmes paramètres.

sql-server sql-server-2012 Ian Boyd
la source
2
Pouvez-vous publier les plans de requête - bonne exécution vs mauvaise exécution?
Kin Shah
4
Ma première supposition d'ici serait de bloquer ...
Tibor Karaszi
3
Qui a rejeté cela? C'est une question très détaillée et bien étudiée même s'il manque les plans de requête! +1 de moi!
Vérace
4
Comment en êtes-vous arrivé à la conclusion que les plans de requête sont "identiques"? Voulez-vous simplement dire qu'ils ont la même forme? Postez-les quelque part afin que nous puissions aussi comparer. Le simple fait de nous dire qu'ils sont identiques ne signifie pas qu'ils sont identiques.
Aaron Bertrand
3
L'ajout des plans d'exécution acutaux à l'aide de PasteThePlan pourrait nous donner une idée de ce que la requête attendait.
Randi Vertongen

Réponses:

2

Jetez un œil aux wait_stats et cela montrera quels sont les plus gros goulots d'étranglement sur votre serveur SQL.

J'ai récemment rencontré un problème où une application externe était lente par intermittence. Cependant, l'exécution des procédures stockées sur le serveur lui-même était toujours rapide.

La surveillance des performances n'a montré aucun souci du tout avec les caches SQL ou l'utilisation de la RAM et des E / S sur le serveur.

Ce qui a aidé à affiner l'enquête était d'interroger les statistiques d'attente collectées par SQL dans sys.dm_os_wait_stats

L'excellent script sur le site Web SQLSkills vous montrera ceux que vous rencontrez le plus. Vous pouvez ensuite affiner votre recherche pour identifier les causes.

Une fois que vous savez quelles sont les attentes, ce script vous aidera à préciser quelle session / base de données connaît les attentes:

SELECT OSW.session_id,
       OSW.wait_duration_ms,
       OSW.wait_type,
       DB_NAME(EXR.database_id) AS DatabaseName
FROM sys.dm_os_waiting_tasks OSW
INNER JOIN sys.dm_exec_sessions EXS ON OSW.session_id = EXS.session_id
INNER JOIN sys.dm_exec_requests EXR ON EXR.session_id = OSW.session_id
OPTION(Recompile);

La requête ci-dessus et d'autres détails proviennent du site Web MSSQLTips .

Le sp_BlitzFirstscript du site Web de Brent Ozar vous montrera également ce qui cause les ralentissements.

KevH
la source