End2End File

Der Auslöser zu diesem Skript war ein älterer Supportfall, bei der ein Kunde sich über "Sanduhren" beim Explorer und beim Speichern von Dateien auf einem Server beschwert hat. Die klassische Kontrolle des Dateiservers mittels Perfmon und anderen lokalen Test (DT Performance Messung etc.) hat insofern nicht geholfen, da die kritischen Kennzahlen alle in Ordnung waren.

Also war eine aktive Langzeitmessung gefragt, bei der permanent eine kleine Grundlast aufgelegt wurde. Und tatsächlich konnte alle 6h eine Unterbrechung von 30Sek gemessen werden, während der aber kein Performance Counter angeschlagen hat. Mit dem Skript wurden dann mehrere Server als Quelle und mehrere Disks als Ziel ausgemessen und so eine bestimmter SAN-Storage isoliert. SAN-Controller und SAN-Switches, Virenscanner, Betriebssystemversionen, Treiber etc. wurden so ausgeschlossen. Letztlich konnte der SAN Storage-Hersteller dann herausfinden, dass wohl eine Festplatte im SAN eine alte Firmware hatte und damit einen Teil-Bus, damals noch SCSI, alle 6h mit einem Reset für 30 Sekunden blockiert hat. Nach dem Firmware-Update dieser Disk waren die Probleme weg.

End2End Monitoring - So fing es an
https://www.youtube.com/watch?v=CNDnw_dgBSs

Was kann ich müssen und analysieren?

End2End-File arbeitet anders und versucht gar nicht erst die maximale Leistung eines Systems zu ermitteln, sondern beaufschlagt das System mit einer definierbaren "Grundlast", und ermittelt die Zeiten hierfür. Es ist damit also sehr einfach möglich, von einem Client über das LAN oder lokal auf dem Server permanent eine kleine konstante Last auf dem Server anzulegen und "Aussetzer" zu ermitteln. Bislang hat das Skript mit geholfen bei ...

  • ... SAN-Problemen
    Bei einem Kunden haben sich Anwender über "Stockungen" bei der Arbeit mit "Dateiservern" beschwert. Nachdem Performance-Tests nur maximale Leistung gezeigt haben und das Netzwerk scheinbar "sauber" blieb, konnte mit end2end-file nachgewiesen werden, das immer regelmäßig die Performance für einige Sekunden "0" war. parallel aufgezeichnete Performance Counter und Queues unter Windows haben aber auch hier keinen Engpass angezeigt.
    Nachdem das Skript dann "lokal" auf dem Server gegen die lokalen Disks gefahren wurde, konnte belegt werden, dass auch hier die "Aussetzer" auf den SAN-Disks, aber nicht den lokalen Disks vorlagen. Insofern waren Netzwerk und "Serverdienst" rehabilitiert. Die Gegenprobe auf allen Servern zeigt, dass alle Server am gleichen Storage-Node das Problem hatten. Bei den anderen Servern ist es nur noch nie aufgefallen. Letztlich konnte mit dem Storage-Anbieter eine alte BIOS- Version auf einer Festplatte im SAN ausgemacht werden, die wohl den SCSI-Bus per Reset quasi "angehalten" hat.
    End2End-File hat nach der Korrektur dann auch keine "Aussetzer" mehr gezeigt.
  • WAN-Links
    Immer mehr "Kunden" zentralisieren ihre Exchange Umgebungen. Damit wird die WAN-Bandbreite natürlich wichtig. Eine kleine "Grundlast" von wenigen Prozent der nutzbaren Bandbreite kann mit end2end-file generiert und die Verzögerungen gemessen werden. Dies ist natürlich nicht für den "Dauereinsatz" vorgesehen, aber kann doch kurzfristige Überlastungen melden oder aufzeichnen, um späteren Beschwerden nachzugehen. Besser wäre es hier natürlich per SNMP die einzelnen Schnittstellen der WAN-Verbindung zu überwachen. Aber oftmals lässt der Provider dies nicht zu und bei einem VPN über das Internet können die beiden VPN-Tore nicht viel über die Gesamtperformance anzeigen. Ein einem Fall hat end2end-File sogar wunderbar gezeigt, wie WAN-Optimierer wie Riverbed oder Cisco WAAS-Systeme arbeiten. Dies war auch der Grund, warum Version 1.1 nicht mehr nur liest, sondern auch schreibt.

