"Explorer passe 700 ms pour ouvrir le menu contextuel de la barre des tâches. 75% de ce temps, il effectue 114 801 opérations de lecture à partir d'un fichier, la quantité moyenne de données lues est de 68 octets.
Dois-je écrire un article à ce sujet, ou un tweet plutôt sarcastique? »Je travaille rapidement sur un ordinateur, et donc cela m'ennuie quand je dois attendre la fin d'une opération, qui doit être effectuée instantanément. Un obstacle constant sur mon ordinateur portable domestique était la fermeture lente des fenêtres de la barre des tâches. Je fais un clic droit sur l'icône, j'attends que le menu s'ouvre, puis je sélectionne «Fermer la fenêtre». Le plus lent dans ce processus devrait être les mouvements de la souris, mais il s'avère que le composant le plus long est le délai avant l'apparition du menu.
Cela m'a dérangé pendant longtemps, mais j'ai montré une maîtrise de soi inhabituelle et je me suis gardé de l'irritation. C'était jusqu'à aujourd'hui, quand j'ai finalement cassé et attrapé le traceur
ETW .
Ce message est écrit comme un chèque pour les blogs de vitesse. Environ 90 minutes se sont écoulées entre le moment où le problème a été découvert et le tweet sarcastique à ce sujet jusqu'à la publication du message.
Le traceur ETW a corrigé la façon dont je fais un clic droit sur la barre des tâches et ferme les deux fenêtres de l'Explorateur. J'ai utilisé la fonction
UIforETW Tracing to file avec les options par défaut, ce qui a donné lieu à un
journal de diagnostic de 20,9 Mo.Parfois, la partie la plus difficile dans l'analyse d'une trace est de trouver l'emplacement du problème, mais dans ce cas, cette partie de l'analyse est triviale. Il y avait trois signaux sans ambiguïté indiquant le bon endroit et le coupable douloureusement évident du crime.
Le premier signal était des événements d'entrée. UIforETW contient un
enregistreur d'entrée intégré (suffisamment anonymisé pour que je ne vole pas accidentellement des mots de passe ou des informations personnelles), j'ai donc juste eu à étudier en détail les événements
MouseUp et
Button Type avec une valeur de 2 correspondant au bouton droit de la souris. Dans le même temps, des marques sur la chronologie
WPA apparaissent lorsque ces événements se produisent - voir les lignes verticales dans la capture d'écran:
Cela m'a fait comprendre que lorsque je relâche le bouton droit de la souris, puis après 600 ms, le focus de la fenêtre change, ce qui, à mon avis, correspond au moment où le menu est affiché. De plus, RuntimeBroker.exe a un bloc clair d'activité CPU entre les événements de relâchement du bouton de la souris et de changement de focus de la fenêtre.
Il n'a pas été prouvé que le changement de focus de la fenêtre et l'activité du CPU sont liés, mais après avoir pris des mesures en utilisant l'application d'enregistrement d'écran, j'ai vu qu'il faut environ 660 ms pour afficher le menu, j'ai donc tendance à y faire confiance.
L'étape suivante consiste à savoir ce que fait RuntimeBroker.exe. Bien que
l'utilisation du processeur (précise) vous aide à voir combien de temps processeur le processus utilise et pourquoi il est inactif, le
tableau d'utilisation du
processeur (échantillonné) est un bon outil pour savoir à quoi le temps processeur est consacré. Je l'ai soigneusement étudié et j'ai rapidement constaté que 264 échantillons provenaient de
KernelBase.dll! ReadFile :
Après avoir cherché un peu plus, j'ai trouvé d'autres piles d'appels qui affectaient également cette fonction, j'ai donc fait un clic droit dessus et sélectionné
Afficher les appelants-> Par fonction . Le mode activé (avec piles inversées) a montré que sur 899 échantillons de ce processus, 628 échantillons, ou 70%, provenant de différentes piles d'appels sont passés par cette fonction:
271 échantillons de ce flux n'ont pas transité par la fonction et les échantillons restants (non représentés) se trouvaient dans d'autres flux.
Notez que 899 échantillons dans un flux de 10252 représentent deux clics de souris, soit environ 450 échantillons ou 450 ms (à une fréquence d'échantillonnage standard de 1 kHz) par clic de souris.
Parfois, les E / S de fichiers sont du temps CPU
L'utilisation du processeur (échantillonnée) indique le temps du
processeur , donc les E / S disque ne sont généralement pas affichées ici, car à ces moments, le flux s'endort et attend le disque. Le fait que les opérations d'E / S soient affichées en tant que temps CPU signifie que toutes les lectures sont tombées sur le cache système et que le temps CPU était une ressource supplémentaire du noyau (voir
ntoskrnl.exe dans la première pile d'appel échantillonnée) dépensée pour obtenir des données du cache.
Maintenant que
les E / S de fichiers sont suspectées, nous devons aller dans
Graph Explorer-> Storage-> File I / O. Après avoir légèrement ajusté l'apparence des colonnes, nous avons obtenu le résultat impressionnant suivant:
, 10 252
RuntimeBroker.exe 229 604
ReadFile, 15 686 586 . 68 .
.
, — . ,
RuntimeBroker.exe . 4 027 904 , , , 1,9 .
, . , ( ):
%appdata%\Microsoft\Windows\Recent\AutomaticDestinations\f01b4d95cf55d32a.automaticDestinations-msWPA. — , . :
« „“, ( ) ( ) „“/ . , ».
, !
, . , , , .
- ReadFile, 68 . , , . , 4 , .
- , - , — .
- , - , . , ETW !
- https://aka.ms/AA60dfg
- , UIforETW ,
- , ( , ), shift+ . , .
- Hacker news
- Reddit
- Twitter