Wie aus linearer Zeit Windows in O (n²) wird

Ich hatte vor kurzem mehrere Minuten Verspätung auf meiner Workstation. Nach der Untersuchung stellte sich heraus, dass die Ursache des Problems eine Sperre war, die fünf Minuten dauern konnte, während der die Quelle der Sperre im Grunde genommen in einem Zyklus von neun Anweisungen drehte.

Es ist sehr wichtig für mich, gute Überschriften für meine Posts auszuwählen, aber ich erinnerte mich sofort, dass der entsprechende Name "48 Cores sind durch neun Anweisungen blockiert" bereits von einem Post vor weniger als einem Monat übernommen wurde. Die Anzahl der blockierten Prozessoren ist unterschiedlich und der Zyklus ist etwas länger, aber in der Tat führt dies dazu, dass Sie Deja Vu erleben. Daher wollte ich, während ich das neu entdeckte Problem erläutere, darüber nachdenken, warum dies die ganze Zeit passiert .

Warum passiert das?

Grob gesagt ergeben sich solche Probleme aus einer Beobachtung, die ich Dawsons erstes Gesetz zum Rechnen nennen werde: O (n ² ) ist ein Magnet für Algorithmen, die sich nicht gut skalieren lassen : Sie sind schnell genug, um in Produktion zu gehen, aber langsam genug, um alles zu verderben. wenn sie dort ankommen.


O (n ² ) in Aktion - Daten aus meinem Fall

Was ist los? Der Entwickler schreibt den Code und verwendet den O (n ² ) -Algorithmus. Vielleicht merkt er das nicht, oder der Algorithmus wird aufgrund eines Fehlers zu O (n ² ), oder der Entwickler weiß, dass er O (n ² ) ist, aber er denkt, dass es niemals wichtig sein wird. Unter Laborbedingungen ist die Codegeschwindigkeit akzeptabel und für die meisten Benutzer in der realen Welt akzeptabel. Dann erstellt jemand 7.000 Prozesse mit aktiviertem App Verifier oder erstellt eine Binärdatei mit 180.000 CFG-Elementen oder sammelt eine so große DLL, dass sie ständig vorhanden ist Es wird eine einfach verknüpfte Liste durchsucht , die den gesamten Prozessor erfasst. Als ich an der Startzeit des Valve Source 2-Motors arbeitete, fand ich viele O (n ² ) -Algorithmen, von denen jeder etwa 30 Sekunden zur Startzeit des Motors beitrug, dh, dieses Problem tritt bei sehr unterschiedlichen Entwicklern auf.

O (n ² ) ist ein Magnet für Algorithmen, die nicht gut skalieren: Sie sind schnell genug, um in Produktion zu gehen, aber langsam genug, um alles zu verderben, wenn sie dort ankommen.

Genau.

Beispielsweise wird die Erstellung von App Verifier-Protokolldateinamen für jeden ausgeführten Prozess in linearer Zeit ausgeführt. Dies ist normal, bis Sie feststellen, dass dies zu O (n ² ) führt, wenn viele Prozesse ausgeführt werden. Manchmal ist es nicht einmal offensichtlich, dass es verschachtelte Schleifen gibt, oder formal ist es nicht O (n ² ), oder es ist nicht offensichtlich, dass die Schleifen so lange laufen können, dass sie die Geschwindigkeit erheblich beeinflussen können ...

Nutzen Sie diese Gelegenheit, denken Sie beim Schreiben von Code darüber nach, überwachen Sie, wie die Leistung unter hohen Lasten skaliert wird, und untersuchen Sie verdächtige Codeabschnitte, wenn Sie ein Profil für solch hohe Lasten erstellen. Oder überlasse es mir, damit ich danach suchen und Artikel in meinem Blog schreiben kann.

Kehren wir zu unseren üblichen Beschwerden zurück

