Comment le temps linéaire se transforme en Windows en O (n²)

J'ai récemment rencontré des retards de plusieurs minutes sur mon poste de travail. Après l'enquête, il s'est avéré que la cause du problème était une serrure, qui pouvait durer cinq minutes, pendant laquelle la source de la serrure tournait essentiellement en un cycle de neuf instructions.

Il est très important pour moi de sélectionner de bonnes rubriques pour mes messages, mais je me suis tout de suite souvenu que le nom approprié "48 cœurs sont bloqués par neuf instructions" avait déjà été repris par un post écrit il y a moins d'un mois. Le nombre de processeurs bloqués est différent et le cycle est un peu plus long, mais en fait, tout cela vous fait ressentir le déjà-vu. Par conséquent, pendant que j'explique le nouveau problème trouvé, je voulais réfléchir à la raison pour laquelle cela se produit tout le temps .

Pourquoi cela se produit-il?

Grosso modo, de tels problèmes surviennent à la suite d'une observation que j'appellerai la première loi de Dawson sur l'informatique: O (n ² ) est un aimant pour les algorithmes qui ne s'adaptent pas bien : ils sont assez rapides pour entrer en production, mais assez lents pour tout gâcher, quand ils y arrivent.


O (n ² ) en action - données extraites de mon cas

Que se passe-t-il? Le développeur écrit le code et utilise l'algorithme O (n ² ). Peut-être qu'il ne s'en rend pas compte, ou que l'algorithme devient O (n ² ) à cause d'un bug , ou que le développeur sait qu'il est O (n ² ), mais il pense que cela ne sera jamais important. Dans des conditions de laboratoire, la vitesse du code est acceptable, et acceptable pour la plupart des utilisateurs dans le monde réel, mais quelqu'un crée alors 7 000 processus avec App Verifier activé ou crée un fichier binaire avec 180 000 éléments CFG , ou collecte une DLL si volumineuse qu'elle est constamment une liste à liaison unique est analysée , ce qui prend tout le processeur. En travaillant sur l'heure de lancement du moteur Valve Source 2, j'ai trouvé de nombreux algorithmes O (n ² ), chacun ajoutant environ 30 secondes à l'heure de lancement du moteur, c'est-à-dire que ce problème se produit avec des développeurs très différents.

O (n ² ) est un aimant pour les algorithmes qui ne s'adaptent pas bien: ils sont assez rapides pour entrer en production, mais assez lents pour tout gâcher lorsqu'ils y arrivent.

Exactement.

Par exemple, la création de noms de fichiers journaux App Verifier est effectuée en temps linéaire pour chaque processus en cours d'exécution, ce qui est normal jusqu'à ce que vous réalisiez que cela conduit à O (n ² ) si de nombreux processus sont en cours d'exécution. Parfois, il n'est même pas évident qu'il existe des boucles imbriquées, ou formellement, ce n'est pas O (n ² ), ou il n'est pas évident que les boucles puissent fonctionner si longtemps qu'elles peuvent affecter de manière significative la vitesse ...

Considérez donc cette opportunité, pensez-y lors de l'écriture de code, surveillez la façon dont les performances sont mises à l'échelle sous de lourdes charges et examinez les sections suspectes de code lors du profilage de telles charges. Ou laissez-le-moi afin que je puisse les rechercher et écrire des articles sur mon blog.

Revenons à nos plaintes habituelles

Comme d'habitude, j'ai travaillé sur mon poste de travail obsolète mais toujours puissant avec 48 processeurs logiques et 96 Go de RAM. J'ai introduit le chrome ninja pour construire Chrome, mais ... rien ne s'est passé. J'ai regardé et j'ai attendu vingt secondes, mais l'assemblage n'a jamais commencé. Alors, bien sûr, je suis passé à UIforETW pour enregistrer la trace ETW . Plus précisément, j'ai essayé de le faire. En essayant de démarrer l'enregistrement de trace, UIforETW se bloque . Pour la première fois dans ma pratique, un bug a utilisé des mesures de protection pour m'empêcher de l'explorer!

Après une ou deux minutes, l'assemblage de Chromium a commencé et UIforETW a commencé la trace, mais il a commencé trop tard et je n'avais pas la moindre information sur ce qui s'était passé.


Options UIforETW avec suivi de tampon circulaire sélectionné

