„Der Explorer benötigt 700 ms, um das Kontextmenü der Taskleiste zu öffnen. In 75% dieser Fälle werden 114.801 Lesevorgänge aus einer Datei ausgeführt. Die durchschnittliche Menge der gelesenen Daten beträgt 68 Byte.
Soll ich einen Beitrag darüber schreiben oder einen eher sarkastischen Tweet? “Ich arbeite schnell an einem Computer und ärgere mich daher, wenn ich auf den Abschluss eines Vorgangs warten muss, der sofort ausgeführt werden sollte. Ein ständiges Hindernis für meinen Hochleistungs-Laptop zu Hause war das langsame Schließen der Fenster in der Taskleiste. Ich klicke mit der rechten Maustaste auf das Symbol, warte, bis sich das Menü öffnet, und wähle dann „Fenster schließen“. Die langsamste in diesem Prozess sollte Mausbewegungen sein, aber es stellt sich heraus, dass die längste Komponente die Verzögerung ist, bevor das Menü angezeigt wird.
Das hat mich lange gestört, aber ich zeigte uncharakteristische Selbstbeherrschung und hielt mich von Irritationen fern. Das war bis heute, als ich endlich kaputt ging und mir den
ETW- Tracer schnappte.
Dieser Beitrag wurde als Check für Speed-Blogging geschrieben. Ungefähr 90 Minuten vergingen von dem Moment an, als das Problem gefunden wurde und der sarkastische Tweet darüber, bis der Beitrag veröffentlicht wurde.
Der ETW-Tracer hat behoben, wie ich mit der rechten Maustaste auf die Taskleiste geklickt und die beiden Explorer-Fenster geschlossen habe. Ich habe die
UIforETW-Ablaufverfolgung für die
Dateifunktion mit Standardoptionen verwendet, was zu einem
20,9-MB-Diagnoseprotokoll führte .
Manchmal ist es am schwierigsten, eine Spur zu analysieren, den Ort des Problems zu finden. In diesem Fall ist dieser Teil der Analyse jedoch trivial. Es gab drei eindeutige Signale, die den richtigen Ort und den schmerzlich offensichtlichen Schuldigen des Verbrechens anzeigten.
Das erste Signal waren Eingangsereignisse. UIforETW enthält einen integrierten
Eingabe-Logger (anonymisiert genug, damit ich nicht versehentlich Passwörter oder persönliche Informationen stehle), sodass ich nur die Ereignisse
MouseUp und
Button Type im Detail mit einem Wert von 2 untersuchen musste, der der rechten Maustaste entspricht. Gleichzeitig erscheinen Markierungen auf der
WPA- Zeitachse, wenn diese Ereignisse auftreten - siehe die vertikalen Linien im Screenshot:
Dies machte mir klar, dass sich der Fensterfokus nach 600 ms ändert, wenn ich die rechte Maustaste loslasse, was meiner Meinung nach dem Moment entspricht, in dem das Menü angezeigt wird. Darüber hinaus verfügt RuntimeBroker.exe über einen eindeutigen Block der CPU-Aktivität zwischen den Ereignissen des Loslassens der Maustaste und dem Ändern des Fokus des Fensters.
Es ist nicht erwiesen, dass die Änderung des Fensterfokus und der CPU-Aktivität zusammenhängen, aber nachdem ich Messungen mit der Bildschirmaufzeichnungsanwendung durchgeführt habe, habe ich festgestellt, dass die Anzeige des Menüs etwa 660 ms dauert, daher vertraue ich dem eher.
Der nächste Schritt besteht darin, zu erfahren, was RuntimeBroker.exe tut. Obwohl Sie
anhand der CPU-Auslastung (präzise) feststellen können, wie viel CPU-Zeit der Prozess benötigt und warum er inaktiv ist, ist die
Tabelle CPU-Auslastung (Stichproben) ein gutes Tool, um herauszufinden, wofür die CPU-Zeit aufgewendet wird. Ich habe es sorgfältig studiert und schnell festgestellt, dass 264 Beispiele von
KernelBase.dll stammen! ReadFile :
Nachdem ich ein wenig mehr gesucht hatte, fand ich andere Anrufstapel, die sich ebenfalls auf diese Funktion
auswirkten . Ich klickte mit der rechten Maustaste darauf und wählte
Anrufer anzeigen-> Nach Funktion . Der aktivierte Modus (mit invertierten Stapeln) zeigte, dass von 899 Stichproben dieses Prozesses 628 Stichproben oder 70% aus verschiedenen Anrufstapeln diese Funktion durchlaufen haben:
271 Proben in diesem Strom haben die Funktion nicht durchlaufen, und die verbleibenden Proben (nicht gezeigt) befanden sich in anderen Strömen.
Es ist zu beachten, dass 899 Abtastwerte in einem Strom von 10 252 zwei Mausklicks darstellen, d. H. Ungefähr 450 Abtastwerte oder 450 ms (bei einer Standardabtastfrequenz von 1 kHz) pro Mausklick.
Manchmal ist Datei-E / A CPU-Zeit
Die CPU-Auslastung (abgetastet) zeigt die
CPU- Zeit an, sodass die Festplatten-E / A hier normalerweise nicht angezeigt werden, da in diesen Momenten der Stream einschläft und auf die Festplatte wartet. Die Tatsache, dass E / A-Vorgänge als CPU-Zeit angezeigt werden, bedeutet, dass alle Lesevorgänge auf den
Systemcache fielen und die CPU-Zeit eine zusätzliche Kernelressource (siehe
ntoskrnl.exe im ersten abgetasteten Aufrufstapel) war, die zum
Abrufen von Daten aus dem Cache aufgewendet wurde.
Nachdem die
Datei-E / A verdächtigt wurde, müssen wir zu
Graph Explorer-> Speicher-> Datei-E / A gehen. Nachdem wir das Erscheinungsbild der Säulen leicht angepasst haben, haben wir das folgende beeindruckende Ergebnis erzielt:
, 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