Wie üblich habe ich an meiner veralteten, aber immer noch leistungsstarken Workstation mit 48 logischen Prozessoren und 96 GB RAM gearbeitet. Ich habe Ninja Chrome eingeführt , um Chromium zu bauen, aber ... nichts ist passiert. Ich habe nachgesehen und 20 Sekunden gewartet, aber die Montage hat nie begonnen. Deshalb bin ich natürlich zu UIforETW gewechselt , um die ETW- Spur aufzuzeichnen. Genauer gesagt habe ich es versucht. Beim Versuch, die Trace-Aufzeichnung zu starten, friert UIforETW ein . Zum ersten Mal in meiner Praxis verwendete ein Käfer Schutzmaßnahmen, um mich daran zu hindern, ihn zu erforschen!

Nach ein oder zwei Minuten begann die Montage von Chromium, und UIforETW startete die Ablaufverfolgung, aber es begann zu spät und ich hatte nicht die geringste Information darüber, was passiert ist.


UIforETW-Optionen mit ausgewähltem Circular Buffer Tracing

Als dasselbe ein paar Tage später passierte, war UIforETW wieder nicht in der Lage, irgendetwas zu tun. Dieses Mal habe ich die Spur verlassen, um in kreisförmigen Speicherpuffern zu arbeiten, um auf die Tatsache vorbereitet zu sein, dass der Hang zum dritten Mal auftreten würde. Dies verringerte jedoch die Geschwindigkeit meiner Build-Tools erheblich, sodass ich nach einigen Stunden aufgab.

Dann wiederholte sich diese Situation erneut . Dieses Mal habe ich das von Microsoft - wprui erstellte ETW - Traceprotokollierungstool ausgeführt und konnte mit der Aufzeichnung beginnen. Ungefähr 40 Sekunden später begann die Montage und ich bekam eine Spur!

Kann ich jetzt mit der Untersuchung beginnen?

Früher bemerkte ich im "Task-Manager", dass WinMgmt.exe während dieser Einfrierungen ausgeführt wurde . Als ich mir die CPU-Auslastungsdaten in WPA ansah, war ich überzeugt, dass nach mehr als vierzig Sekunden, in denen WinMgmt.exe fast der einzige Arbeitsprozess war, mein Computer nach dem Herunterfahren von WinMgmt.exe zum Leben erweckt wurde:


Wir warten auf das Erwachen von Prozessen, nachdem WinMgmt.exe abgeschlossen ist

All dies ist ziemlich verdächtig, aber meine weisen Leser wissen, dass "danach" nicht "aufgrund" bedeutet und dass Beweise erforderlich sind.

Wie beim letzten Mal habe ich den Moment des Entsperrens im Diagramm angenähert, die Kontextwechsel nach Einschaltzeit sortiert und nach dem ersten Schalter mit einem langen Wert für " Zeit seit letztem" gesucht (der angibt, wie lange der Thread nicht ausgeführt wurde). Nachdem ich ein Dutzend Threads verpasst hatte, bei denen es sich nur um kurze Ausfallzeiten handelte, fand ich den ersten von vielen, der 41,57 Sekunden wartete. Der schlafende Thread hat WinMgmt.exe nicht aufgeweckt , aber ich fand schnell heraus, dass er mit dem Thread aufgewacht ist, der WinMgmt.exe einen Bruchteil einer Millisekunde zuvor aufgeweckt hat .

Eine Erläuterung der Diagramme zur CPU-Auslastung (präzise) und der Konzepte für vorbereitende Threads / neue Threads finden Sie in diesem Lernprogramm oder in dieser Dokumentation .