Lorsque la même chose s'est produite quelques jours plus tard, UIforETW n'a de nouveau pu rien faire. Cette fois, j'ai laissé la trace fonctionner dans des tampons de mémoire circulaires, pour être préparé au fait que le blocage se produirait pour la troisième fois. Cependant, cela a considérablement réduit la vitesse de mes outils de construction, donc après quelques heures, j'ai abandonné.

Puis cette situation s'est répétée à nouveau . Cette fois, j'ai exécuté l'outil de journalisation de trace ETW créé par Microsoft - wprui , et j'ai pu commencer l'enregistrement. Environ 40 secondes plus tard, l'assemblage a commencé à fonctionner et j'ai eu une trace!

Puis-je commencer l'enquête maintenant?

Plus tôt, j'ai remarqué dans le "Gestionnaire des tâches" que WinMgmt.exe s'exécutait pendant ces blocages . Après avoir examiné les données d'utilisation précise du processeur dans WPA, j'étais convaincu qu'après plus de quarante secondes, pendant lesquelles WinMgmt.exe était presque le seul processus de travail, ma machine a pris vie après l' arrêt de WinMgmt.exe :


Nous attendons l'éveil des processus une fois WinMgmt.exe terminé

Tout cela est plutôt suspect, mais mes sages lecteurs savent que «après» ne signifie pas «en raison de» et nécessiteront des preuves.

Comme la dernière fois , j'ai approximé le moment du déverrouillage sur le graphique, en triant les commutateurs de contexte par Switch-In Time et en recherchant le premier commutateur avec une longue durée depuis la dernière valeur (indiquant la durée pendant laquelle le thread n'a pas été exécuté). Après avoir raté une douzaine de threads qui n'étaient que des temps d'arrêt courts, j'ai trouvé le premier de nombreux qui a attendu 41,57 secondes. Le thread endormi n'a pas réveillé WinMgmt.exe , mais j'ai rapidement découvert qu'il s'est réveillé avec le thread qui a réveillé WinMgmt.exe une fraction de milliseconde auparavant.

Pour une explication des graphiques d'utilisation du processeur (précis) et des concepts de thread de préparation / nouveau thread, consultez ce didacticiel ou cette documentation .

Dans la capture d'écran avec les données de changement de contenu, la ligne 17 contient le flux 72 748 (WinMgmt.exe) , qui active le flux 74 156 (svchost.exe). Ensuite, à la ligne 19, le thread 74 156 (svchost.exe) active le thread 58 704 (svchost.exe) , qui attendait 41,57 secondes. C'est le premier fil qui se réveille après un long sommeil et de là continue la chaîne d'activation des flux. Les threads qui viennent d'être activés peuvent être vus dans la colonne New Thread Id , puis descendre quelques lignes et les voir dans la colonne Readying Thread Id , en activant un autre thread. Les noms et les ID de processus vous aident à comprendre le contexte. La ligne 17 est associée aux lignes 18 et 19, la ligne 19 est associée à 20, qui est associée à la ligne 23, qui est associée à la ligne 27, et ainsi de suite; chaque fil est activé par le fil précédent de la chaîne:


Le monstre se réveille - de longs fils inactifs prennent vie

41.57 est long à bloquer un thread, mais en réalité des centaines de threads ont été bloqués, et ils ont été bloqués beaucoup plus longtemps. La seule raison pour laquelle leur valeur Time Since Last est d'environ 41,5 secondes est que la longueur de la trace avant le blocage est résolue.

Il semble que les résultats soient conformes à la théorie selon laquelle le problème se situe dans WinMgmt.exe , mais ils ne le prouvent pas. Ma confiance a augmenté lorsque j'ai regardé svchost.exe (3024) dans Trace-> Configuration système-> Services et découvert qu'il s'agit d'un service Winmgmt , mais j'avais encore besoin de plus de certitude.

Après avoir fouillé un peu plus (errant en avant et en arrière dans le temps), j'ai décidé que les interactions étaient trop compliquées pour les analyser en détail, en particulier sans les noms de flux qui pourraient nous indiquer ce que font 25 threads différents dans svchost.exe (3024) .

Preuve!

J'ai alors décidé d'approcher différemment la preuve de culpabilité de WinMgmt.exe . Cela valait peut-être la peine de commencer par cela, mais ce serait trop simple. J'ai pris la ligne de commande WinMgmt.exe de la table Processus dans WPA et l'ai démarrée manuellement. La commande a la forme:

winmgmt.exe / verifyrepository