Es sind also manchmal die einfachen Skripte, die einem bei der Fehlersuche voran bringen.

So funktioniert das Skript

Dazu schreibt End2End-File eine bestimmte konfigurierbare Anzahl an Bytes auf die angegeben Datei (Local oder Netzwerk) und misst die Zeit hierfür. Danach pausiert das Skript für eine ebenfalls einstellbare Zeit um dann den Prozess zu wiederholen. Die Zeitdauer für das Schreiben wird zu einem Mittelwert verrechnet und wenn eine bestimmte ebenfalls konfigurierbare Abweichung vorhanden ist, wird ein Alarm (z.B. im Eventlog) generiert. Zudem werden alle Messwerte in einer CSV-Datei mit protokolliert.

Dieses Skript hat mir schon gute Dienste getan, wenn die Umgebung eigentlich ohne Fehler läuft aber manchmal Verzögerungen zu beobachten sind und Performancecounter oder SNMP-Werte der Switches zu ungenau waren oder nicht zur Verfügung standen.

Die Standardwerte sind wie folgt im Skript definiert. Sie können alle Werte im Skript ändern oder per Kommandozeile überschreiben.

  • Testfilename = ".\end2end-file.tmp"
    Dies ist der Dateiname und Pfad, welcher beschrieben wird.
  • Reportfilename= ".\end2end-file.csv"
    Ausgabe der aktuellen Messwerte als CSV-Datei
  • IdleTime = 100
    Ruhezeit zwischen zwei Schreibvorgängen in Millisekunden
  • Buffersize = 1024
    Größe des zu schreibenden Buffer in Bytes
  • Alarmdelta = 1000
    Maximale Abweichung des Messwerts vom Mittelwert in ms

Mit diesen Werte schreibt das Skript also alle 100ms eine 1KB-Datei. Wenn man die Zeit für das Schreiben als gering ansetzt, dann produziert dieses Skript maximal 10kbyte oder 100kbit/Sek. Ziel des Skript es ja nicht die maximale Leistung zu ermitteln, sondern die Kontinuität. Es liegt an ihnen, die Werte anzupassen. Eine höhere Belastung können Sie durch einen größeren Buffer als auch durch kürzere Pausenzeiten erreichen.

Wichtig: Beachten Sie die Funktion SMB Caching, welche speziell bei SMB/CIFS im WAN und Azure als SMB-Server eine Rolle spielt.

Download und Anwendung

Ursprünglich entstand das Skript als VBScript. Mittlerweile habe ich auf PowerShell umgestellt, die aber von der Funktion her identisch sind. Sie können die Skripte ja vergleichen. Gerade die Verarbeitung von Kommandozeilenparametern ist denkbar einfacher. Auch die Event-Log Ausgabe.

end2end-file.20190722.ps1

Ich kann zwar das Skript kostenfrei zum Download anbieten, allerdings müssen Sie schon selbst überlegen, von welchen Systemen aus auf welche andere Systeme Sie einen Test laufen lassen wollen und wie Sie die Daten am Ende auswerten und interpretieren. Das Skript misst einfach nur.

Das Skript beschreibt permanent eine 10 Kilobyte Datei und misst die hierfür benötigte Zeit. Um den Server nicht zu überlasten, wird dann eine kurze Pause (100ms) eingelegt, so dass dieses Skript eine Dauerlast von ca. 100kByte/Sek = 1 Megabit produziert. Dies sollte einen aktuellen Server nicht beeinträchtigen. Die benötigte Zeit wird gespeichert und gemittelt, so dass ein "Durchschnitt" vorhanden ist. Weicht ein Zugriff nun sehr stark davon ab, wird die erkannt und eine Meldung hinterlassen.