Im Screenshot mit den Inhaltsumschaltdaten enthält Zeile 17 den Stream 72.748 (WinMgmt.exe) , der den Stream 74.156 (svchost.exe) aktiviert . In Zeile 19 aktiviert der Thread 74.156 (svchost.exe) den Thread 58.704 (svchost.exe) , der auf 41,57 Sekunden gewartet hat. Dies ist der erste Faden, der nach einem langen Schlaf aufwacht und von diesem die Kette der Aktivierung von Flüssen fortsetzt. Gerade aktivierte Threads werden in der Spalte " Neue Thread- ID" angezeigt. Gehen Sie einige Zeilen nach unten und sehen Sie sie in der Spalte "Thread-ID bereitstellen" , um einen anderen Thread zu aktivieren. Die Namen und Prozess-IDs helfen Ihnen, den Kontext zu verstehen. Zeile 17 ist den Zeilen 18 und 19 zugeordnet, Zeile 19 ist 20 zugeordnet, die der Zeile 23 zugeordnet ist, die der Zeile 27 zugeordnet ist, und so weiter; Jeder Thread wird durch den vorherigen Thread in der Kette aktiviert:


Das Monster erwacht - lange, leere Fäden werden lebendig

41.57 ist eine lange Zeit, um einen Thread zu blockieren, aber in Wirklichkeit wurden Hunderte von Threads blockiert und sie wurden viel länger blockiert. Der einzige Grund dafür, dass der Wert für " Zeit seit dem letzten Mal" ungefähr 41,5 Sekunden beträgt, ist, dass die Länge der Ablaufverfolgung vor dem Auflösen des Hangs behoben wurde.

Es scheint, dass die Ergebnisse mit der Theorie übereinstimmen , dass sich das Problem in WinMgmt.exe befindet , aber sie beweisen es nicht. Mein Selbstvertrauen nahm zu, als ich mir svchost.exe (3024) unter Trace-> System Configuration-> Services ansah und feststellte, dass es sich um einen Winmgmt- Dienst handelt, aber ich brauchte noch mehr Sicherheit.

Nachdem ich ein bisschen weiter gewühlt hatte (in der Zeit vorwärts und rückwärts gewandert), entschied ich, dass die Interaktionen zu kompliziert sind, um sie im Detail zu analysieren, insbesondere ohne Streamnamen , die darauf hindeuten könnten, was 25 verschiedene Threads in svchost.exe (3024) tun.

Beweis!

Dann habe ich mich entschieden, WinMgmt.exe schuldbeweis anders anzusprechen . Vielleicht hat es sich gelohnt, damit anzufangen, aber es wäre zu einfach. Ich habe die Befehlszeile WinMgmt.exe aus der Prozesstabelle in WPA genommen und sie manuell gestartet. Der Befehl hat die Form:

winmgmt.exe / verifyrepository

und es dauerte ungefähr fünf Minuten, um fertig zu sein. Während es funktionierte (und ich viel Zeit hatte), stellte ich fest, dass ich den ETW-Trace nicht über UIforETW starten konnte . Solche Beweise waren besser als jede komplizierte Analyse, die ich durchführen konnte.


Konfiguration, um nur lange ruhende Threads anzuzeigen

Dann habe ich den Repro erneut ausgeführt, wobei die Ablaufverfolgung bereits ausgeführt wurde. Nach der Analyse der Ablaufverfolgung entdeckte ich mehr als hundert Prozesse, deren Threads länger als fünf Minuten blockiert waren !

Und nochmal auf den Punkt ...

Aus Gewohnheit schaute ich mir noch einmal die CPU-Auslastungsdaten (Sampled) an, um festzustellen, auf welche Weise WinMgmt.exe Zeit verschwendete. Ich habe schnell herausgefunden, dass 96,5% der Samples in repdrvfs.dll! CPageCache :: Read () enthalten sind und vier verschiedene Stacks aufgerufen haben:


Vier Wege, die mich zu CPageCache :: Read führten

Hier wird ein Baum mit vollständigen Stapeln für diese Funktion angezeigt, hauptsächlich für Personen von Microsoft, die dieses Problem untersuchen möchten:


Vollständige Stapel, die zu CPageCache :: Read führen

Ich habe eine Adressenspalte hinzugefügt und festgestellt, dass sich 95,3% der Stichproben in einem Zyklus von neun Anweisungen befanden (Stichproben gingen immer nur in sieben von neun Anweisungen ein (wenn Sie wissen möchten, warum, siehe hier ), aber der Debugger zeigte die volle Größe des Zyklus an). :