et il a fallu environ cinq minutes pour terminer. Pendant que cela fonctionnait (et j'avais beaucoup de temps), j'ai découvert que je ne pouvais pas démarrer la trace ETW à partir d' UIforETW . Une telle preuve était meilleure que toute analyse complexe que je pouvais faire.


Configuration pour afficher uniquement les threads dormants depuis longtemps

Ensuite, j'ai exécuté à nouveau la repro avec la trace déjà en cours d'exécution; Après analyse de la trace, j'ai découvert plus d'une centaine de processus dont les threads ont été bloqués pendant plus de cinq minutes!

Et encore une fois au point ...

Par habitude, j'ai regardé à nouveau les données d'utilisation du processeur (échantillonnées) pour voir sur quoi WinMgmt.exe perdait du temps. J'ai rapidement découvert que 96,5% des échantillons se trouvaient dans repdrvfs.dll! CPageCache :: Read () , appelé sur quatre piles différentes:


Quatre chemins qui m'ont conduit à CPageCache :: Lire

Un arbre de piles complètes pour cette fonction est affiché ici, principalement pour les personnes de Microsoft qui souhaitent rechercher ce problème:


Piles complètes menant à CPageCache :: Lire de trois façons

J'ai ajouté une colonne d'adresse et j'ai découvert que 95,3% des échantillons étaient dans un cycle de neuf instructions (les échantillons tombaient toujours dans seulement sept des neuf instructions (si vous voulez savoir pourquoi, voir ici ), mais le débogueur a montré la taille complète du cycle) :


Échantillons par adresse - sept adresses très «hot»

Ensuite, j'ai commencé manuellement winmgmt.exe / verifyrepository , et en même temps, j'ai collecté des données de compteur CPU sur les instructions de branche qui étaient en cours d'exécution . À partir de cela, je pouvais à peu près comprendre combien de fois la boucle a fonctionné. Ce n'était probablement pas nécessaire, mais je voulais m'assurer que la boucle a été exécutée plusieurs fois et n'a pas été exécutée lentement (pour une raison quelconque). Je pensais que c'était très cool de pouvoir le faire simplement, il suffit d'apporter une petite modification au fichier batch. J'ai découvert que WinMgmt.exe exécutait environ une instruction de branchement par cycle, c'est-à-dire que le cycle (qui, comme je le savais déjà, consommait la majeure partie du temps CPU) était extrêmement rapide, et le ralentissement était dû au fait qu'il fonctionnait à des centaines de millions fois.

Délai Xperf

Juste pour des raisons de méticulosité, j'ai décidé de voir pourquoi UIforETW ne pouvait pas commencer le traçage pendant cet incident. Il s'est avéré que UIforETW exécutait xperf , mais xperf était inactif pendant 41,5 secondes (en fait plus) dans cette pile d'appels:

xperf.exe! wmain
xperf.exe! CStopTrace :: Execute
perfctrl.dll! LoggingSession :: EnumLoggers
perfctrl.dll! LoggingSession :: LoggingSession
perfctrl.dll! LoggingSession :: CreateProviderList
perfctrl.dll! GetProviderInfoCache
perfctrl.dll! CProviderInfoCache :: CProviderInfoCache
tdh.dll! TdhfEnumerateProviders
tdh.dll! TdhpWbemConnect
wbemprox.dll! CLocator :: ConnectServer
wbemprox.dll! CDCOMTrans :: DoActualConnection

En bref, xperf est appelé par Wbem et est donc bloqué par ce problème. xperf essaie d'arrêter la trace avant de la démarrer, car j'ai ajouté ce comportement pour rendre le début de la trace plus tolérant aux pannes . Je soupçonne qu'un blocage se produirait toujours, mais je n'en suis pas sûr.

Nous créons des graphiques de complexité informatique

J'ai remarqué que WinMgmt.exe scanne le répertoire c: \ windows \ System32 \ wbem \ Repository , qui fait 1,9 Go sur ma machine, j'ai donc demandé au travail et sur Twitter de dire combien ce répertoire prend pour obtenir des points de données. J'ai également demandé aux gens de corriger le temps d'exécution de winmgmt.exe / verifyrepository et j'ai commencé à planifier. Même si ces tests ont été effectués sur des machines complètement différentes avec des vitesses de processeur différentes, le graphique s'est avéré assez clair:


La relation entre la racine carrée du temps et la taille du référentiel

Ce graphique du rapport sqrt (temps) à la taille du référentiel est incroyablement idéal pour les données reçues de six machines différentes, et néanmoins, il est réel. De toute évidence, la fonction VerifyRepository a des performances O (n ² ). Si n est la taille du répertoire du référentiel en Go , alors VerifyRepository prend environ 1,6 * n ² minutes. Il s'agit d'une bonne estimation approximative pour toutes les valeurs - d'une fraction de seconde à dix minutes.

Pertinence

Soit j'ai de la chance, soit je suis juste observateur, car pendant quelques semaines, personne n'a plus rencontré ce problème - je pensais que des choses étranges se passaient avec ma voiture. Mais soudain, j'ai commencé à entendre des plaintes étrangement similaires de collègues. L'un d'eux avait un référentiel de 2,6 Go, ce qui prenait dix minutes à vérifier. Le problème a affecté certains de nos développeurs de CI , et à différents degrés, différentes autres personnes. Mes collègues savent généralement qu'en cas de problèmes avec les performances des machines Windows, je dois me le dire, cependant, de nombreux autres employés de Google travaillant sous Windows sont empêchés par ce bogue, mais ils ne le réalisent pas.

Heureusement, j'ai déjà commencé à travailler avec notre service informatique. J'ai trouvé le script qui a lancé WinMgmt et j'ai découvert qu'il s'exécute toutes les heures. Cela signifiait que ma machine exécutait WinMgmt.exe / verifyrepository 10% du temps, et certains de mes collègues avaient plus de 16% du temps. Il y a une probabilité assez élevée d'obtenir un délai de dix minutes avant l'assemblage.

Au moment où les rapports ont commencé à arriver, le correctif était déjà en cours de production. Le script était facultatif et ne valait certainement pas les problèmes qu'il causait, donc le correctif consistait à désactiver son appel.

Résumé

winmgmt.exe / verifyrepository contient un cycle de neuf instructions, dont le nombre d'itérations d'exécution est proportionnel au carré de la taille du référentiel wbem . Pour cette raison, l'exécution de la commande peut prendre jusqu'à dix minutes, bien qu'en réalité, elle devrait être exécutée en quelques secondes. C'est mauvais en soi.

Mais pire encore, l'équipe effectue un verrouillage WMI ( Windows Management Instrumentation ) pendant son fonctionnement, de sorte que tout processus qui effectue des opérations WMI se fige.

Énigmes incroyables

Le script qui exécutait winmgmt.exe / verifyrepository toutes les heures le faisait depuis de nombreuses années, mais un comportement problématique a commencé à apparaître il y a seulement un à deux mois. Vraisemblablement, cela signifie que le référentiel wbem est récemment devenu beaucoup plus grand. Les retards à 0,5 Go sont facilement ignorés, mais à partir de 1,0 Go et plus, ils peuvent déjà se fatiguer. Comme suggéré sur Twitter, j'ai exécuté strings.exe pour le fichier objects.data. Beaucoup de chaînes les plus courantes contiennent polmkr dans le nom, mais je ne sais pas ce que cela signifie.

J'ai publié un rapport de bogue sur Twitter , et au début, cela a provoqué un certain mouvement de la part de l'équipe WMI , mais j'ai ensuite cessé de recevoir des réponses, donc je ne sais pas quelle est la situation actuellement.

Je voudrais voir un correctif pour le problème de performances, et je voudrais que notre service informatique puisse trouver et résoudre le problème qui rend nos référentiels wbem si gros. Mais pour l'instant, le service informatique a promis de ne pas exécuter la commande / verifyrepository toutes les heures de plus, ce qui devrait nous aider à éviter les pires symptômes.

Les références

• Une liste générale des didacticiels, des enquêtes et de la documentation ETW est disponible ici: https://tinyurl.com/etwcentral
• Le tutoriel d'utilisation du processeur (échantillonné) (pour savoir sur quoi le temps du processeur est dépensé) est ici et la documentation est ici.
• Le didacticiel d'utilisation du processeur (précis) (pour trouver les raisons pour lesquelles les threads ne peuvent pas s'exécuter) est ici et la documentation est ici.
• Des liens vers des articles individuels sont donnés dans le corps de l'article, vous pouvez également les trouver dans ma catégorie Investigate Reporting
• D'autres histoires sur les algorithmes O (n ² ) peuvent être lues sur Accidentally Quadratic

Une discussion de l'article sur Reddit est ici , une discussion sur les nouvelles des hackers est ici , un fil sur Twitter est ici, et peut-être ici