Powershell Trace (Write-Trace)

Diese Seite beschäftigt sich dem Performancebremse "Write-host" und "Start-Transcript" für Diagnoseausgaben von Skripten. Powershell-Skripte kann man wunderbar per Taskplaner auch im Hintergrund automatisiert starten. Natürlich ist dann ein gewisses Logging erforderlich da Sie ja nicht auf die Konsole schauen können. Wer nun eifrig mit Write-Host, Write-Verbose und Write-Debug hantiert und dann die Ausgaben mit Start-Transcript in eine Datei protokollieren lässt, hat alle Informationen um bei einem Fehler oder Problem auch nachträglich die Ursache zu finden. Das Problem dabei: Ihr Skript wird sehr langsam.

Rennpferd oder Schnecke

Aufgefallen ist mir das bei einem Kunden, bei dem ein PowerShell-Skript jede Stunde im Hintergrund die Mitgliedschaften von Gruppen ermittelt und dann bei Änderungen gewisse Aktionen ausgeführt hat. Ich habe mit Hash-Tabellen und CSV-Datenbanken gearbeitet, um einen Vorher/Nachher-Vergleich zu erreichen und die Ergebnisse und Zwischenstände zu speichern. Aber je weiter der Rollout voran gekommen ist und je mehr Anwender damit zu verarbeiten waren, desto länger wurde die Laufzeit.

Ich habe dann ein paar "Zeitstempelausgaben" addiert und musste feststellen, dass das Skript an Stellen langsam war, an denen ich es wirklich nicht erwartet hätte. So dauerte das Auslesen von wenigen tausend Mitgliedern einer Gruppe in eine Hashtabelle über 10 Minuten. Wenn ich aber das reine Auslesen als Einzeiler in Powershell ausgeführt habe, dann waren es eher Sekunden. Aber dabei lief natürlich keine Bildschirmausgabe mit. Das war unbefriedigend und zudem war ja absehbar, dass das Skript im Endausbau eventuell gar nicht mehr innerhalb einer Stunde fertig werden würde.

Messreihe los!

Ich wusste aber erst einmal nicht, ob es nun wirklich die Ausgabe auf die Console, das Transcript oder die Speicherorganisation mit Hash-Tabellen war. Also war eine kleine Testserie erforderlich.

# Initilaisieren der Hashtabelle
$test=@{}


# 10.000 Einträge in Hashtabelle addieren
measure-command {1..10000 | %{$test[$_]=$_}} | fl TotalSeconds
TotalSeconds      : 0.746168


# 10.000 Einträge in Hashtabelle addieren mit Write-Verbose aber VerbosePreference ist SilentlyContinue”
measure-command {1..10000 | %{$test[$_]=$_; write-verbose $_}} | fl TotalSeconds
TotalSeconds      : 1.8838652


# 10.000 Einträge in Hashtabelle addieren mit Write-Verbose aber VerbosePreference ist "Continue"”, d.h. sichtbar
$VerbosePreference="continue"
measure-command {1..10000 | %{$test[$_]=$_; write-verbose $_}} | fl TotalSeconds
TotalSeconds      : 23.0433452


# 10.000 Einträge in Hashtabelle addieren mit Write-Verbose aber VerbosePreference ist "Continue" aber Fenster ist minimiert
measure-command {1..10000 | %{$test[$_]=$_; write-verbose $_}} | fl TotalSeconds
TotalSeconds      : 12.0433452


# 10.000 Einträge in Hashtabelle addieren mit Write-Verbose aber VerbosePreference ist "Continue" und Transcript ist aktiv
measure-command {1..10000 | %{$test[$_]=$_; write-verbose $_}} | fl TotalSeconds
TotalSeconds      : 295.9679879


# 10.000 Einträge in Hashtabelle addieren mit Write-Verbose aber VerbosePreference ist "SilentlyContinue" und Transcript ist aktiv
measure-command {1..10000 | %{$test[$_]=$_; write-verbose $_}} | fl TotalSeconds
TotalSeconds      : 4.5755291