Proben nach Adresse - sieben sehr „heiße“ Adressen

Dann habe ich winmgmt.exe / verifyrepository manuell gestartet und gleichzeitig CPU- Zählerdaten über die ausgeführten Verzweigungsanweisungen gesammelt . Daraus konnte ich ungefähr herausfinden, wie oft die Schleife lief. Dies war wahrscheinlich nicht notwendig, aber ich wollte sicherstellen, dass die Schleife viele Male ausgeführt wurde und nicht langsam (aus irgendeinem Grund). Ich fand es sehr cool, dass ich es einfach machen kann, nur eine winzige Änderung an der Batch-Datei vornehmen. Ich fand heraus, dass WinMgmt.exe ungefähr eine Verzweigungsanweisung pro Zyklus ausführte, das heißt, der Zyklus (der, wie ich bereits wusste, den größten Teil der CPU-Zeit in Anspruch nahm) war extrem schnell und die Verlangsamung lag an der Tatsache, dass er Hunderte von Millionen lief mal.

Xperf-Verzögerung

Aus Gründen der Akribie habe ich mich entschlossen, herauszufinden, warum UIforETW während dieses Vorfalls nicht mit der Verfolgung beginnen konnte. Es stellte sich heraus, dass UIforETW xperf ausführte , aber xperf in diesem Aufrufstapel 41,5 Sekunden (tatsächlich länger) im Leerlauf war:

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

Kurz gesagt, xperf wird von Wbem aufgerufen und daher von diesem Problem blockiert. xperf versucht, die Ablaufverfolgung vor dem Starten zu stoppen, da ich dieses Verhalten hinzugefügt habe, um den Start der Ablaufverfolgung fehlertoleranter zu gestalten . Ich vermute, dass immer noch ein Hang auftritt, weiß es aber nicht genau.

Wir erstellen Graphen von rechnerischer Komplexität

Ich habe festgestellt, dass WinMgmt.exe das Verzeichnis c: \ windows \ System32 \ wbem \ Repository durchsucht, das sich auf meinem Computer auf 1,9 GB befindet. Daher habe ich bei der Arbeit und auf Twitter gefragt, wie viel dieses Verzeichnis zum Abrufen von Datenpunkten benötigt. Ich habe auch Leute gebeten, die Laufzeit von winmgmt.exe / verifyrepository zu korrigieren, und mit dem Planen begonnen. Obwohl diese Tests auf völlig unterschiedlichen Rechnern mit unterschiedlichen CPU-Geschwindigkeiten durchgeführt wurden, stellte sich heraus, dass das Diagramm ziemlich klar ist:


Die Beziehung zwischen der Quadratwurzel der Zeit und der Größe des Repositorys

Dieses Diagramm des Verhältnisses von sqrt (Zeit) zur Repository-Größe ist unglaublich ideal für Daten, die von sechs verschiedenen Computern empfangen werden, und es ist dennoch real. Offensichtlich hat die VerifyRepository- Funktion die Leistung von O (n ² ). Wenn n die Größe des Repository-Verzeichnisses in GB ist , dauert VerifyRepository ca. 1,6 * n ² Minuten. Dies ist eine gute grobe Schätzung für alle Werte - von einem Sekundenbruchteil bis zu zehn Minuten.

Relevanz

Entweder habe ich Glück oder ich bin nur wachsam, weil seit ein paar Wochen niemand mehr auf dieses Problem gestoßen ist - ich dachte, mit meinem Auto passieren seltsame Dinge. Aber plötzlich hörte ich verdächtig ähnliche Beschwerden von Kollegen. Einer von ihnen verfügte über ein 2,6-GB-Repository, dessen Überprüfung zehn Minuten in Anspruch nahm. Das Problem betraf einige unserer CI- Entwickler und in unterschiedlichem Maße auch andere Personen. Meine Kollegen wissen normalerweise, dass ich im Falle von Problemen mit der Leistung von Windows-Computern das sagen muss. Es gibt jedoch wahrscheinlich viele andere Google-Mitarbeiter, die unter Windows arbeiten und durch diesen Fehler verhindert werden, aber sie erkennen dies nicht.

