MSXFAQ MeetNow aktiv: Komm doch einfach dazu.

PS Dateiperformance

Ich habe zwar schon auf der Seite PS Performance etwas zur Ausgabe in Dateien geschrieben aber im Hinblick auf Write-Host Logging und andere Skripte habe ich das Thema Protokollierung in eine Datei noch einmal bearbeitet.

Auslöser war ein Skript "SMTPStorm", welches sehr viele Verbindungen zu Exchange Servern starten sollte und ich natürlich die Aktivitäten und Zeiten protokollieren wollte. Es ging dabei um den Aufbau von möglichst vielen TCP-Verbindungen und die Erfassung der Antwort. Ich erhoffte mir durchaus ein paar hundert oder sogar tausend Verbindungsanfragen pro Sekunde. Wenn dann ein "Write-Host" oder ein Schreiben in eine Datei auch nur 1ms Zeit dauert und das Skript blockiert, dann kann ich diese Werte nie erreichen. Es besteht das Risiko, dass ein Logging/Debugging die Messungen selbst verfälschen. Das kann ein ineffektiver Disk-I/O sein, weil Out-File jedes mal erst die Datei suchen, öffnen, anhängen, schließen muss oder die Bildschirmausgabe durch das Scrolling das Skript verzögert. Ohne eigene Programmierung laufen auch PowerShell-Skripte sequentiell ab.

Ausgabe auf Konsole und Datei

Habe also mehrere Testläufe gemacht und einfach einen Zeitstempel mit der laufenden Nummer ausgeben lassen:

Write-Host "$(Get-Date -f o)$($_)"

Für die Ausgabe auf den Bildschirm mit Streamwriter war das dann folgende Schleife:

Write-Host "Starting test: Ohne Bildschirmausgabe mit StreamWriter"
$start = Get-Date
$outfile = New-Object System.IO.StreamWriter ".\logfile.txt"
1..$iteration | ForEach-Object {
    # Write-Host "$(Get-Date -f u)$($_)" 
    $outfile.WriteLine("$(Get-Date -f u)$($_)")
    # "$(Get-Date -f o)$($_)" | Out-File -Append "output.txt" 
}
$outfile.Close();
$end = Get-Date
Write-Host "Duration: $($end - $start)"

Die drei Zeilen in der Schleife habe ich entsprechend ein/aus-kommentiert. Anbei auch dein Skript, welches alle Varianten nacheinander ausführt:

ps-dateiperformance.ps1.txt

Den String habe ich auch über verschiedene Wege in der PowerShell 7 in Dateien und auf den Bildschirm verschieden oft schreiben lassen und die Zeit in Sekunden gemessen:

Ausgabe 1000 10.000

Nur Write-Host

0,259

2,498

Write-Host mit aktiviertem Transcript

0,615

4,683

Write-Host mit Dateiausgabe an Out-File -Append

2,330

24,209

Write-Host mit Dateiausgabe an StreamWriter

0,296

2,750

Ohne Write-Host mit Dateiausgabe an StreamWriter

0,040

0,214

Ohne Write-Host mit Dateiausgabe mit Out-File -Append

2,158

23,090

Diese Werte sind nur miteinander vergleichbar aber nicht über verschiedene Systeme hinweg, da unterschiedliche CPUs und Hintergrundlasten nicht heraus gerechnet werden können. Ihre eigenen Messwerte können daher anders aussehen

Nun sind 1000 oder 10.000 Ausgaben nicht gerade sehr viel und ein paar Sekunden Verzögerung eines Skript hört sich ja nicht nach viel an. Wenn ich aber 10.000 TCP-Connections starten und protokollieren will, dann ist auch 1 Sekunde viel, wenn jede Verbindung nur genau eine Ausgabe mit "Out-File" schreiben würde. Würde ich dann je eine Zeile für "INIT, CONNECT, LESEN, CLOSE" verwenden, dann würde Out-File die Ausgabe um über 4 Sekunden ausbremsen. Mehr als 250 Connections/Sekunde könnte ich so nie erzeugen.

Zeitstempel ermitteln

Der Vollständigkeit halber hat mich natürlich noch interessiert, ob die Ermittlung des Zeitstempel noch einen Einfluss hat.

Befehl Dauer in mx

measure-command {$a= 1..100000 | get-date}

750-900

measure-command {$a= 1..100000 | get-date -Format u}

450.550

measure-command {1..100000 | get-date | out-null}

890-1300

measure-command {1..100000 | %{[datetime]::Now} | Out-Null}

300-380

measure-command {$a= 1..100000 | %{[datetime]::UtcNow}}

250-320

measure-command {$a= 1..100000 | %{([System.DateTime]::UtcNow).tostring("u")}}

450-490

Da sind natürlich nun wirklich keine Werte aber wir sehen auch, dass die Ausgabe nach "Out-Null" über die Pipeline länger braucht und ich durch die Angabe einer Formatierung einen String anstelle eines PSObjects aus Ausgabe erzeuge und damit weiter Zeit sparen kann. Wenn ich das letzte Millisekündchen rauspressen will, sollte ich nicht "Get-Date" sondern "[datetime]::Now" verwenden.

Ergebnis

Für den normalen Einsatz in der PowerShell ist es ziemlich egal, ob sie mit "Get-Date -Format u" oder "[System.DateTime]::UtcNow).tostring('u')" die aktuelle Zeit holen und selbst die Ausgabe in eine Protokolldatei können Sie mit "Out-File" machen. Natürlich ist dies langsamer, da Out-File jedes Mal die Datei erst öffnen, schreiben und schließen muss. Allerdings ist der Code vielleicht einfacher zu lesen und sie können die Zieldatei mit angeben. Bei einem StreamWriter müssen Sie z.B. auch darauf achten, dass beim ungeplanten Ende des Skripts auch der Handle wieder freigegeben wird.

Wer aber zeitkritische Abschnitte oder sehr große Datenmengen protokollieren muss, sollte im Hinterkopf behalten, dass ein Write-Host auf die Konsole durchaus Zeit kosten kann.

Weitere Links