# 10.000 Einträge in Hashtabelle addieren und mit out-file protokollieren
measure-command {1..10000 | %{$test[$_]=$_; "verbose $_"| Out-File trace.txt -Append}} | fl TotalSeconds
TotalSeconds      : 184.3268518


# 10.000 Einträge in Hashtabelle addieren und StreamWriter schreiben
$tracefile = New-Object System.IO.StreamWriter "c:\temp\append3.txt"
measure-command {1..10000 | %{$test[$_]=$_; $tracefile.WriteLine("verbose $_") }} | fl TotalSeconds
$tracefile.Close();
TotalSeconds      : 0.6148604


# 10.000 Einträge in Hashtabelle addieren und an Debug senden
measure-command {1..10000 | %{$test[$_]=$_; [System.Diagnostics.Debug]::WriteLine("verbose $_") }} | fl TotalSeconds
TotalSeconds      : 0.7493729
TotalSeconds      : 4.4674756  (mit aktiviertem Sysinternals DebugView


# 10.000 Einträge in Hashtabelle addieren mit Write-progress
measure-command {1..10000 | %{$test[$_]=$_; Write-Progress -Activity "count $_"}} | fl TotalSeconds
TotalSeconds      : 84.5293784
 
 
# 10.000 Einträge in Hashtabelle addieren mit Write-progress bei jeder 10ten ausgaben
measure-command {1..10000 | %{$test[$_]=$_; if ($_%10 -eq 0) {Write-Progress -Activity "count $_"}}} | fl TotalSeconds
TotalSeconds      : 10.9353648

Ich denke die Messreihe zeigt sehr gut, dass allein die Ausgabe der Aktionen auf den Bildschirm die Laufzeit explodieren lässt. Das Skript läuft natürlich schneller, wenn ich die Konsole minimiere. Das direkte Schreiben der Ausgabe mit Outfile, was natürlich nicht dem Transcript entspricht ist ebenfalls langsam während eine Ausgabe mit dem StreamWriter fast kaum bremst. Auch die Ausgabe mit System.Diagnostics.Debug ist schnell und selbst wenn es einen DebugListener gibt, ist es zwar gebremst aber das ist kein Vergleich mit den anderen Ausgaben.

Alternative

Detailliertes Protokollieren kostet Ressourcen mit Bordmitteln zur Ausgabe auf die Konsole um sie per Start-Transcript wieder abzugreifen und in ein Logfile zu schreiben, ist zeitintensiv. Es zeigt sich, dass die Write-*-Commandlets zwar schnell und einfach sind, aber ihre Grenzen bei unsachgemäßem Einsatz schnell deutlich werden. Insbesondere wenn Skripte viele Ausgaben produzieren, weil sie z.B. für jeden der 20.000 Benutzer einen Eintrag ausgeben. Dann kann auch das schnellste Script gebremst werden. Aber irgendwie muss ich doch protokollieren, was meine Skripte machen um nachträglich diese analysieren zu können. Aber Transcript und viele Bildschirmausgaben kann wohl doch nicht die Lösung sein.

Also muss ich zukünftig zumindest die Skripte anders gestalten, die im Hintergrund laufen. Bildschirmausgaben sollen nur sparsam genutzt werden aber dafür müssen Aktionen eigens ausgegeben und Fehler abgefangen werden. Das Transcript kann durchaus mitlaufen, wenn auf der "Console" eben nur die wesentlichen Dinge erscheinen. Eine Debug-Ausgabe mit "Write-Debug" sollte man nicht über Transcript einfangen.

Ich habe mir ein paar Regeln zurecht gelegt:

  • Keine Ausgabe ist eine gute Ausgabe
    Versuchen Sie nicht alles auf den Bildschirm zu schreiben, sondern nur "wichtige" Dinge, die bei einem Tracing erforderlich sind
    • Write-Debug ist geeignet, wenn…
      .. Sie wirklich in einer Fehlersituation etwas im Skript nachstellen wollen, ohne den Code zu ändern
      Sie sollten die "$DebugPreference" auf SilentlyContinue lassen
    • Write-Verbose ist hilfreich, wenn..
      .. Sie durch den Parameter "-Verbose" etwas mehr erfahren wollen. Aber auch hier ist "$Verbosepreference" per Default auf "SilentlyContinue"
    • Write-Progress
      Wenn Sie dem Skript "zuschauen", dann hilft dieses Werkzeug bei der Fortschrittsanzeige. Im Transcript erscheint es nicht
  • Write-Host ist ganz schlecht.
    Es macht den Host bei vielen Ausgaben langsam und wird nicht einmal vom Transcript erfasst. Der Text erscheint nur auf der Console. Für geplante Tasks bringt Sie das nicht weiter
  • Transcript bremst ein wenig aber ist erlaubt
    Voraussetzung ist aber, dass Sie eben die Console nur mit wirklich wichtigen Meldungen beschreiben.
  • Fehler abfangen und ausgeben
    Fehler sind wichtig und jeder Fehler sollte ausgeben werden. Daher steht ja "$errorpreference" auch auf Continue. Sie sehen die Fehler auf der Console und sie langen im eventuell aktivierten Transcript.
    Es ist ihnen natürlich erlaubt auch selbst die Fehlerbehandlung zu machen und entsprechende Ausgaben zu generieren.
  • Eigener Trace
    Es ist deutlich schneller, wen Sie Debug und Trace-Ausgaben selbst formulieren und mit einem StreamWriter wegschreiben
    Denken Sie aber daran, danach das File zu schreiben, damit der FileHandle wieder freigegeben wird. Damit können Sie aber keine Ausgaben von Write-Verbose, Write-Debug oder Write-Error abfangen.
    Sie müssen also schon selbst sich um Fehlerbehandlung und deren Ausgabe kümmern, wenn Sie im Trace auch diese Daten haben wollen.

Für mich bedeutet das

  1. Ganz wenige "Write-Host" und "Write-Progress" und nur für Ausgaben, die auf der Console sinnvoll sind.
  2. Write-Verbose, um bestimmte Aktivitäten auszugeben, wenn der Aufruf mit "-verbose" angefordert wird,
  3. Write-Debug ist wirklich eine Ausnahme

Ich denke ich werde meine Ideen von vor einigen Jahren doch noch mal aufgreifen und ein eigenes Modul bauen, welches z.B. ein "Write-Trace" implementiert, welches mir ein einfaches Logging in einer Datei und eventuell die Windows Debug-Schnittstelle erlaubt. Oder ich nutze gleich eine allgemein zugänglich Log-Klasse wie z.B. Log4Net

Modul Write-Trace

Alles in allem bin ich dann doch mal wieder dabei gelandet mir ein "Trace-Modul" zu bauen, welches ich flexibel in anderen Skripten einsetzen kann aber möglichst gar keine Abhängigkeiten hat. Write-Trace ist und will kein Ersatz für ein super flexibles Tracing oder Debugging sein. Ich schreibe aber häufig Skripte, die per Taskplaner ausgeführt "unsichtbar" werden und da ist ein Logging unersetzlich. Leider sind Write-Verbose, Write-Error, Write-Debug., Write-Host und Write-Output auf die Console langsam und mit Start-Transcript wird das anhängen an eine Datei auch nicht schneller. Daher würde ich mit den Write-* Commandlets von PowerShell nur dann arbeiten, wenn jemand auf dem Bildschirm auch zuschauen will oder es nicht um Performance geht.

Meine Anforderungen waren also

  • Formatierte Ausgabe mit Zeit, Level und Text
    Wenn ich schon Logs schreibe, dann bitte lesbar in eine Textdatei, anhand man schnell sich zurecht findet. Dazu gehört ein Zeitstempel und eine "Severity"
  • Keine 3rd Party DLLs oder Module
    Ich verzichte also absichtlich auf bekannte Libraries wie Log4net u.a. Es wird einfach eine PSM1-Datei sein
  • Logfile reicht, kein Eventlog, SNMPTrap, Syslog, Perfmon, SMTP-Mail o.ä.
    Das würde die Parameter nur aufblähen und komplex machen
  • Ersatz für Write-Host u.a. aber kein Ersatz für Transcript
    Wenn ich aber "Logging" einfach am Transcript vorbei in eine Trace-Datei lege und reduziert auf der Konsole ausgeben dann wird das Skript hoffentlich weniger stark gebremst.
  • Kompromisse
    Ein Modul kann zwar initialen Code ausführen aber bei einem Abbruch des Skripts kann es nichts mehr aufräumen. Eine Ausgabe mit dem schnellen System.IO.StreamWriter kann dann nicht mehr mit einem Close geschlossen werden. Für die erste Version muss ein Out-File herhalten, auch wenn es jedes Mal die Datei neu zum Anhängen öffnet.

Daher habe ich ein PSM1-Modul gestartet, welches einen Befehl "Write-Trace" implementiert, der einen "numerischen Level" und eben die "Message" annimmt. Daneben gibt es einen Set-TraceParameter und Get-TraceParameter, um die Wert für das Logfile und den maximalen Level für die Ausgabe auf den Bildschirm und die Datei zu steuern bzw. abzufragen. Hier der Download des Moduls:

write-trace.psm1
Bitte TXT-Datei nach dem Download nach "write-trace.psm1" umbenennen

Hier ein Beispiel für die Nutzung:

import-module .\write-trace.psm1 -force
set-TraceParameter -tracefilename ".\testtrace.log"
get-TraceParameter
write-trace "Normal"
write-trace -level 1 "Error"
write-trace -level 2 "Warning"
write-trace -level 3 "Info"
write-trace -level 4 "Debug 4"
write-trace -level 5 "Debug 5"
Write-Trace "Start $($MyInvocation.InvocationName) on $($env:COMPUTERNAME) by $env:UserDOMAIN\$env:UserNAME

Die erzeugte Log-Datei sieht dann wie folgt aus:

Als Erweiterung könnte ich mir vorstellen, die Ausgaben auf dem Bildschirm noch farblich zu codieren. Es gibt natürlich auch noch viele andere vergleichbare Module und Skripte.

1000 Ausgaben auf Bildschirm und Datei dauern bei mir ca. 5 Sekunden (also 5ms/Zeile). Ohne Bildschirmausgabe sind es aber immer noch 4 Sekunden. Nur komplett ohne Ausgaben, die ja über den Level gesteuert werden können, gehen 0,5 Sek ins Land. Der Schreibzugriff mit Out-File ist nun mal nicht der Schnellste.

Mittelfristig kann ich mir vorstellen, das Logging z.B. noch mit Syslog und farblichen Ausgaben zu erweitern.

Gibt es nichts im .NET Framework ?

Erst später habe ich gefunden, dass es auch im System.Diagnostics-Namespace einen "TextWriterTraceListener" gibt, mit dem man Traces abfischen kann, die man mit der Trace-Funktion und Debug-Funktion erstellt. Auch DebugView (Sysinternals) ist ein Listener. Allerdings müsste man den Listener dann als zweiten Prozess starten und in der Debug-Schnittstelle tummeln sich auch noch andere Programme. Daher habe ich diesen Weg nicht weiter beschrieben.

[System.Diagnostics.Debug]::WriteLine($message, $category);

[System.Diagnostics.Trace]::WriteLine($message, $category);

Beidem Meldung landet dann im "Debug Channel" und kann z.B. mit DebugView angezeigt werden:

Der Unterschied zwischen "Trace" und "Debug" ist zumindest beim Entwickeln mit Visual Studio der, dass "DEBUG"-Meldungen nur mit in den Code kompiliert werden, Wenn Sie auch "debug" beim kompilieren aktiviert haben. Trace-Meldungen landen immer im Code. Bei PowerShell ist das aber wohl kein Unterschied. Da fehlt dann natürlich nur noch der "Listener" per PowerShell, der diese Meldungen einfängt und in eine Logdatei schreibt.

Weitere Links