Zum Glück habe ich bereits angefangen, mit unserer IT-Abteilung zu arbeiten. Ich habe das Skript gefunden, mit dem WinMgmt gestartet wurde, und festgestellt, dass es stündlich ausgeführt wird. Dies bedeutete, dass auf meinem Computer 10% der Zeit WinMgmt.exe / verifyrepository ausgeführt wurde und einige meiner Kollegen über 16% der Zeit verfügten. Es besteht eine relativ hohe Wahrscheinlichkeit, dass sich die Montage um zehn Minuten verzögert.

Als die Berichte eintrafen, war der Fix bereits auf dem Weg zur Produktion. Das Skript war optional und die verursachten Probleme auf keinen Fall wert. Daher bestand die Lösung darin, den Aufruf zu deaktivieren.

Zusammenfassung

winmgmt.exe / verifyrepository enthält einen Zyklus von neun Befehlen, deren Anzahl der Ausführungsiterationen proportional zum Quadrat der Größe des wbem-Repositorys ist . Aus diesem Grund kann die Ausführung des Befehls bis zu zehn Minuten dauern, obwohl sie in der Realität in wenigen Sekunden ausgeführt werden sollte. Das ist schlecht für sich.

Noch schlimmer ist, dass das Team während des Betriebs eine WMI-Sperre ( Windows Management Instrumentation ) durchführt, sodass alle Prozesse, die WMI-Vorgänge ausführen, einfrieren.

Erstaunliche Rätsel

Das Skript, das winmgmt.exe / verifyrepository stündlich ausführte, tat dies viele Jahre lang, aber problematisches Verhalten trat erst vor ein bis zwei Monaten auf. Dies bedeutet vermutlich, dass das wbem-Repository in letzter Zeit viel größer geworden ist. Verzögerungen bei 0,5 GB sind leicht zu übersehen, ab 1,0 GB können sie jedoch bereits anstrengend sein. Wie auf Twitter vorgeschlagen, habe ich strings.exe für die Datei objects.data ausgeführt. Viele der gebräuchlichsten Zeichenfolgen enthalten polmkr im Namen, aber ich weiß nicht, was das bedeutet.

Ich habe auf Twitter einen Fehlerbericht veröffentlicht , der zunächst einige Bewegungen des WMI-Teams verursachte , dann jedoch keine Antworten mehr erhielt. Daher weiß ich nicht, wie es jetzt aussieht.

Ich würde gerne eine Lösung für das Leistungsproblem finden, und ich möchte, dass unsere IT-Abteilung in der Lage ist, das Problem zu finden und zu beheben, das unsere wbem-Repositorys so groß macht. Derzeit hat die IT-Abteilung jedoch zugesagt, den Befehl / verifyrepository nicht mehr stündlich auszuführen, um die schlimmsten Symptome zu vermeiden.

Referenzen

• Eine allgemeine Liste von ETW-Tutorials, Untersuchungen und Dokumentationen finden Sie hier: https://tinyurl.com/etwcentral
• Das Tutorial zur CPU-Auslastung (Sampled) (um herauszufinden, wofür die CPU-Zeit aufgewendet wird) und die Dokumentation finden Sie hier.
• Das Lernprogramm zur CPU-Auslastung (Präzise) (aus Gründen, aus denen Threads nicht ausgeführt werden können) und die Dokumentation finden Sie hier.
• Links zu einzelnen Artikeln finden Sie im Hauptteil des Beitrags. Sie finden sie auch in meiner Kategorie " Berichterstattung untersuchen"
• Andere Geschichten über O (n ² ) -Algorithmen können auf Accidentally Quadratic nachgelesen werden

Eine Diskussion des Artikels über Reddit ist hier , eine Diskussion über Hacker-News ist hier , ein Thread auf Twitter ist hier und möglicherweise hier