Die Funktion des Skripts ist eigentlich ganz einfach. Um jedoch den Netzwerkzugriff zu testen, muss es auf einem Client oder anderen Server gestartet werden. Soll dies nicht interaktiv erfolgen, muss das Skript mit SRVANY, dem Windows Taskplaner oder anderen Tools als "Dienst" implementiert werden.

Achtung
Um in das Eventlog zu schreiben, muss das PowerShell-Skript als Administrator laufen oder Sie vergeben explizit die Berechtigungen. Solche Dinge übernimmt bei Programmen in der Regel die Setup-Routine.

Windows Eventlog

Übrigens protokolliert auch Windows die ein oder andere Statistik im Eventlog. Ich kann leider nicht sagen, seit welcher Version dies erfolgt, aber auf meinem Windows 10 1903 Client finde ich:

Protokollname: Microsoft-Windows-Ntfs/Operational
Quelle:        Microsoft-Windows-Ntfs
Datum:         22.07.2019 15:21:16
Ereignis-ID:   146
Aufgabenkategorie:Keine
Ebene:         Informationen
Schlüsselwörter:Statistik
Benutzer:      SYSTEM
Computer:      fcyova.uclabor.de
Beschreibung:
IO-Latenzzusammenfassung:

           Version: 2
           Volumen-ID: {e08de796-4bb3-4479-82e3-3654d710d298}
           Volumenname: C:
           Rang-Index: 0

           Maximal akzeptable IO-Latenz: 30000 ms

           Latenzzeitfenster – Lesen/Schreiben (ns): [5000000, 30000000, 100000000, 0, 0, 0, 0]
           Latenzzeitfenster – Kürzen (ns): [10000000, 50000000, 100000000, 0, 0, 0, 0]
           Latenzzeitfenster – Leeren (ns): [10000000, 50000000, 100000000, 0, 0, 0, 0]

           Intervalldauer: 3616778500 us

           Nicht zwischengespeicherte Lesevorgänge: 
                     Anzahl IO-Vorgänge: 15846
                     Bytes insgesamt: 466924065
                     Durchschnittliche Latenzzeit: 392116 ns

           Nicht zwischengespeicherte Schreibvorgänge: 
                     Anzahl IO-Vorgänge: 26089
                     Bytes insgesamt: 629773015
                     Durchschnittliche Latenzzeit: 847601 ns

           Dateileerungen: 
                     Anzahl IO-Vorgänge: 2299
                     Durchschnittliche Latenzzeit: 3204909 ns

           Verzeichnisleerungen: 
                     Anzahl IO-Vorgänge: 0
                     Durchschnittliche Latenzzeit: 0 ns

           Volumenleerungen: 
                     Anzahl IO-Vorgänge: 0
                     Durchschnittliche Latenzzeit: 0 ns

           Kürzungen auf Dateiebene: 
                     Anzahl IO-Vorgänge: 0
                     Bytes insgesamt: 0
                     Anzahl Ausweitungen: 0
                     Durchschnittliche Latenzzeit: 0 ns

           Volumenkürzungen: 
                     Anzahl IO-Vorgänge: 338
                     Bytes insgesamt: 419864576
                     Anzahl Ausweitungen: 1311                     Durchschnittliche Latenzzeit: 3052739 ns

 Weitere Informationen finden Sie auf der Registerkarte "Details".

Ereignis-XML:
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
  <System>
    <Provider Name="Microsoft-Windows-Ntfs" Guid="{3ff37a1c-a68d-4d6e-8c9b-f79e8b16c482}" />
    <EventID>146</EventID>
    <Version>2</Version>
    <Level>4</Level>
    <Task>0</Task>
    <Opcode>0</Opcode>
    <Keywords>0x4000000000200000</Keywords>
    <TimeCreated SystemTime="2019-07-22T13:21:16.115727200Z" />
    <EventRecordID>69</EventRecordID>
    <Correlation />
    <Execution ProcessID="4" ThreadID="4004" />
    <Channel>Microsoft-Windows-Ntfs/Operational</Channel>
    <Computer>fcyova.uclabor.de</Computer>
    <Security UserID="S-1-5-18" />
  </System>
  <EventData>
    <Data Name="Version">2</Data>
    <Data Name="VolumeCorrelationId">{e08de796-4bb3-4479-82e3-3654d710d298}</Data>
    <Data Name="VolumeNameLength">2</Data>
    <Data Name="VolumeName">C:</Data>
    <Data Name="IsBootVolume">true</Data>
    <Data Name="TierIndex">0</Data>
    <Data Name="MaxLatencyMs">30000</Data>
    <Data Name="ReadWriteLatencyBucket1">5000000</Data>
    <Data Name="ReadWriteLatencyBucket2">30000000</Data>
    <Data Name="ReadWriteLatencyBucket3">100000000</Data>
    <Data Name="ReadWriteLatencyBucket4">0</Data>
    <Data Name="ReadWriteLatencyBucket5">0</Data>
    <Data Name="ReadWriteLatencyBucket6">0</Data>
    <Data Name="ReadWriteLatencyBucket7">0</Data>
    <Data Name="TrimLatencyBucket1">10000000</Data>
    <Data Name="TrimLatencyBucket2">50000000</Data>
    <Data Name="TrimLatencyBucket3">100000000</Data>
    <Data Name="TrimLatencyBucket4">0</Data>
    <Data Name="TrimLatencyBucket5">0</Data>
    <Data Name="TrimLatencyBucket6">0</Data>
    <Data Name="TrimLatencyBucket7">0</Data>
    <Data Name="FlushLatencyBucket1">10000000</Data>
    <Data Name="FlushLatencyBucket2">50000000</Data>
    <Data Name="FlushLatencyBucket3">100000000</Data>
    <Data Name="FlushLatencyBucket4">0</Data>
    <Data Name="FlushLatencyBucket5">0</Data>
    <Data Name="FlushLatencyBucket6">0</Data>
    <Data Name="FlushLatencyBucket7">0</Data>
    <Data Name="HighIoLatencyCount">0</Data>
    <Data Name="IntervalDurationUs">3616778500</Data>
    <Data Name="NCReadIOCount">15846</Data>
    <Data Name="NCReadTotalBytes">466924065</Data>
    <Data Name="NCReadAvgLatencyNs">392116</Data>
    <Data Name="NCWriteIOCount">26089</Data>
    <Data Name="NCWriteTotalBytes">629773015</Data>
    <Data Name="NCWriteAvgLatencyNs">847601</Data>
    <Data Name="FileFlushCount">2299</Data>
    <Data Name="FileFlushAvgLatencyNs">3204909</Data>
    <Data Name="DirectoryFlushCount">0</Data>
    <Data Name="DirectoryFlushAvgLatencyNs">0</Data>
    <Data Name="VolumeFlushCount">0</Data>
    <Data Name="VolumeFlushAvgLatencyNs">0</Data>
    <Data Name="FileLevelTrimCount">0</Data>
    <Data Name="FileLevelTrimTotalBytes">0</Data>
    <Data Name="FileLevelTrimExtentsCount">0</Data>
    <Data Name="FileLevelTrimAvgLatencyNs">0</Data>
    <Data Name="VolumeTrimCount">338</Data>
    <Data Name="VolumeTrimTotalBytes">419864576</Data>
    <Data Name="VolumeTrimExtentsCount">1311</Data>
    <Data Name="VolumeTrimAvgLatencyNs">3052739</Data>
    <Data Name="IoBucketsCount">33</Data>
    <Data Name="TotalBytesBucketsCount">31</Data>
    <Data Name="ExtentsBucketsCount">2</Data>
    <Data Name="IoCount">117</Data>
    <Data Name="IoCount">66</Data>
    <Data Name="IoCount">6461</Data>
    <Data Name="IoCount">306</Data>
    <Data Name="IoCount">151</Data>
    <Data Name="IoCount">135</Data>
    <Data Name="IoCount">50</Data>
    <Data Name="IoCount">62</Data>
    <Data Name="IoCount">2413</Data>
    <Data Name="IoCount">10018</Data>
    <Data Name="IoCount">14</Data>
    <Data Name="IoCount">6362</Data>
    <Data Name="IoCount">409</Data>
    <Data Name="IoCount">298</Data>
    <Data Name="IoCount">6</Data>
    <Data Name="IoCount">10740</Data>
    <Data Name="IoCount">833</Data>
    <Data Name="IoCount">6457</Data>
    <Data Name="IoCount">407</Data>
    <Data Name="IoCount">5</Data>
    <Data Name="IoCount">19</Data>
    <Data Name="IoCount">72776</Data>
    <Data Name="IoCount">2</Data>
    <Data Name="IoCount">9254</Data>
    <Data Name="IoCount">1</Data>
    <Data Name="IoCount">1324</Data>
    <Data Name="IoCount">3</Data>
    <Data Name="IoCount">14314</Data>
    <Data Name="IoCount">181</Data>
    <Data Name="IoCount">323</Data>
    <Data Name="IoCount">15</Data>
    <Data Name="IoCount">2155</Data>
    <Data Name="IoCount">144</Data>
    <Data Name="TotalLatencyUs">179432200</Data>
    <Data Name="TotalLatencyUs">599766900</Data>
    <Data Name="TotalLatencyUs">1649265200</Data>
    <Data Name="TotalLatencyUs">2650608400</Data>
    <Data Name="TotalLatencyUs">225418500</Data>
    <Data Name="TotalLatencyUs">1170836400</Data>
    <Data Name="TotalLatencyUs">96564600</Data>
    <Data Name="TotalLatencyUs">538047100</Data>
    <Data Name="TotalLatencyUs">38728000</Data>
    <Data Name="TotalLatencyUs">259674100</Data>
    <Data Name="TotalLatencyUs">125329100</Data>
    <Data Name="TotalLatencyUs">1363736600</Data>
    <Data Name="TotalLatencyUs">3486745300</Data>
    <Data Name="TotalLatencyUs">69835500</Data>
    <Data Name="TotalLatencyUs">52253100</Data>
    <Data Name="TotalLatencyUs">3052253200</Data>
    <Data Name="TotalLatencyUs">7198636700</Data>
    <Data Name="TotalLatencyUs">1180668500</Data>
    <Data Name="TotalLatencyUs">3449500800</Data>
    <Data Name="TotalLatencyUs">1182700</Data>
    <Data Name="TotalLatencyUs">4781700</Data>
    <Data Name="TotalLatencyUs">619925100</Data>
    <Data Name="TotalLatencyUs">17272900</Data>
    <Data Name="TotalLatencyUs">87312200</Data>
    <Data Name="TotalLatencyUs">8143200</Data>
    <Data Name="TotalLatencyUs">431081700</Data>
    <Data Name="TotalLatencyUs">24400300</Data>
    <Data Name="TotalLatencyUs">4157331800</Data>
    <Data Name="TotalLatencyUs">1594697700</Data>
    <Data Name="TotalLatencyUs">717499100</Data>
    <Data Name="TotalLatencyUs">314327000</Data>
    <Data Name="TotalLatencyUs">5786824900</Data>
    <Data Name="TotalLatencyUs">1581261600</Data>
    <Data Name="TotalBytes">15577088</Data>
    <Data Name="TotalBytes">17367040</Data>
    <Data Name="TotalBytes">48422400</Data>
    <Data Name="TotalBytes">13423104</Data>
    <Data Name="TotalBytes">1175552</Data>
    <Data Name="TotalBytes">649728</Data>
    <Data Name="TotalBytes">65536</Data>
    <Data Name="TotalBytes">82432</Data>
    <Data Name="TotalBytes">69653851</Data>
    <Data Name="TotalBytes">101969968</Data>
    <Data Name="TotalBytes">2942838</Data>
    <Data Name="TotalBytes">54908782</Data>
    <Data Name="TotalBytes">2543656</Data>
    <Data Name="TotalBytes">6582272</Data>
    <Data Name="TotalBytes">49152</Data>
    <Data Name="TotalBytes">422377389</Data>
    <Data Name="TotalBytes">45154094</Data>
    <Data Name="TotalBytes">56307708</Data>
    <Data Name="TotalBytes">2539520</Data>
    <Data Name="TotalBytes">266240</Data>
    <Data Name="TotalBytes">73216</Data>
    <Data Name="TotalBytes">82084140</Data>
    <Data Name="TotalBytes">36864</Data>
    <Data Name="TotalBytes">41806525</Data>
    <Data Name="TotalBytes">4096</Data>
    <Data Name="TotalBytes">89596092</Data>
    <Data Name="TotalBytes">12288</Data>
    <Data Name="TotalBytes">373012669</Data>
    <Data Name="TotalBytes">3963560</Data>
    <Data Name="TotalBytes">211484672</Data>
    <Data Name="TotalBytes">208379904</Data>
    <Data Name="TrimExtentsCount">786</Data>
    <Data Name="TrimExtentsCount">525</Data>
    <Data Name="IoTypeIndex">0</Data>
    <Data Name="IoTypeIndex">1</Data>
    <Data Name="IoTypeIndex">4</Data>
    <Data Name="IoTypeIndex">5</Data>
    <Data Name="IoTypeIndex">8</Data>
    <Data Name="IoTypeIndex">9</Data>
    <Data Name="IoTypeIndex">12</Data>
    <Data Name="IoTypeIndex">13</Data>
    <Data Name="IoTypeIndex">16</Data>
    <Data Name="IoTypeIndex">20</Data>
    <Data Name="IoTypeIndex">21</Data>
    <Data Name="IoTypeIndex">28</Data>
    <Data Name="IoTypeIndex">29</Data>
    <Data Name="IoTypeIndex">32</Data>
    <Data Name="IoTypeIndex">33</Data>
    <Data Name="IoTypeIndex">36</Data>
    <Data Name="IoTypeIndex">37</Data>
    <Data Name="IoTypeIndex">44</Data>
    <Data Name="IoTypeIndex">45</Data>
    <Data Name="IoTypeIndex">48</Data>
    <Data Name="IoTypeIndex">52</Data>
    <Data Name="IoTypeIndex">56</Data>
    <Data Name="IoTypeIndex">57</Data>
    <Data Name="IoTypeIndex">60</Data>
    <Data Name="IoTypeIndex">61</Data>
    <Data Name="IoTypeIndex">64</Data>
    <Data Name="IoTypeIndex">65</Data>
    <Data Name="IoTypeIndex">68</Data>
    <Data Name="IoTypeIndex">69</Data>
    <Data Name="IoTypeIndex">0</Data>
    <Data Name="IoTypeIndex">1</Data>
    <Data Name="IoTypeIndex">4</Data>
    <Data Name="IoTypeIndex">5</Data>
  </EventData>
</Event>

Windows trackt selbst auch schon die ein oder andere Zugriffe mit, so dass sie auch diese Datenquellen anzapfen können. Ich habe allerdings noch nicht weiter nachgeschaut, was die vielen gleichen Einträge mit unterschiedlichen Werten zu interpretieren sind.

Weitere Links