Exchange Latenz und Outlook Performance

Auf der Seite Outlook langsam haben ich beschrieben , warum Outlook manchmal langsam erscheint. Mal abgesehen von langsamen Clients aufgrund großer OST-Dateien auf langsamen Disks mit zu wenige RAM und CPU und vielen Add-ons gibt es natürlich auch immer mehr performante Systeme, die schnelle CP Us mit „genug“ Ram (4Gb ist heute ja schon Standard und für 32bit Outlook mehr als genug) und schnellen SSDs angebunden sind. Dennoch klemmt es hin und wieder. Diese Seite beschreibt weitere Möglichkeiten zur Analyse.

Der erste Teil bis zum Server ist auch für On-Premises-Installationen interessant. Aber alle weitere Auswertungen sind aktuell noch nicht in Office 365 möglich.

Outlook Cache, Views und Threads

Zuerst müssen Sie sich noch mal in Erinnerung rufen, dass Outlook am besten mit einem lokalen Cache (OST-Datei) genutzt wird. Es macht einfach keinen Sinn, wenn Anwender immer wieder die gleichen üb er das LAN Daten vom Server abrufen, nur weil sie zwischen Kalender, Kontakte und Posteingang springen. Das primäre Postfach muss mit wenigen Sonderfällen wirklich im Cached-Mode betrieben werden. Der Engpass ist dann eigentlich immer nur die lokale Disk, wenn die OST größer und fragmentierter wird.

Aber es gibt auch Daten, die nicht in der OST-Datei landen oder landen sollten. So sind z.B. Kalender von Teammitgliedern in de r Regel nicht im Cache und auch der Zugriff auf „Shared MailboxenR 20; werden viele im Cache ausschließen. Es macht ebenso wenig Sinn jede Änderung in einem gemeinsam genutzten Eingang b ei allen berechtigten Personen in die OST-Datei zu synchronisieren. Das provoziert zudem Synchronisationskonflikte und Mehrfachbearbeitungen.

Genau das sind aber die Fälle, in denen Outlook dann auch mal blockiert. Wenn der Anwender auf einen Ordner dort klickt, dann muss Outlook die Daten vom Exchange Server holen. Beim ersten Mal muss Outlook sogar alle Elemente laden, die in der eingestellten Ansicht (View) darzustellen sind. Diese Ansicht wird von Outlook dann aber wieder in der OST-Datei mit gespeichert. Das beinhalt et aber nicht die Elemente selbst. Wenn der Benutzer nun einige Zeit später „wieder kommt“, dann fragt Outlook wieder beim Server nach, ob sich etwas geändert hat. Wenn das nicht der Fall ist, dann zeigt Outlook die vorherige Ansicht einfach wieder an. Wurde aber was geändert, was bei Kalendern und „Shared Mailboxes“ eher wahrscheinlich ist, dann muss Outlook die Änderungen abfragen um die neue Ansicht generieren zu können. Und in der Zeit "blockiert“ Outlook und es ist ein direkter Bezug zur Reaktionszeit des Servers vorhanden.

Microsoft hat hier zwei Grenzwerte:
Wenn Exchange länger als 100ms für die Antwort eines Request braucht ist es zu lange.
Wenn Outlook länger als 5 Sekunden nicht mehr auf Windows Messages reagiert, dann sieht der Anwender ein "Hängen", weil das Fenster grau wird.

Stationen und Latenzzeit

Ich beschränke mich nun mal auf Exchange 2013 und höher mit Outlook und dass dabei eben nur noch die Protokolle RPC/HTTP oder MAPI/HTTP genutzt werden. Für POP3/IMAP4 passt dieses Bild nicht und ActiveSync ist bezüglich einer "langsamen Reaktion" auch nicht im Scope. Wenn eine Mail auf ein Mobilgerät erst nach Minuten oder Stunden kommt, dann ist das meist nicht eine schlechten Exchange Performance geschuldet. Gerade "letzte Änderungen" sind in der Regel eh noch im Exchange Cache und damit schnell ausgeliefert. Wenn ihr Outlook aber wie oben beschrieben, ab und an auf Kalender oder Shared Mailboxen zugreift und es "langsam" erscheint, dann bewegen wir uns im Bereich von Sekunden, die für Anwender natürlich zu lange dauern. Ich habe hier einmal versucht alle Stationen eines Outlook bis zum Postfach zu skizzieren.

Wie schnell Outlook nun wieder zur Verfügung steht, hängt von der Geschwindigkeit an, mit der das Backend, also die Server, auf Anfragen antworten und die Antwort beim Server ankommt. Ich beschreibe hier die Stationen und häufige Fehlkonfigurationen, die vorab ausgeschlossen werden sollten, ehe Sie dann weiter unten die verschiedenen Stationen bezüglich einer Latenzmessung analysieren.

  • Outlook Client
    Der Outlook 2016 ist die Schnittstelle zum Anwender und Auslöser der Anfragen. Es gibt einige Möglichkeiten der Protokollierung aber oft sind es auch Add-ons, die Outlook langsamer machen.
  • HTTP-Proxy
    Durch die Nutzung von von HTTP als Übertragungsprotokoll können durchaus entsprechende HTTP-Proxy-Systeme als Relay involviert sein. Das ist in einem internen LAN meist nicht der Fall aber auch die ein oder andere Fehlkonfiguration habe ich schon mal gesehen, dass der Name es Exchange Zugangspunkt nicht ausgenommen war, so dass Clients einer Niederlassung über den lokalen Proxy ins Internet und dann wieder von außen auf den Exchange Server Zugegriffen haben. Manchmal sind es auch Add-on-Produkte wie ein Cloud Proxy (Z-Scaler und andere) die den Verkehr nach draußen leiten. Über NetMon auf dem Client oder die Kontrolle der Client-IP auf dem Weg zum Exchange kann so eine Fehlkonfiguration entdeckt werden
  • LAN/WAN
    Auf dem Weg von Client zum Server ist zum einen ein LAN/WAN mit optionaler Optimierung, z.B.: Riverbed) oder ein Weg über ein IPSEC VPNs (Internet) zu bedenken. Diese Systeme "Optimieren", indem sie z.B. Pakete zusammenfassen aber dadurch natürlich auch verzögern. Meist überwiegt aber der Vorteil eben durch Kompression und Bandbreitenvermeidung. Langsamer zu starten aber dann den Durchsatz zu erhöhen kann am Ende doch schneller sein.
  • Firewall/Reverse Proxy
    Es gibt nicht nur den Proxy auf der Client-Seite sondern auch auf der Server Seite werden gerne Schutz- und Filterprogramme eingesetzt. Das kann ein einfacher Reverse Proxy mit URL-Filterung sein aber auch eine Next Generation Firewall, die sich die Pakete gerne sehr genau anschaut. Teilweise inklusive SSL-Decodierung. Das dauert natürlich "Zeit". Gerade Firewalls werden auch intern gerne zur Trennung "Clients" und "Datacenter" eingesetzt.
  • Loadbalancer
    Wer mehr als einen Exchange Server betreibt, muss die HTTP-Zugriffe auf die Server verteilen und sollte dies so machen, dass nur funktionsfähige Server Anfragen bearbeiten und die Last auch gleichmäßig verteilt wird. DNS Round Robin hat einige Einschränkungen aber auch ein Loadbalancer ist natürlich eine Komponente in der Kette, die idealerweise nur wenige Millisekunden kostet. Aber wenn der Loadbalancer auch zugleich Default Gateway oder generell zu schwach dimensioniert ist, dann kann es hier schon zu nennenswerten Verzögerungen kommen..
  • Exchange Frontend
    Der IIS auf dem Exchange Frontend Server nimmt die Anfragen an und bearbeitet diese über den Application-Pool. Er erzwingt eine Authentifizierung und ermittelt den Backend Server, welcher die aktive Datenbank betreibt. Er reicht dann den Request zum Backend weiter. Diese aktive Verarbeitung benötigt natürlich etwas Zeit.
  • Exchange Backend
    Die eigentliche Arbeit führt aber der Backend-Server aus. Auch hier nimmt ein IIS die Anfragen vom Frontend an und der Information Store muss letztlich die Daten aus den Datenbanken auf den Massenspeicher lesen und schreiben. Hierbei nutzt der Prozess natürlich Caching um kürzlich veränderte Informationen schnell bereitstellen zu können. Beim Schreiben oder beim Zugriff auf ältere Daten ist die Latenz des Disk-Subsystems eine kritische Komponente

An verschiedenen Stellen kann mit unterschiedlichen Werkzeugen gemessen und ausgewertet werden, wie der einzelne Request durch die Systeme läuft und wo letztlich die Zeit benötigt wird.

Auswertung mit Outlook RPC

Die meisten Administratoren aber auch Benutzer sind sich gar nicht bewusst, dass Outlook von Hause aus schon einige Kennzahlen mitschreibt. Outlook zeigt diese über das RPCDiag-Fenster auch an, welches über das Outlook Icon über CTRL + Rechte Maustaste" oder als Parameter "/RPCDIAG" beim Aufruf mit geöffnet werden kann.

Wenn Sie das Fenster dann etwas zurechtrücken, dann erscheinen zwei Spalten, die eine erste Aussage zur Verbindung zu lassen.

  • Durchschnittliche Bearbeitungszeit (in ms)
    Dieser Wert wird vom Exchange Server an den Client in der Antwort mitgeliefert und sagt aus, wie lange der Server an der Antwort im Mittel zu arbeiten hatte. Sie sehen hier einige Verbindungen zu meinem On-Premises-Postfach bei Net at Work, während ich zuhause gearbeitet habe. Die Antwortzeiten des Servers sind also mit 6-32ms absolut im grünen Bereich. Die eine Verbindung zum Office 365 Postfach braucht 40ms. Microsoft sagt, dass hier je nach Dokument 80ms bis 100ms in Ordnung sind.
  • Durchschnittliche Reaktionszeit (in ms)
    Hier protokolliert Outlook die durchschnittliche Dauer in Millisekunden, die Anfragen bei dieser Verbindung benötigt haben. Es ist also ein "Ende zu Ende"-Werte, der alle Komponenten mit einbezieht. Wenn Sie dann die Bearbeitungszeit abziehen, haben Sie einen ersten Anhaltspunkt für die durchschnittliche Laufzeit (Roundtrip) der Pakete

Ich weise aber extra noch mal darauf hin, dass es sich um einen Durchschnittswert der individuellen Verbindung handelt. Die Zahlen sind ein erster Hinweis aber erlauben nicht die Reaktionszeit einzelner langsamer Anfragen zu finden.

Als Indikator für einen generell langsamen Server oder eine schlechte Leitung können diese Zahlen aber schon dienen, wenn z.B. die Bearbeitungszeit über 100ms ist und die Reaktionszweit sehr hoch ist.

Allerdings sind die Counter auch immer mit Vorbehalt zu betrachten, denn auch bei MAPI/HTTP und RPC/HTTP gibt es Anfragen, die vom Server absichtlich erst verspätet ausgeliefert werden. Wenn Outlook "fertig" ist dann stellt es nämlich eine "NotifyWait"-Anfrage an den Server. Der Server antwortet darauf aber erst, wenn sich auch etwas geändert hat. Das ist die Art "Push Notification", die Outlook und Exchange nutzen. Ein UDP-Paket zu Zeiten von Exchange 2003 und früher funktioniert eigentlich nur noch in internen gerouteten Netzwerken.

Auswertung mit Outlook Perfmon

Diese Counter stellt Outlook übrigens auch als Performance Counter bereit. Allerdings wird Outlook üblicherweise von einem "Anwender "gestartet, der kein lokaler Administrator ist. Daher kann er die Counter gar nicht anlegen und das Office Setup hat diese ebenfalls nicht angelegt. Wenn Sie aber Outlook einmalig als "Administrator" starten, dann werden die Counter angelegt. Alternativ können Sie den Benutzer in die Gruppe "Leistungsprotokollbenutzer" addieren.

Allerdings sind die Zahlen genauso nur beschränkt für eine Fehlersuche hilfreich wie die Daten des RPCDIAG-Fensters. eine Unterscheidung nach Connection ist nicht sichtbar und die Durchschnittszeiten sind schon mal gruppiert. Zudem bin ich nicht sicher, ob die Daten auch sauber aktualisiert werden, wenn Outlook danach wieder als normaler User gestartet wird. Was die Counter letztlich auf einem Terminal Server anzeigen würden, habe ich nicht weiter verfolgt.

Auswertung mit Outlook und Fiddler

Durch die Verwendung von HTTPS als einziges Transport-Protokoll seit Exchange 2013/2016 eröffnen sich natürlich auch auf dem Client neue Optionen. Insbesondere die Analyse mit mit Fiddler und aktivierter HTTPS-Decryption erlaubt eine sehr genaue Analyse des HTTP-Verkehrs. Wenn Sie Fiddler aktiv haben, sehen Sie alle Requests des Clients. Hier lassen sich die Zugriffe auf "/mapi" nicht verbergen:

Sie sehen hier auch am Anfang wieder mehrere 401 bis die Authentifizierung erfolgreich gelaufen ist. Interessanterweise werde aber dann die folgenden Requests nicht mehr mit einem Authentication-Header gesendet, sondern einfach so beantwortet. Schaut man sich so einen Request man genauer an, dann sehen Sie viele Felder. Es gibt einige Cookies, die anscheinend dem Backend Server beweisen, dass der Zugriff bereits authentifiziert ist.

Interessant finde ich den Cookie "MapiRouting", den man mit dem Text Wizard von Fiddler mal schnell von BASE64 nach TXT konvertieren kann. Ich bin mir ziemlich sicher, dass dieses Prefix "RUM" gefolgt von einer GUID von jedem Frontend "verstanden" wird um den Client gleich zum richtigen Backend zu senden.

Interessant sind weiterhin die grün umrissenen weiteren Headerfelder. Sie kennzeichnen den Request per GUID und diese Werte brauchen wir später noch. In dem Zuge ist auch der "X-RequestType" interessant. Hiervon habe ich die folgenden Werte gefunden.

RequestType Bedeutung

Connect

Diesen RequestType habe ich bislang immer am Anfang einer Verbindung gesehen.

Execute

Die Mehrzahl der Request sind EXECUTE-Requests, bei denen Exchange etwas tun muss. Das kann Lesen aber auch schreiben sein

NotifyWait

Diese Meldungen haben oft eine bis zu 10 Minuten Latenzzeit. Outlook registriert sich für Änderungen und Exchange verzögert den Abruf, bis dies gelingt. Diese Werte müssen bei der Latenzermittlung ignoriert werden.

QueryRows

Laut MSDN eine Anfrage an das Adressbuch

DNToMid

Outlook fordert eine Auflösung eines "DistinguishedName" an eine MinID

ResolveNames

Auflösung von Empfängern

Ping

Ich vermute es handelt sich einfach um einen Verbindungstest zum "am Leben erhalten" einer http-Connection

Bind

Verbindet sich mit dem Adressbuch

Logoff

Diesen Request-Type habe ich bislang immer am Ende  einer Verbindung gesehen

Die Unterscheidung dieser verschiedenen MAPI-Befehle ist wichtig für die spätere Auswertung, da nicht alle Befehle unbedingt eine kurze Latenzzeit haben müssen. Es gibt aber durchaus noch einige mehr.

Die Reaktionszeit jeder einzelnen HTTP-Connection kann auch Fiddler mit ausgeben. Über die Karteikarte "Statistics" sind die verschiedenen Zeitpunkte und damit auch die Dauer zu ermitteln.

Das kann schon mal ein erster Hinweise auf "sehr lange Laufzeiten" sein. Wer mag, kann diese Zeiten auch in der tabellarischen Übersicht mit anzeigen lassen, indem er auf die Spaltenköpfe per rechter Maustaste die Felder addiert:

Das macht die Suche nach Langläufern etwas einfacher.

So können sie zwar etwas mühselig aber allein auf dem Client ohne weiteren Hilfsmittel die Antwortzeit des Servers auf jeden einzelnen Request dieses individuellen Clients auswerten.

Outlook Dump

Aus Sicht von Microsoft "Hängt" eine Applikation, wenn Sie 5 Sekunden nicht mehr auf eine Windows Message reagiert, d.h. wenn Sie in einer Applikation eine Aktion ausführen, dann sendet Windows ja z.B. ein "Maus wurde gedrückt" Event an die Applikation. Die Applikation muss dann darauf reagieren und eine Rückmeldung geben. Wenn dies länger als 5 Sekunden dauert, dann kann das einen Dump auslösen. Dazu benötigen Sie das Programm "PROCDUMP".

Procdump
https://technet.microsoft.com/en-us/sysinternals/dd996900.aspx
Download: https://download.sysinternals.com/files/Procdump.zip

Sie laden das Programm herunter und packen es aus. Dann müssen Sie als Administrator über eine Kommandozeile folgendes ausführen

procdump -h -ma Outlook.exe

Procdump klemmt sich dann an den Prozess "Outlook.exe" und wartet auf genau diesen Moment. Wenn Outlook dann über 5 Sekunden "Hängt", wird ein DUMP des Prozess geschrieben. Diesen Dump kann dann Microsoft auswerten.

Netsh Capture

Ebenso kann ein Mitschnitt des Netzwerkverkehrs zu Hinweisen führen. Zwar sind alle Übertragungen als solches schon einmal verschlüsselt. Das gilt für RPC/TCP genauso wie für RPC/HTTPs und MAPI/HTTPs. Die beiden letzten Protokolle nutzen HTTPS und können sehr gut mit "Fiddler" analysiert werden. Mit NETSH ist wieder eine CMD-Shell als Administrator erforderlich:

REM Start des Trace
netsh trace start scenario=netconnection capture=yes report=yes

REM nun versuchen den Fehler in Outlook nachzustellen und danach Outlook möglichst schnell beenden

REM Trace danach stoppen
netsh stop trace

Die netsh-Logs werden im Verzeichnis %TEMP%\NetTraces\ des Anwenders gespeichert. Auch diese Traces kann ein Microsoft Support zur Analyse heranziehen. Einige der Dateien können Sie natürlich auch selbst analysieren.

NetSH legt neben der nettrace.etl-Datei, noch eine CAB-Datei an, in der umfangreiche Ausgaben protokolliert sind, die insbesondere für eine Ferndiagnose hilfreich sein können. Interessant sind hier die Text-Dateien mit der lokalen Konfiguration. Aber auch die mitgeschnittenen Pakete können hilfreich sein um z.B. Verbindungsabbrüche o.ä. zu erkennen. Die ETL-Dateien können z.B. mit dem Microsoft Message Analyzer analysiert werden.

Sonstige Outlook Ausweitungsmöglichkeiten

Damit sind die Auswertemöglichkeiten aber immer noch nicht erschöpft. Ein Weg etwaige Outlook Probleme zu erkennen ist die Funktion von OffCAT

Ansonsten gibt es in den Outlook Optionen noch die Protokollierung.

Allerdings können nach meinem Kenntnisstand die geschriebenen ETL-Traces nur von Microsoft im Rahmen eines Support Ticket ausgewertet werden.

Logging auf dem Weg

Für einen Exchange Admin oder Helpdesk wird es kaum möglich auf dem LAN oder WAN entsprechenden Messwerte zu erfassen. Es ist selbst für gestandene Netzwerk-Administratoren nicht einfach die Performance einer Anwendung nur anhand von Aufzeichnungen auf dem Netzwerk zu ermitteln. Meist liefern die System nur Daten zur Auslastung der Leitung Aber nicht zu den Laufzeiten/Roundtrip der Pakete. Router und Switches sind hier meist über fordert und nicht jeder hat eine höherwertige Firewall oder gar WAN-Optimierer, die Applikationen unterscheiden und messen.

Inwieweit auf Firewalls, Proxy-Servern und einem Loadbalancer überhaupt solche Kennzahlen erfasst werden, ist produktabhängig. Natürlich können auf auf dem Weg mit NetMon, Wireshark oder anderen Tools einfach die Pakete mitschneiden und anhand der Zeitpunkte die Laufzeiten ermitteln. Das ist nicht wirklich einfach aus der Menge der Pakete die fraglichen Pakete zu ermitteln. Speziell wenn der Loadbalancer ohne Affinität arbeitet, können auf dem Exchange Server kaum noch sinnvoll mitschneiden. Eine Filterung auf die Inhalte ist aufgrund der Verschlüsselung (HTTPS) nur mit einem erhöhten Aufwand möglich.

Sie sollten daher andere Quellen für eine Performance Analyse und Fehlersuche vorziehen. Die Analyse von Netzwerkinformationen ist erst einmal zu aufwändig im Verhältnis zu den Daten. Einzig für HTTP-Proxy-Logs könnte man eine Ausnahme machen.
Interessant sind seitens des Netzwerks natürlich die leicht zu erhaltenen Auslastungsinformationen von WAN-Links oder die Erreichbarkeit einfacher PING-Tests.

Solange Sie aber Zugriff auf den Exchange Server haben, können Sie als Exchange Administrator dort durchaus interessante Daten ermitteln.

Exchange Frontend und Backend Übersicht

Bei Exchange 2013 und neuer landen die Clients über einen Loadbalancer auf dem Frontend Server, früher als CAS = Client Access Service bezeichnet. Der IIS nimmt die Anfragen der Clients entgegen und leitet diese an den Proxy-Prozess von Exchange weiter, welcher entscheiden, auf welchem "Backend"-System die gewünschte Information gerade "aktiv" ist. Der Frontend gibt dann die Anfrage an den Backend weiter. Auch dort nimmt die IIS-Instanz die Daten entgegen und leitet diese entsprechend der URL an die jeweilige Applikation. Sowohl MAPIHTTP also auch RPCHTTP nutzen im Hintergrund natürlich weiter die Schnittstelle zum Microsoft Exchange Informationsstore (IS)

Diese "beiden" IIS-Instanzen laufen seit Exchange 2016 auch immer auf dem gleichen Server aber sind an unterschiedliche IP-Ports gebunden. So ist eine klare Trennung von vorneherein sichergestellt. Entsprechend gibt es auch getrennte Sätze für die IISLogs und Performance Counter.

Aber auch die Exchange Komponenten haben eigene Performance Counter und Logdateien.

Performance Counter sind wir fast immer nur "Mittelwerte" und daher nur dann hilfreich, wenn etwas generell langsamer oder zäher als erwartet oder versprochen ist. Wenn es darum geht auch einzelne Requests zu analysieren, dann bleibt nur die Analyse von Protokolldateien,

Bei den Protokoll-Dateien gibt es nun gleich mehrere interessante Pfade

Datenquelle Standard-Pfad Interessante Felder

Frontend IIS-Log

C:\inetpub\logs\LogFiles\W3SVC1

  • cs-uri-query
    Enthält den Request-String des Clients mit der X-RequestID
  • time-taken
    Die Dauer bis zur vollständigen Übermittlung der Antwort an den Client.

Frontend Exchange HTTP Proxy MAPI/HTTP

und

Frontend Exchange HTTP Proxy RPC/HTTP

$exinstall\Logging\HttpProxy\Mapi\HttpProxy_YYYYMMDDHH-*.log

$exinstall\Logging\HttpProxy\RpcHTTP\HttpProxy_YYYYMMDDHH-*.log

  • DateTime
    Zeitstempel
  • RequestID
    Eindeutige ID der Anforderung, über die diese dann ggfls auch auf dem Backend gefunden werden kann
  • UrlHost
    Hostname des Frontend
  • ClientIpAddress
    IP-Adresse der anfordernden Station. Meist der Client oder Reverse Proxy
  • UserAgent
  • TargetServer
    Hostname des Backend, zu dem der Request weiter geleitet wird
  • ClientRequestId
    Enthält die X-RequestID mit einem "R:"-Prefix
  • BackendProcessingLatency
    Gemessene Verarbeitungsdauer des Request an den Backend
  • RequestHandlerLatency
    Gesamtdauer der Verarbeitung auf dem Frontend

Backend IIS Log

C:\inetpub\logs\LogFiles\W3SVC2

Keine hilfreichen Felder beim MAPI/HTTP

Backend Exchange MAPI/HTTP

Bis Ex2016 CU4 $exinstall\Logging\MAPI Client Access\MapiHttp_YYYYMMDDHH-*.log
Seit Ex2016 CU5 $exinstall\Logging\MapiHttp\Mailbox\MapiHttp_YYYYMMDDHH-*.log

  • RequestID
  • Totalrequestlatency

Backend Exchange RPC/HTTP

$exinstall\Logging\RPC Client Access\RCA_YYYYMMDDHH-*.log

  • RequestID
  • Totalrequestlatency

Die Spalte "interessante Felder" ist ein Auszug der Felder, die für eine weitere Bewertung interessant sind.

Analyse: Start Client Request

Ich nehme mir als Beispiel nun wieder den Request von oben und aus dem Request sehe ich zwei interessante Felder.

  • Request Header: X-ClientInfo: {C62bF819-8709-4EBF-8996-0348269CC4EE}:22
    Die Kennzeichnung bleibt gleich und kann ich in den Server Logs als Filter nutzen. Sie kennzeichnet die Session auf dem Client. Alle Requests zu dieser Session werden mit dieser Nummer geführt. Es gibt also in der Regel mehrere Zeilen
  • Request Header: X-RequestId: {40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:64
    Diese Kennzeichnung wird aber so immer nur einmal verwendet. Die hintere Nummer wird mit jedem Request hochgezählt. Insofern ist diese Nummer ideal um einen Request genau zu finden.

Im passenden Response dazu gibt es zwei Felder:

  • Response Header: X-FEServer: EX01
  • Response Header: X-BEServer: EX01

Dies beiden Felder verraten mir den vom Loadbalancer angesprochenen Frontend Server und den Backend Server, auf dem die Datenbank aktiv war. In dem Beispiel war es zweimal der gleiche Server.

Analyse: Frontend IISLog

Ich starte mit dem IISLOG des Frontend Service und suche nach dem String aus "X-RequestID" {40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:64 und werden natürlich fündig. Hier ein Auszug des IISLogs und sie sehen schon hier die aufsteigende Reihenfolge.

#Software: Microsoft Internet Information Services 8.5
#Version: 1.0
#Date: 2017-04-30 00:00:03
#Fields: date time s-ip cs-method cs-uri-stem cs-uri-query s-port cs-Username c-ip cs(User-Agent) cs(Referer) sc-status sc-substatus sc-win32-status time-taken
2017-04-30 11:34:24 192.168.100.33 POST /mapi/emsmdb/ MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de&CorrelationID=<empty>;&ClientRequestInfo=R:{40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:63;RT:Execute;CI:{C62BF819-8709-4EBF-8996-0348269CC4EE}:22;CID:{8B2F2AC2-9969-47C1-977D-EDED9E7044ED}&cafeReqId=623ebcab-4b94-48ee-b97c-96fa97921e8d; 443 MSXFAQ\fcarius 192.168.100.5 Microsoft+Office/15.0+(Windows+NT+6.1;+ucmapi+15.0.4919;+Pro) - 200 0 0 109
2017-04-30 11:34:24 192.168.100.33 POST /mapi/emsmdb/ MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de&CorrelationID=<empty>;&ClientRequestInfo=R:{40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:64;RT:Execute;CI:{C62BF819-8709-4EBF-8996-0348269CC4EE}:22;CID:{A0B0F28F-2EA9-4F3F-B343-1F402D45EDCE}&cafeReqId=6b21805d-3792-4bbb-a880-ac909fe1802f; 443 MSXFAQ\fcarius 192.168.100.5 Microsoft+Office/15.0+(Windows+NT+6.1;+ucmapi+15.0.4919;+Pro) - 200 0 0 31
2017-04-30 11:34:24 192.168.100.33 POST /mapi/emsmdb/ MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de&CorrelationID=<empty>;&ClientRequestInfo=R:{40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:65;RT:Execute;CI:{C62BF819-8709-4EBF-8996-0348269CC4EE}:22;CID:{A3DE7A97-24DA-4A04-91A1-27711B3BA1CB}&cafeReqId=51bf3121-84ab-4353-b1bf-17570288d2c6; 443 MSXFAQ\fcarius 192.168.100.5 Microsoft+Office/15.0+(Windows+NT+6.1;+ucmapi+15.0.4919;+Pro) - 200 0 0 15
2017-04-30 11:34:24 192.168.100.33 POST /mapi/emsmdb/ MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de&CorrelationID=<empty>;&ClientRequestInfo=R:{40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:66;RT:Execute;CI:{C62BF819-8709-4EBF-8996-0348269CC4EE}:22;CID:{CEF886B2-828A-4CFC-8E05-C3D96C872F03}&cafeReqId=3843f6a6-fb3a-48bc-8027-e6473d964367; 443 MSXFAQ\fcarius 192.168.100.5 Microsoft+Office/15.0+(Windows+NT+6.1;+ucmapi+15.0.4919;+Pro) - 200 0 0 15
2017-04-30 11:34:24 192.168.100.33 POST /mapi/emsmdb/ MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de&CorrelationID=<empty>;&ClientRequestInfo=R:{40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:67;RT:Execute;CI:{C62BF819-8709-4EBF-8996-0348269CC4EE}:22;CID:{A45D13EA-E1A3-46CC-B163-B0C4AD9D7E01}&cafeReqId=9bbebd7b-7ae5-4993-b5f0-bdbd9da9f93c; 443 MSXFAQ\fcarius 192.168.100.5 Microsoft+Office/15.0+(Windows+NT+6.1;+ucmapi+15.0.4919;+Pro) - 200 0 0 15
2017-04-30 11:34:24 192.168.100.33 POST /mapi/emsmdb/ MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de&CorrelationID=<empty>;&ClientRequestInfo=R:{40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:68;RT:Execute;CI:{C62BF819-8709-4EBF-8996-0348269CC4EE}:22;CID:{3681AC1A-F6A9-4FFD-9FBD-B96AAD8F9E65}&cafeReqId=a552dff9-d435-42a0-ac9b-592aa1773227; 443 MSXFAQ\fcarius 192.168.100.5 Microsoft+Office/15.0+(Windows+NT+6.1;+ucmapi+15.0.4919;+Pro) - 200 0 0 15

Die zweite Datenzeile enthält den Request und mich interessiert eigentlich die letzte Spalte "Time-Taken", die hier mit 31ms angegeben ist. Dieses Feld ist daher interessant, da es die Gesamtdauer des Requests bis zur abgeschlossenen Zustell an den Client enthält. IIS, bzw. genauer http.sys startet den Time mit dem Eintreffen des Requests aber stoppt den Timer und schreibt das Log erst, wenn der Client die Antwort komplett bekommen und per TCP-ACK dem Server auch bestätigt habe. Diese Zeit enthält damit nur das Teilstück der Anfrage des Clients nicht aber ansonsten ist der Wert sehr interessant.

31ms ist in dem Fall natürlich in Ordnung.

Analyse: Frontend Proxy

Aber wenn der Wert höher wäre, dann gilt der nächste Blick dem Exchange Frontend Log zu HTTP. Aus dem IISLog sollten Sie sich schon mal die Uhrzeit (hier 11:34) und den Tag holen, denn das httpProxy-Log von Exchange schreibt je Stunde eine neue Datei. Denken Sie daran, dass IIS und Exchange immer in GMT protokollieren. In Deutschland müssen sie daher meist 1 oder 2 Stunden abziehen. Aber der Text in "X-RequestId" ist eindeutig und wenn sie nichts finden, ist es die falsche Datei in C:\Program Files\Microsoft\Exchange Server\V15\Logging\HttpProxy\Mapi\HttpProxy_YYYYMMDDHH-*.log. Hier der passende Auszug:

DateTime,RequestId,MajorVersion,MinorVersion,BuildVersion,RevisionVersion,ClientRequestId,Protocol,UrlHost,UrlStem,ProtocolAction,AuthenticationType,IsAuthenticated,AuthenticatedUser,Organization,AnchorMailbox,UserAgent,ClientIpAddress,ServerHostName,HttpStatus,BackEndStatus,ErrorCode,Method,ProxyAction,TargetServer,TargetServerVersion,RoutingType,RoutingHint,BackEndCookie,ServerLocatorHost,ServerLocatorLatency,RequestBytes,ResponseBytes,TargetOutstandingRequests,AuthModulePerfContext,HttpPipelineLatency,CalculateTargetBackEndLatency,GlsLatencyBreakup,TotalGlsLatency,AccountForestLatencyBreakup,TotalAccountForestLatency,ResourceForestLatencyBreakup,TotalResourceForestLatency,ADLatency,SharedCacheLatencyBreakup,TotalSharedCacheLatency,ActivityContextLifeTime,ModuleToHandlerSwitchingLatency,ClientReqStreamLatency,BackendReqInitLatency,BackendReqStreamLatency,BackendProcessingLatency,BackendRespInitLatency,BackendRespStreamLatency,ClientRespStreamLatency,KerberosAuthHeaderLatency,HandlerCompletionLatency,RequestHandlerLatency,HandlerToModuleSwitchingLatency,ProxyTime,CoreLatency,RoutingLatency,HttpProxyOverhead,TotalRequestTime,RouteRefresherLatency,UrlQuery,BackEndGenericInfo,GenericInfo,GenericErrors,EdgeTraceId,DatabaseGuid
#Software: Microsoft Exchange Server
#Version: 15.01.0669.032
#Log-type: HttpProxy Logs
#Date: 2017-04-30T11:00:02.666Z
#Fields: DateTime,RequestId,MajorVersion,MinorVersion,BuildVersion,RevisionVersion,ClientRequestId,Protocol,UrlHost,UrlStem,ProtocolAction,AuthenticationType,IsAuthenticated,AuthenticatedUser,Organization,AnchorMailbox,UserAgent,ClientIpAddress,ServerHostName,HttpStatus,BackEndStatus,ErrorCode,Method,ProxyAction,TargetServer,TargetServerVersion,RoutingType,RoutingHint,BackEndCookie,ServerLocatorHost,ServerLocatorLatency,RequestBytes,ResponseBytes,TargetOutstandingRequests,AuthModulePerfContext,HttpPipelineLatency,CalculateTargetBackEndLatency,GlsLatencyBreakup,TotalGlsLatency,AccountForestLatencyBreakup,TotalAccountForestLatency,ResourceForestLatencyBreakup,TotalResourceForestLatency,ADLatency,SharedCacheLatencyBreakup,TotalSharedCacheLatency,ActivityContextLifeTime,ModuleToHandlerSwitchingLatency,ClientReqStreamLatency,BackendReqInitLatency,BackendReqStreamLatency,BackendProcessingLatency,BackendRespInitLatency,BackendRespStreamLatency,ClientRespStreamLatency,KerberosAuthHeaderLatency,HandlerCompletionLatency,RequestHandlerLatency,HandlerToModuleSwitchingLatency,ProxyTime,CoreLatency,RoutingLatency,HttpProxyOverhead,TotalRequestTime,RouteRefresherLatency,UrlQuery,BackEndGenericInfo,GenericInfo,GenericErrors,EdgeTraceId,DatabaseGuid
2017-04-30T11:34:25.144Z,623ebcab-4b94-48ee-b97c-96fa97921e8d,15,1,669,32,R:{40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:63;RT:Execute;CI:{C62BF819-8709-4EBF-8996-0348269CC4EE}:22;CID:{8B2F2AC2-9969-47C1-977D-EDED9E7044ED},Mapi,owa.netatwork.de,/mapi/emsmdb/,,Negotiate,true,MSXFAQ\fcarius,netatwork.de,MailboxGuid~e6721880-50d5-41a6-960c-6db2f5b1eb2a,Microsoft Office/15.0 (Windows NT 6.1; ucmapi 15.0.4919; Pro),192.168.103.70,EX01,200,200,,POST,Proxy,EX01.netatwork.de,15.01.0669.000,IntraForest,MailboxGuidWithDomain,Database~7b475535-a572-4073-b90a-2c3feb0072dd~~2017-05-30T11:33:58,,,118,283,,,6,0,,0,,0,,0,0,,0,106,0,0,1,0,93,0,1,0,0,0,99,1,95,5,6,12,106,,?MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de,,BeginRequest=2017-04-30T11:34:25.035Z;CorrelationID=<empty>;ProxyState-Run=None;FEAuth=BEVersion-1942061725;XForwardedMod=true;BeginGetRequestStream=2017-04-30T11:34:25.050Z;OnRequestStreamReady=2017-04-30T11:34:25.050Z;MailboxServerByServerGuard_EX01.netatwork.de=1;MailboxServerByForestGuard_netatwork.de=1;TotalMailboxServerGuard=1;BeginGetResponse=2017-04-30T11:34:25.050Z;OnResponseReady=2017-04-30T11:34:25.144Z;EndGetResponse=2017-04-30T11:34:25.144Z;ProxyState-Complete=ProxyResponseData;SharedCacheGuard=0;EndRequest=2017-04-30T11:34:25.144Z;,,,|RoutingDB:7b475535-a572-4073-b90a-2c3feb0072dd
2017-04-30T11:34:25.254Z,6b21805d-3792-4bbb-a880-ac909fe1802f,15,1,669,32,R:{40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:64;RT:Execute;CI:{C62BF819-8709-4EBF-8996-0348269CC4EE}:22;CID:{A0B0F28F-2EA9-4F3F-B343-1F402D45EDCE},Mapi,owa.netatwork.de,/mapi/emsmdb/,,Negotiate,true,MSXFAQ\fcarius,netatwork.de,MailboxGuid~e6721880-50d5-41a6-960c-6db2f5b1eb2a,Microsoft Office/15.0 (Windows NT 6.1; ucmapi 15.0.4919; Pro),192.168.103.70,EX01,200,200,,POST,Proxy,EX01.netatwork.de,15.01.0669.000,IntraForest,MailboxGuidWithDomain,Database~7b475535-a572-4073-b90a-2c3feb0072dd~~2017-05-30T11:34:25,,,94,128,,,0,1,,0,,0,,0,0,,0,20,0,0,2,1,13,0,0,1,0,0,20,0,14,3,5,5,20,,?MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de,,BeginRequest=2017-04-30T11:34:25.222Z;CorrelationID=<empty>;ProxyState-Run=None;FEAuth=BEVersion-1942061725;XForwardedMod=true;BeginGetRequestStream=2017-04-30T11:34:25.238Z;OnRequestStreamReady=2017-04-30T11:34:25.238Z;MailboxServerByServerGuard_EX01.netatwork.de=1;MailboxServerByForestGuard_netatwork.de=1;TotalMailboxServerGuard=1;BeginGetResponse=2017-04-30T11:34:25.238Z;OnResponseReady=2017-04-30T11:34:25.238Z;EndGetResponse=2017-04-30T11:34:25.238Z;ProxyState-Complete=ProxyResponseData;SharedCacheGuard=0;EndRequest=2017-04-30T11:34:25.254Z;,,,|RoutingDB:7b475535-a572-4073-b90a-2c3feb0072dd
2017-04-30T11:34:25.332Z,51bf3121-84ab-4353-b1bf-17570288d2c6,15,1,669,32,R:{40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:65;RT:Execute;CI:{C62BF819-8709-4EBF-8996-0348269CC4EE}:22;CID:{A3DE7A97-24DA-4A04-91A1-27711B3BA1CB},Mapi,owa.netatwork.de,/mapi/emsmdb/,,Negotiate,true,MSXFAQ\fcarius,netatwork.de,MailboxGuid~e6721880-50d5-41a6-960c-6db2f5b1eb2a,Microsoft Office/15.0 (Windows NT 6.1; ucmapi 15.0.4919; Pro),192.168.103.70,EX01,200,200,,POST,Proxy,EX01.netatwork.de,15.01.0669.000,IntraForest,MailboxGuidWithDomain,Database~7b475535-a572-4073-b90a-2c3feb0072dd~~2017-05-30T11:34:25,,,49,152,,,0,0,,0,,0,,0,0,,0,16,0,0,0,0,11,1,0,1,0,0,16,0,13,3,4,4,16,,?MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de,,BeginRequest=2017-04-30T11:34:25.316Z;CorrelationID=<empty>;ProxyState-Run=None;FEAuth=BEVersion-1942061725;XForwardedMod=true;BeginGetRequestStream=2017-04-30T11:34:25.316Z;OnRequestStreamReady=2017-04-30T11:34:25.316Z;MailboxServerByServerGuard_EX01.netatwork.de=1;MailboxServerByForestGuard_netatwork.de=1;TotalMailboxServerGuard=1;BeginGetResponse=2017-04-30T11:34:25.316Z;OnResponseReady=2017-04-30T11:34:25.332Z;EndGetResponse=2017-04-30T11:34:25.332Z;ProxyState-Complete=ProxyResponseData;SharedCacheGuard=0;EndRequest=2017-04-30T11:34:25.332Z;,,,|RoutingDB:7b475535-a572-4073-b90a-2c3feb0072dd
2017-04-30T11:34:25.457Z,3843f6a6-fb3a-48bc-8027-e6473d964367,15,1,669,32,R:{40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:66;RT:Execute;CI:{C62BF819-8709-4EBF-8996-0348269CC4EE}:22;CID:{CEF886B2-828A-4CFC-8E05-C3D96C872F03},Mapi,owa.netatwork.de,/mapi/emsmdb/,,Negotiate,true,MSXFAQ\fcarius,netatwork.de,MailboxGuid~e6721880-50d5-41a6-960c-6db2f5b1eb2a,Microsoft Office/15.0 (Windows NT 6.1; ucmapi 15.0.4919; Pro),192.168.103.70,EX01,200,200,,POST,Proxy,EX01.netatwork.de,15.01.0669.000,IntraForest,MailboxGuidWithDomain,Database~7b475535-a572-4073-b90a-2c3feb0072dd~~2017-05-30T11:34:25,,,51,131,,,0,0,,0,,0,,0,0,,0,11,0,0,0,1,5,0,0,0,0,0,10,1,6,5,5,5,11,,?MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de,,BeginRequest=2017-04-30T11:34:25.441Z;CorrelationID=<empty>;ProxyState-Run=None;FEAuth=BEVersion-1942061725;XForwardedMod=true;BeginGetRequestStream=2017-04-30T11:34:25.457Z;OnRequestStreamReady=2017-04-30T11:34:25.457Z;MailboxServerByServerGuard_EX01.netatwork.de=1;MailboxServerByForestGuard_netatwork.de=1;TotalMailboxServerGuard=1;BeginGetResponse=2017-04-30T11:34:25.457Z;OnResponseReady=2017-04-30T11:34:25.457Z;EndGetResponse=2017-04-30T11:34:25.457Z;ProxyState-Complete=ProxyResponseData;SharedCacheGuard=0;EndRequest=2017-04-30T11:34:25.457Z;,,,|RoutingDB:7b475535-a572-4073-b90a-2c3feb0072dd
2017-04-30T11:34:25.582Z,9bbebd7b-7ae5-4993-b5f0-bdbd9da9f93c,15,1,669,32,R:{40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:67;RT:Execute;CI:{C62BF819-8709-4EBF-8996-0348269CC4EE}:22;CID:{A45D13EA-E1A3-46CC-B163-B0C4AD9D7E01},Mapi,owa.netatwork.de,/mapi/emsmdb/,,Negotiate,true,MSXFAQ\fcarius,netatwork.de,MailboxGuid~e6721880-50d5-41a6-960c-6db2f5b1eb2a,Microsoft Office/15.0 (Windows NT 6.1; ucmapi 15.0.4919; Pro),192.168.103.70,EX01,200,200,,POST,Proxy,EX01.netatwork.de,15.01.0669.000,IntraForest,MailboxGuidWithDomain,Database~7b475535-a572-4073-b90a-2c3feb0072dd~~2017-05-30T11:34:25,,,63,129,,,0,1,,0,,0,,0,0,,0,11,0,0,1,0,6,0,0,1,1,0,11,0,7,3,4,4,11,,?MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de,,BeginRequest=2017-04-30T11:34:25.566Z;CorrelationID=<empty>;ProxyState-Run=None;FEAuth=BEVersion-1942061725;XForwardedMod=true;BeginGetRequestStream=2017-04-30T11:34:25.566Z;OnRequestStreamReady=2017-04-30T11:34:25.566Z;MailboxServerByServerGuard_EX01.netatwork.de=1;MailboxServerByForestGuard_netatwork.de=1;TotalMailboxServerGuard=1;BeginGetResponse=2017-04-30T11:34:25.566Z;OnResponseReady=2017-04-30T11:34:25.582Z;EndGetResponse=2017-04-30T11:34:25.582Z;ProxyState-Complete=ProxyResponseData;SharedCacheGuard=0;EndRequest=2017-04-30T11:34:25.582Z;,,,|RoutingDB:7b475535-a572-4073-b90a-2c3feb0072dd
2017-04-30T11:34:25.613Z,ffdb7521-9e7c-41e6-a8a2-d42a74070be4,15,1,669,32,R:{8A0DEB93-B3A9-440A-A062-8F01335230C6}:2;RT:DNToMId;CI:{C62BF819-8709-4EBF-8996-0348269CC4EE}:8;CID:{7744E91E-A061-470F-B7D0-0B021F86B4D4},Mapi,EX01.netatwork.de,/mapi/nspi/,,Negotiate,true,MSXFAQ\fcarius,netatwork.de,MailboxGuid~e6721880-50d5-41a6-960c-6db2f5b1eb2a,Microsoft Office/15.0 (Windows NT 6.1; Microsoft Lync 15.0.4919; Pro),192.168.103.70,EX01,200,200,,POST,Proxy,EX01.netatwork.de,15.01.0669.000,IntraForest,MailboxGuidWithDomain,Database~7b475535-a572-4073-b90a-2c3feb0072dd~~2017-05-30T11:34:00,,,288,112,,,0,0,,0,,0,,0,0,,0,21,0,0,0,1,16,0,0,1,0,0,21,0,17,3,3,3,21,,?MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de,,BeginRequest=2017-04-30T11:34:25.597Z;CorrelationID=<empty>;ProxyState-Run=None;FEAuth=BEVersion-1942061725;XForwardedMod=true;BeginGetRequestStream=2017-04-30T11:34:25.597Z;OnRequestStreamReady=2017-04-30T11:34:25.597Z;MailboxServerByServerGuard_EX01.netatwork.de=1;MailboxServerByForestGuard_netatwork.de=1;TotalMailboxServerGuard=1;BeginGetResponse=2017-04-30T11:34:25.597Z;OnResponseReady=2017-04-30T11:34:25.613Z;EndGetResponse=2017-04-30T11:34:25.613Z;ProxyState-Complete=ProxyResponseData;SharedCacheGuard=0;EndRequest=2017-04-30T11:34:25.613Z;,,,|RoutingDB:7b475535-a572-4073-b90a-2c3feb0072dd
2017-04-30T11:34:25.660Z,a552dff9-d435-42a0-ac9b-592aa1773227,15,1,669,32,R:{40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:68;RT:Execute;CI:{C62BF819-8709-4EBF-8996-0348269CC4EE}:22;CID:{3681AC1A-F6A9-4FFD-9FBD-B96AAD8F9E65},Mapi,owa.netatwork.de,/mapi/emsmdb/,,Negotiate,true,MSXFAQ\fcarius,netatwork.de,MailboxGuid~e6721880-50d5-41a6-960c-6db2f5b1eb2a,Microsoft Office/15.0 (Windows NT 6.1; ucmapi 15.0.4919; Pro),192.168.103.70,EX01,200,200,,POST,Proxy,EX01.netatwork.de,15.01.0669.000,IntraForest,MailboxGuidWithDomain,Database~7b475535-a572-4073-b90a-2c3feb0072dd~~2017-05-30T11:34:25,,,59,392,,,0,1,,0,,0,,0,0,,0,10,0,1,0,0,5,0,1,0,0,0,10,0,6,3,3,3,10,,?MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de,,BeginRequest=2017-04-30T11:34:25.644Z;CorrelationID=<empty>;ProxyState-Run=None;FEAuth=BEVersion-1942061725;XForwardedMod=true;BeginGetRequestStream=2017-04-30T11:34:25.644Z;OnRequestStreamReady=2017-04-30T11:34:25.644Z;MailboxServerByServerGuard_EX01.netatwork.de=1;MailboxServerByForestGuard_netatwork.de=1;TotalMailboxServerGuard=1;BeginGetResponse=2017-04-30T11:34:25.644Z;OnResponseReady=2017-04-30T11:34:25.660Z;EndGetResponse=2017-04-30T11:34:25.660Z;ProxyState-Complete=ProxyResponseData;SharedCacheGuard=0;EndRequest=2017-04-30T11:34:25.660Z;,,,|RoutingDB:7b475535-a572-4073-b90a-2c3feb0072dd

Irgendwann hat Exchange 2016 damit angefangen als erste Zeile auch die Feldnamen zu addieren. Das macht die Verarbeitung mit "Import-CSV" deutlich einfacher. Sie können die Datei also sehr einfach einlesen und parsen. Hier ein Beispiel:

import-csv c:\temp\fe1.csv | where {$_.ClientRequestID.contains("{40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:64")} | fl RequestId,*laten*

RequestId                       : 6b21805d-3792-4bbb-a880-ac909fe1802f
ServerLocatorLatency            :
HttpPipelineLatency             : 0
CalculateTargetBackEndLatency   : 1
GlsLatencyBreakup               :
TotalGlsLatency                 : 0
AccountForestLatencyBreakup     :
TotalAccountForestLatency       : 0
ResourceForestLatencyBreakup    :
TotalResourceForestLatency      : 0
ADLatency                       : 0
SharedCacheLatencyBreakup       :
TotalSharedCacheLatency         : 0
ModuleToHandlerSwitchingLatency : 0
ClientReqStreamLatency          : 0
BackendReqInitLatency           : 2
BackendReqStreamLatency         : 1
BackendProcessingLatency        : 13
BackendRespInitLatency          : 0
BackendRespStreamLatency        : 0
ClientRespStreamLatency         : 1
KerberosAuthHeaderLatency       : 0
HandlerCompletionLatency        : 0
RequestHandlerLatency           : 20
HandlerToModuleSwitchingLatency : 0
CoreLatency                     : 3
RoutingLatency                  : 5
RouteRefresherLatency           :

Sie sehen auch , dass hier sehr viele Variablen ein "Latency" im Namen enthalten. Ich finde hier die folgenden drei Felder interessant:

RequestId                       : 6b21805d-3792-4bbb-a880-ac909fe1802f
BackendProcessingLatency        : 13
RequestHandlerLatency           : 20

Das HttpProxyModul behauptet, es hätte 20ms benötigt, wovon 13ms durch eine Wartezeit auf den Backend zu verantworten sind. Da laut IISLog der Request aber 32ms gedauert hat, sind als 12ms zum Teil durch den IIS verschuldet aber natürlich darf der Zeitaufwand bis zur Zustellung auf den Client samt Quittierung nicht vergessen werden. Die Zahlen sind also schon "stimmig". Die RequestID ist hier eine neue Nummer. Die brauche ich aber später im weiteren Verlauf der Analyse.

Analyse: Backend IISLog

Der nächste Schritt ist dann der Blick auf den Backend. Auch hier beginne ich mit dem IISLog in C:\inetpub\logs\LogFiles\W3SVC2. Allerdings kann ich hier nicht mehr nach dem Wert aus "X-RequestID" suchen, da dieser dort nicht mehr sichtbar ist. Auf dem Backend meldet sich ja der Exchange Frontend Service mit einer verkürzen URL:

#Software: Microsoft Internet Information Services 8.5
#Version: 1.0
#Date: 2017-04-30 00:00:03
#Fields: date time s-ip cs-method cs-uri-stem cs-uri-query s-port cs-Username c-ip cs(User-Agent) cs(Referer) sc-status sc-substatus sc-win32-status time-taken
2017-04-30 11:34:24 fe80::c576:b2c3:f631:f737%12 POST /mapi/emsmdb/ MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de 444 Anonymous fe80::c576:b2c3:f631:f737%12 Microsoft+Office/15.0+(Windows+NT+6.1;+ucmapi+15.0.4919;+Pro) - 200 0 0 93
2017-04-30 11:34:24 fe80::c576:b2c3:f631:f737%12 POST /mapi/emsmdb/ MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de 444 Anonymous fe80::c576:b2c3:f631:f737%12 Microsoft+Office/15.0+(Windows+NT+6.1;+ucmapi+15.0.4919;+Pro) - 200 0 0 0
2017-04-30 11:34:24 fe80::c576:b2c3:f631:f737%12 POST /mapi/emsmdb/ MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de 444 Anonymous fe80::c576:b2c3:f631:f737%12 Microsoft+Office/15.0+(Windows+NT+6.1;+ucmapi+15.0.4919;+Pro) - 200 0 0 15
2017-04-30 11:34:24 fe80::c576:b2c3:f631:f737%12 POST /mapi/emsmdb/ MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de 444 Anonymous fe80::c576:b2c3:f631:f737%12 Microsoft+Office/15.0+(Windows+NT+6.1;+ucmapi+15.0.4919;+Pro) - 200 0 0 0
2017-04-30 11:34:24 fe80::c576:b2c3:f631:f737%12 POST /mapi/emsmdb/ MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de 444 Anonymous fe80::c576:b2c3:f631:f737%12 Microsoft+Office/15.0+(Windows+NT+6.1;+ucmapi+15.0.4919;+Pro) - 200 0 0 15
2017-04-30 11:34:24 fe80::c576:b2c3:f631:f737%12 POST /mapi/nspi/ MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de&FrontEnd=EX01.MSXFAQ.DE&RequestId=ffdb7521-9e7c-41e6-a8a2-d42a74070be4&ClientRequestInfo=R:{8A0DEB93-B3A9-440A-A062-8F01335230C6}:2;RT:DNToMId;CI:{C62BF819-8709-4EBF-8996-0348269CC4EE}:8;CID:{7744E91E-A061-470F-B7D0-0B021F86B4D4}&ResponseInfo=XRC:0;SC:0;RC:0&Stage=BegR:2017-04-30T11:34:25.5979120Z;PostAR:1;PreH:1;PostH:15;EndR:15 444 Anonymous fe80::c576:b2c3:f631:f737%12 Microsoft+Office/15.0+(Windows+NT+6.1;+Microsoft+Lync+15.0.4919;+Pro) - 200 0 0 15
2017-04-30 11:34:24 fe80::c576:b2c3:f631:f737%12 POST /mapi/emsmdb/ MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de 444 Anonymous fe80::c576:b2c3:f631:f737%12 Microsoft+Office/15.0+(Windows+NT+6.1;+ucmapi+15.0.4919;+Pro) - 200 0 0 15
2017-04-30 11:34:24 fe80::c576:b2c3:f631:f737%12 POST /mapi/emsmdb/ MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de 444 Anonymous fe80::c576:b2c3:f631:f737%12 Microsoft+Office/15.0+(Windows+NT+6.1;+ucmapi+15.0.4919;+Pro) - 200 0 0 15
2017-04-30 11:34:24 fe80::c576:b2c3:f631:f737%12 POST /mapi/nspi/ MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de&FrontEnd=EX01.MSXFAQ.DE&RequestId=5dddb15b-0178-4eba-bfac-daafcb1e12c3&ClientRequestInfo=R:{8A0DEB93-B3A9-440A-A062-8F01335230C6}:3;RT:QueryRows;CI:{C62BF819-8709-4EBF-8996-0348269CC4EE}:8;CID:{4AE5A612-170D-42F5-BE72-50DF8A397B30}&ResponseInfo=XRC:0;SC:0;RC:0&Stage=BegR:2017-04-30T11:34:25.7541355Z;PostAR:1;PreH:1;PostH:14;EndR:14 444 Anonymous fe80::c576:b2c3:f631:f737%12 Microsoft+Office/15.0+(Windows+NT+6.1;+Microsoft+Lync+15.0.4919;+Pro) - 200 0 0 15
2017-04-30 11:34:24 fe80::c576:b2c3:f631:f737%12 POST /mapi/emsmdb/ MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de 444 Anonymous fe80::c576:b2c3:f631:f737%12 Microsoft+Office/15.0+(Windows+NT+6.1;+ucmapi+15.0.4919;+Pro) - 200 0 0 0
2017-04-30 11:34:24 fe80::c576:b2c3:f631:f737%12 POST /mapi/emsmdb/ MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de 444 Anonymous fe80::c576:b2c3:f631:f737%12 Microsoft+Office/15.0+(Windows+NT+6.1;+ucmapi+15.0.4919;+Pro) - 200 0 0 0
2017-04-30 11:34:25 fe80::c576:b2c3:f631:f737%12 POST /mapi/emsmdb/ MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de 444 Anonymous fe80::c576:b2c3:f631:f737%12 Microsoft+Office/15.0+(Windows+NT+6.1;+ucmapi+15.0.4919;+Pro) - 200 0 0 0
2017-04-30 11:34:25 fe80::c576:b2c3:f631:f737%12 POST /mapi/emsmdb/ MailboxId=e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de 444 Anonymous fe80::c576:b2c3:f631:f737%12 Microsoft+Office/15.0+(Windows+NT+6.1;+ucmapi+15.0.4919;+Pro) - 200 0 0 0

An der Stelle lohnt sich es nicht weiter zu suchen, denn allein die MailboxID ist zu wenig um die Anfrage an ein Postfach zuordnen zu können. Man sieht aber, dass z.B. NSPI-Anfragen durchaus noch eine RequestID haben.

Analyse: Backend Service Log

Wir schauen also weiter und betrachten das Backend-Log des MAPI/HTTP-Service aus C:\Program Files\Microsoft\Exchange Server\V15\Logging\MapiHttp\Mailbox\MapiHttp_YYYYMMDDHH-*.log. Hier nutzt ich nun die RequestID aus dem Frontend Log, welche in diesem Log die Anforderung eindeutig identifiziert.

DateTime,RequestId,MapiRequestId,ClientRequestId,RequestType,HttpStatusCode,ResponseCode,StatusCode,ReturnCode,TotalRequestLatency,DeploymentRing,MajorVersion,MinorVersion,BuildVersion,RevisionVersion,AuthenticatedUserEmail,UPN,Puid,TenantGuid,MailboxId,MDBGuid,ActAsUserEmail,ClientIP,SourceCafeServer,EdgeInfo,NetworkDeviceInfo,SessionCookie,SequenceCookie,MapiClientInfo,ClientSoftware,ClientSoftwareVersion,ClientMode,AuthenticationType,AuthModuleLatency,LiveIdBasicLog,LiveIdBasicError,LiveIdNegotiateError,OAuthLatency,OAuthError,OAuthErrorCategory,OAuthExtraInfo,AuthenticatedUser,RopIds,OperationSpecific,GenericInfo,GenericErrors
#Software: Microsoft Exchange Server
#Version: 15.01.0669.032
#Log-type: MapiHttp Logs
#Date: 2017-04-30T11:00:02.760Z
#Fields: DateTime,RequestId,MapiRequestId,ClientRequestId,RequestType,HttpStatusCode,ResponseCode,StatusCode,ReturnCode,TotalRequestLatency,DeploymentRing,MajorVersion,MinorVersion,BuildVersion,RevisionVersion,AuthenticatedUserEmail,UPN,Puid,TenantGuid,MailboxId,MDBGuid,ActAsUserEmail,ClientIP,SourceCafeServer,EdgeInfo,NetworkDeviceInfo,SessionCookie,SequenceCookie,MapiClientInfo,ClientSoftware,ClientSoftwareVersion,ClientMode,AuthenticationType,AuthModuleLatency,LiveIdBasicLog,LiveIdBasicError,LiveIdNegotiateError,OAuthLatency,OAuthError,OAuthErrorCategory,OAuthExtraInfo,AuthenticatedUser,RopIds,OperationSpecific,GenericInfo,GenericErrors
2017-04-30T11:34:25.050Z,623ebcab-4b94-48ee-b97c-96fa97921e8d,{40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:63,{8B2F2AC2-9969-47C1-977D-EDED9E7044ED},Execute,200,0,0,0,91,Unknown,15,1,669,32,MSXFAQ\fcarius,,,,e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de,7b475535-a572-4073-b90a-2c3feb0072dd,Frank.Carius@Netatwork.de,192.168.100.5,EX01.MSXFAQ.DE,<null>,,MAPIAAAAAOuq/bjg0efE9sbrZitna6aqpKmGPMAAAAAAAA=,2-afq2Vw==,{C62BF819-8709-4EBF-8996-0348269CC4EE}:22,UcMapi.exe,15.0.4919.1000,2,Negotiate,,,,,,,,,Anonymous,>[254]<[254],OwnerLogon;LogonId: 1;,cpn=M_ABR/RUM_ABR/RUM_ABRC/M_APAR/M_APRH/M_DTC/M_DTQ/M_DTE/M_RDE/M_RDrE/M_RDrEc/M_RDEc/M_DTEc/M_APoRH/M_AER/;cpv=0/0/0/1/1/2/2/2/2/2/91/91/91/91/91/;Dbl:EXR.T[]=36;I32:ATE.C[DC01.msxfaq.de]=2;F:ATE.AL[DC01.msxfaq.de]=0;Dbl:RPC.T[]=41;I32:RPC.C[]=5;I32:MAPI.C[]=241;I32:ROP.C[]=1196914781;I32:ADS.C[DC01]=2;F:ADS.AL[DC01]=6.5018;I32:ATE.C[DC01.msxfaq.de]=1;F:ATE.AL[DC01.msxfaq.de]=0;I32:ADS.C[DC03]=1;F:ADS.AL[DC03]=9.5194;Dbl:BudgUse.T[]=156.257995605469;Dbl:STCPU.T[]=31;I32:RPCSVR.C[]=5;F:RPCSVR.AL[]=0;Dbl:ST.T[]=22;I32:MB.C[]=5;F:MB.AL[]=8.2;Dbl:MAPI.T[]=45;I32:RPCDB.C[]=5;F:RPCDB.AL[]=0,
2017-04-30T11:34:25.238Z,6b21805d-3792-4bbb-a880-ac909fe1802f,{40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:64,{A0B0F28F-2EA9-4F3F-B343-1F402D45EDCE},Execute,200,0,0,0,13,Unknown,15,1,669,32,MSXFAQ\fcarius,,,,e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de,7b475535-a572-4073-b90a-2c3feb0072dd,Frank.Carius@Netatwork.de,192.168.100.5,EX01.MSXFAQ.DE,<null>,,MAPIAAAAAOuq/bjg0efE9sbrZitna6aqpKmGPMAAAAAAAA=,3-h0/nKQ==,{C62BF819-8709-4EBF-8996-0348269CC4EE}:22,UcMapi.exe,15.0.4919.1000,2,Negotiate,,,,,,,,,Anonymous,>[86]<[86],,cpn=M_ABR/RUM_ABR/RUM_ABRC/M_APAR/M_APRH/M_DTC/M_DTQ/M_DTE/M_RDE/M_RDrE/M_RDrEc/M_RDEc/M_DTEc/M_APoRH/M_AER/;cpv=0/0/0/11/11/11/11/11/11/12/12/12/12/12/12/;,
2017-04-30T11:34:25.316Z,51bf3121-84ab-4353-b1bf-17570288d2c6,{40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:65,{A3DE7A97-24DA-4A04-91A1-27711B3BA1CB},Execute,200,0,0,0,10,Unknown,15,1,669,32,MSXFAQ\fcarius,,,,e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de,7b475535-a572-4073-b90a-2c3feb0072dd,Frank.Carius@Netatwork.de,192.168.100.5,EX01.MSXFAQ.DE,<null>,,MAPIAAAAAOuq/bjg0efE9sbrZitna6aqpKmGPMAAAAAAAA=,4-EitOXw==,{C62BF819-8709-4EBF-8996-0348269CC4EE}:22,UcMapi.exe,15.0.4919.1000,2,Negotiate,,,,,,,,,Anonymous,>[73]<[73],,cpn=M_ABR/RUM_ABR/RUM_ABRC/M_APAR/M_APRH/M_DTC/M_DTQ/M_DTE/M_RDE/M_RDrE/M_RDrEc/M_RDEc/M_DTEc/M_APoRH/M_AER/;cpv=0/0/0/1/1/2/2/2/2/2/9/9/9/10/10/;Dbl:ST.T[]=1;I32:RPCSVR.C[]=2;F:RPCSVR.AL[]=0;I32:MB.C[]=2;F:MB.AL[]=1.5;Dbl:BudgUse.T[]=31.2761993408203;Dbl:MAPI.T[]=4;I32:RPCDB.C[]=2;F:RPCDB.AL[]=0;Dbl:RPC.T[]=3;I32:RPC.C[]=2;Dbl:EXR.T[]=3;I32:MAPI.C[]=4;I32:ROP.C[]=478765931,
2017-04-30T11:34:25.457Z,3843f6a6-fb3a-48bc-8027-e6473d964367,{40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:66,{CEF886B2-828A-4CFC-8E05-C3D96C872F03},Execute,200,0,0,0,4,Unknown,15,1,669,32,MSXFAQ\fcarius,,,,e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de,7b475535-a572-4073-b90a-2c3feb0072dd,Frank.Carius@Netatwork.de,192.168.100.5,EX01.MSXFAQ.DE,<null>,,MAPIAAAAAOuq/bjg0efE9sbrZitna6aqpKmGPMAAAAAAAA=,5-w9WTFA==,{C62BF819-8709-4EBF-8996-0348269CC4EE}:22,UcMapi.exe,15.0.4919.1000,2,Negotiate,,,,,,,,,Anonymous,>[39]<[39],,cpn=M_ABR/RUM_ABR/RUM_ABRC/M_APAR/M_APRH/M_DTC/M_DTQ/M_DTE/M_RDE/M_RDrE/M_RDrEc/M_RDEc/M_DTEc/M_APoRH/M_AER/;cpv=0/0/0/1/2/2/2/2/2/2/4/4/4/4/4/;I32:RPCSVR.C[]=1;F:RPCSVR.AL[]=0;I32:MB.C[]=1;F:MB.AL[]=1;Dbl:MAPI.T[]=1;I32:RPCDB.C[]=1;F:RPCDB.AL[]=0;Dbl:RPC.T[]=1;I32:RPC.C[]=1;Dbl:EXR.T[]=1;I32:MAPI.C[]=2;I32:ROP.C[]=239382969,
2017-04-30T11:34:25.566Z,9bbebd7b-7ae5-4993-b5f0-bdbd9da9f93c,{40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:67,{A45D13EA-E1A3-46CC-B163-B0C4AD9D7E01},Execute,200,0,0,0,5,Unknown,15,1,669,32,MSXFAQ\fcarius,,,,e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de,7b475535-a572-4073-b90a-2c3feb0072dd,Frank.Carius@Netatwork.de,192.168.100.5,EX01.MSXFAQ.DE,<null>,,MAPIAAAAAOuq/bjg0efE9sbrZitna6aqpKmGPMAAAAAAAA=,6-fdv2Zw==,{C62BF819-8709-4EBF-8996-0348269CC4EE}:22,UcMapi.exe,15.0.4919.1000,2,Negotiate,,,,,,,,,Anonymous,>[2]<[2],,cpn=M_ABR/RUM_ABR/RUM_ABRC/M_APAR/M_APRH/M_DTC/M_DTQ/M_DTE/M_RDE/M_RDrE/M_RDrEc/M_RDEc/M_DTEc/M_APoRH/M_AER/;cpv=0/0/0/1/1/2/2/2/2/2/4/4/4/5/5/;I32:RPCSVR.C[]=1;F:RPCSVR.AL[]=0;I32:MB.C[]=1;F:MB.AL[]=2;Dbl:BudgUse.T[]=31.2425994873047;Dbl:MAPI.T[]=2;I32:RPCDB.C[]=1;F:RPCDB.AL[]=0;Dbl:RPC.T[]=2;I32:RPC.C[]=1;Dbl:EXR.T[]=1;I32:MAPI.C[]=3;I32:ROP.C[]=239382983,
2017-04-30T11:34:25.644Z,a552dff9-d435-42a0-ac9b-592aa1773227,{40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:68,{3681AC1A-F6A9-4FFD-9FBD-B96AAD8F9E65},Execute,200,0,0,0,4,Unknown,15,1,669,32,MSXFAQ\fcarius,,,,e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de,7b475535-a572-4073-b90a-2c3feb0072dd,Frank.Carius@Netatwork.de,192.168.100.5,EX01.MSXFAQ.DE,<null>,,MAPIAAAAAOuq/bjg0efE9sbrZitna6aqpKmGPMAAAAAAAA=,7-md4IGw==,{C62BF819-8709-4EBF-8996-0348269CC4EE}:22,UcMapi.exe,15.0.4919.1000,2,Negotiate,,,,,,,,,Anonymous,>[7]<[7],,cpn=M_ABR/RUM_ABR/RUM_ABRC/M_APAR/M_APRH/M_DTC/M_DTQ/M_DTE/M_RDE/M_RDrE/M_RDrEc/M_RDEc/M_DTEc/M_APoRH/M_AER/;cpv=0/0/0/1/1/2/2/2/2/2/3/3/3/4/4/;I32:RPCSVR.C[]=1;F:RPCSVR.AL[]=0;I32:MB.C[]=1;F:MB.AL[]=1;Dbl:MAPI.T[]=1;I32:RPCDB.C[]=1;F:RPCDB.AL[]=0;Dbl:RPC.T[]=1;I32:RPC.C[]=1;I32:MAPI.C[]=1;I32:ROP.C[]=239382984,

Es ist die zweite Datenzeile, die hier protokolliert, was die Backend Rolle aus der Anforderung gemacht hat. Auch diese Datei kann per PowerShell recht einfach mit Import-CSV gelesen werden. Hier einmal die Zeile in umgebrochener Form:

DateTime               : 2017-04-30T11:34:25.238Z
RequestId              : 6b21805d-3792-4bbb-a880-ac909fe1802f
MapiRequestId          : {40ECC8CD-9F6E-43CA-AE2E-B758989D4665}:64
ClientRequestId        : {A0B0F28F-2EA9-4F3F-B343-1F402D45EDCE}
RequestType            : Execute
HttpStatusCode         : 200
ResponseCode           : 0
StatusCode             : 0
ReturnCode             : 0
TotalRequestLatency    : 13
DeploymentRing         : Unknown
MajorVersion           : 15
MinorVersion           : 1
BuildVersion           : 669
RevisionVersion        : 32
AuthenticatedUserEmail : MSXFAQ\fcarius
UPN                    :
Puid                   :
TenantGuid             :
MailboxId              : e6721880-50d5-41a6-960c-6db2f5b1eb2a@netatwork.de
MDBGuid                : 7b475535-a572-4073-b90a-2c3feb0072dd
ActAsUserEmail         : Frank.Carius@Netatwork.de
ClientIP               : 192.168.100.5
SourceCafeServer       : EX01.MSXFAQ.DE
EdgeInfo               : <null>
NetworkDeviceInfo      :
SessionCookie          : MAPIAAAAAOuq/bjg0efE9sbrZitna6aqpKmGPMAAAAAAAA=
SequenceCookie         : 3-h0/nKQ==
MapiClientInfo         : {C62BF819-8709-4EBF-8996-0348269CC4EE}:22
ClientSoftware         : UcMapi.exe
ClientSoftwareVersion  : 15.0.4919.1000
ClientMode             : 2
AuthenticationType     : Negotiate
AuthModuleLatency      :
LiveIdBasicLog         :
LiveIdBasicError       :
LiveIdNegotiateError   :
OAuthLatency           :
OAuthError             :
OAuthErrorCategory     :
OAuthExtraInfo         :
AuthenticatedUser      : Anonymous
RopIds                 : >[86]<[86]
OperationSpecific      :
GenericInfo            : cpn=M_ABR/RUM_ABR/RUM_ABRC/M_APAR/M_APRH/M_DTC/M_DTQ/M_DTE/M_RDE/M_RDrE/M_RDrEc/M_RDEc/M_DTEc/M_APoRH/M_AE
                         R/;cpv=0/0/0/11/11/11/11/11/11/12/12/12/12/12/12/;
GenericErrors          :

Hier sind es auch wieder einige Felder, die für eine erste Auswertung interessant sind.

RequestType            : Execute
HttpStatusCode         : 200
TotalRequestLatency    : 13

Wenn man also vom Client her den problematischen Request ermittelt hat, kann man über den IIS des Frontend oder den Frontend HttpProxy-Log schon einmal eine erste Zeitabschätzung machen. Aus dem Frontend HttpProxy-Log lässt sich dann eine RequestID ermitteln, mit der die Anfrage auch im Backend-Log gefunden werden kann.

Exchange Server Client Performance Counter

Ehe ich in der Folge auf die verschiedenen Optionen zur Analyse der Log-Dateien eingehe, möchte ich noch einmal den Blick auf Performance Counter werfen. Die Latenzzeit in den Logs wird in Teilen auch als Performancecounter sichtbar.

Exemplarisch habe ich die MapiHttp-Counter dokumentiert. Nutzbar ist aber eigentlich nur die "Averaged Latency" und vielleicht der Connection Count. Ich kann anhand der Beschreibung nur vermuten, dass hier die vom Client gemeldete Latenz an den Server gemeldet wird. Angeblich soll dies seit Exchange 2013 gar nicht mehr erfolgen. Bei Exchange 2003 gab es sogar noch eine eigene API dazu.

Sie sehen aber schon an den Countern, dass die Staffelung nach >2, >5, >10 Sekunden nicht wirklich weiter hilft. Auch die Anzeige der "RPC Average Latency" des "MSExchangeIS Store" zeigt nur, dass der Server eigentlich schnell genug sein müsste. Eine Auswertung nach Client oder Subnetz o.ä. ist so nicht möglich. Dennoch sind diese Counter für ein allgemeines Monitoring wichtig:

MSExchangeIS Client (*)\RPC Average Latency
Should be less than 25 ms on average

Analyse Exchange IS Performance Counter

Auch die Exchange Server führen Performance Counter mit, die sich auf die Massenspeicher beziehen. Der Exchange Information Store protokolliert sehr genau die Anzahl und die Latenz von Lese und Schreibzugriffen auf das Subsystem und so können Sie bei einem laufenden Server gut erfassen, ob es hier vielleicht zu Engpässen kommt. Exchange Protokolliert sehr viele Werte, von denen Aber nur vier für eine erste Betrachtung relevant sind:

Die Einträge finden Sie in Perfmon nuter "MSexchange Database" zwischen all den anderen Countern.

  • I/O Database Reads Average Latency is the average length of time, in milliseconds, per database read operation.
  • I/O Database Writes Average Latency is the average length of time, in milliseconds, per database write operation.

Beide Counter müssen natürlich in Relation zu der absoluten Anzahl an Lese/Schreib-Operationen gesetzt werden. Wenn ein Storage System sehr viele IOPs hat, kann die Latenzzeit schon etwas höher liegen. Dennoch sind hier 20ms eine erste Warnschwelle.

Die Herausforderung dabei ist, dass diese Werte pro Datenbank aber nicht pro DISK oder LUN ermittelt werden. Wer ein "geradliniges" Speichersystem hat, bei der Datenbanken auf eigenen Disks liegen, kann die Zahlen leichter interpretieren als eine Umgebung, bei der mehrere Datenbanken auf den gleichen Disks liegen und selbst Disks durch eine Verknüpfung per RAID und logischen Laufwerke nicht mehr unabhängig von einander sind.

Auswertungen Backend mit Powershell Einzeiler

Aus dem BackendLog lassen sich aber noch viel mehr Daten ohne weitere Vorarbeiten generieren. Denn obwohl der Backend Server sich hinter dem Frontend und sogar hinter einem Loadbalancer verbirgt, sind auch im Backend-Log umfangreiche Informationen vorhanden, da diese im HTTP-Post mit geliefert werden, z.B.

  • Client IP
    Das ist aber nicht die echte Client IP sondern die, welche der Exchange Server sieht.
  • Angemeldeter User
  • Verwendete Outlook Version
  • Verwendete Anmeldung
  • Latenz

Schon einfache "Import-CSV" mit einer Verkettung von "Group" erlauben erste Überblicke. Hier ein paar Beispiele:

# Welche Anmeldeverfahren verwenden Benutzer 
PS C:\> import-csv "C:\Program Files\Microsoft\Exchange Server\V15\Logging\MapiHttp\Mailbox\MapiHttp_2017043011-1.LOG" | group -NoElement -Property AuthenticationType

Count Name
----- ----
    4
    1 AuthenticationType
 1689 Negotiate
   12
  120 Kerberos
# Welche Befehle sind wie verteilt
PS C:\> import-csv "C:\Program Files\Microsoft\Exchange Server\V15\Logging\MapiHttp\Mailbox\MapiHttp_2017043011-1.LOG" |  group RequestType -NoElement

Count Name
----- ----
    4
    1 RequestType
   24 PING
  476 NotificationWait
  862 Execute
   12
  120 EcDoDummy
  167 Connect
  160 Disconnect
Übersicht der HTTP-Statuscodes
PS C:\> import-csv "C:\Program Files\Microsoft\Exchange Server\V15\Logging\MapiHttp\Mailbox\MapiHttp_2017043011-1.LOG" | group -NoElement -Property httpStatuscode

Count Name
----- ----
    4
    1 HttpStatusCode
 1569 200
   12
  240 401
# Übersicht der verschiedenen Client Versionen
PS C:\> import-csv "C:\Program Files\Microsoft\Exchange Server\V15\Logging\MapiHttp\Mailbox\MapiHttp_2017043011-1.LOG" | group -NoElement -Property ClientSoftwareVersion

Count Name
----- ----
  195 15.0.4893.1000
  221 16.0.7369.6567
    8 16.0.4266.1003
  616 15.0.4919.1000
  300 15.1.669.32
   90 16.0.6741.6564
   55 16.0.4498.1000

Aber für eine ordentliche Betrachtung nach Latenz reicht das natürlich nicht. Wer versucht mit einem einfachen Powershell hier die Latenz auszuwerten, wird scheitern, wie folgendes Beispiel zeigt:

PS C:\> import-csv "C:\Program Files\Microsoft\Exchange Server\V15\Logging\MapiHttp\Mailbox\MapiHttp_2017043011-1.LOG" | %{[int]$_.totalrequestlatency} | Measure-Object  -Average -Maximum -Minimum

Count    : 1825
Average  : 79224,5610958904
Sum      :
Maximum  : 599150
Minimum  : 0
Property :

Hier mache lange Requests von bis zu 599 Sekunden (ca. 10 Minuten) die Messung unbrauchbar. Hier muss also auf jeden Fall eine Differenzierung nach dem Befehl erfolgen, damit lange "NotifyWait" die wichtigen "Execute"-Befehle nicht überdecken. Auch macht es wenig Sinn, hier einfach nur Min/Max/Avg zu ermitteln. Interessanter ist schon die Klassifizierung in Geschwindigkeitsgruppen:

  • 0-20ms = Schnell
  • 20-80ms = Mittel
  • 80-2000ms = Langsam
  • >200ms = Sehr langsam

Das geht natürlich nicht mittels "Measure-Objekt". Da muss man schon selbst einen kleine Auswertung schreiben. die dann auch gleich nach dem RequestType unterscheiden kann. Eine Analyse der Backend oder Frontend Logs ist zwar nett aber die beim Client erreichte Antwortzeit aus "Time-Taken" ist so nicht zu erhalten. Allerdings ist solch eine erste Auswertung schon hilfreich um generelle Aussage zur Latenzzeit bei der Bereitstellung von Inhalten zu liefern.

Auswertung nach Latenz

Die Auswertung der Latenz ist natürlich wichtig und aus meiner Sicht ist das HTTP-Proxy-Log des Frontends bezogen auf die Protokolle MAPI/HTTP und RPC/HTTP eine idealer Quelle für eine Analyse. Es enthält fast alle wichtigen Felder.

  • DateTime
    Zeitstempel
  • RequestID
    Eindeutige ID der Anforderung, über die diese dann ggfls. auch auf dem Backend gefunden werden kann
  • UrlHost
    Hostname des Frontend
  • ClientIpAddress
    IP-Adresse der anfordernden Station. Meist der Client oder Reverse Proxy
  • UserAgent
    Der verwendete Client
  • TargetServer
    Hostname des Backend, zu dem der Request weiter geleitet wird
  • ClientRequestId
    Enthält die X-RequestID mit einem "R:"-Prefix
  • BackendProcessingLatency
    Gemessene Verarbeitungsdauer des Request an den Backend
  • RequestHandlerLatency
    Gesamtdauer der Verarbeitung auf dem Frontend

Das Einzige, was hier nun stört sind die Menge an Daten, die auf einem größeren Server schon mal zusammen kommen. Daher habe ich ein PowerShell-Script entwickelt, welches eine Vorverarbeitung übernimmt. Ich habe in der ersten Version darauf verzichtet das Skript direkt auf den Servern per "Remote PowerShell" verteilt zu starten sondern erwarte die UNC-Pfade zu den Logs der Frontend HttpProxy Komponente. Zudem gibt es die Filteroption bezüglich des Zeitraums bezüglich Tage und Stunde, die so im Dateiname enthalten sind. Das Skript liest die Dateien per Import-CSV und extrahiert dann folgende Listen für eine weitere Verarbeitung.

  • Liste der User mit Client-IP, AD-Standort wenn Liste vorhanden, Outlook-Version, Anzahl Requests, Anzahl der "Execute" Latenzzeiten nach Klassifizierung (Kurz,mittel,langsam,sehrlangsam)
    Damit sind auch Auswertungen nach Standorten, Outlook Versionen etc. und die gefühlte Performance  möglich aber nicht über den Zeitverlauf
  • Summierte Requests
    Um eine Auswertung über die Zeit zu erreichen, versuche ich die Anzahl der Requests und damit die Datenmenge zu reduzieren, indem ich mehrere Requests in einem Zeitslot der gleichen Verbindung zusammenfasse und die Summen ermittle
  • Auszug nach User und Subnetz
    In der Regel beschwert sich ein Anwender über eine langsame Reaktion von Outlook oder Exchange. Ein Anwender ist aber "namentlich" bekannt und zumindest von Intern auch über seine IP-Adresse und ggfls. den Zeitraum eingrenzbar. Insofern ist mein erstes Ziel z.B. über alle Exchange Server die Logs eines gewissen Zeitraums einzulesen und daraus nur die Einträge zu extrahieren, die diesen fraglichen Benutzer betreffen.

Bei allen Requests wäre es natürlich auch interessant das Feld "Time-Taken" des IIS passend zu den Requests zu ermitteln. Das Zusammenführen dieser Informationen habe ich noch nicht umgesetzt.

Ich habe mir dazu die HttpProxy-Logs des Frontend als schnelle Quelle ausgesucht, welche mehrere Latenzzeiten, den User, das Kommando und die Client-IP enthalten und so einen schnellen Überblick über die Responsezeit von Exchange gibt. Die Strecke zum Client wird dabei nicht berücksichtigt.

Folgende Zeilen lesen die Logs entsprechend ein:

get-item $exinstall\Logging\HttpProxy\Mapi\HttpProxy_YYYYMMDDHH-*.log `` 
| Import.csv `
| where {AuthenticatedUser -like fcarius} `
| select DateTime,RequestId,MajorVersion,MinorVersion,BuildVersion,RevisionVersion,ClientRequestId,Protocol,UrlHost,`
          UrlStem,ProtocolAction,AuthenticationType,IsAuthenticated,AuthenticatedUser,Organization,AnchorMailbox,UserAgent,`
          ClientIpAddress,ServerHostName,HttpStatus,BackEndStatus,ErrorCode,Method,ProxyAction,TargetServer,`
          TargetServerVersion,RoutingType,RoutingHint,BackEndCookie,ServerLocatorHost,ServerLocatorLatency,RequestBytes,`
          ResponseBytes,TargetOutstandingRequests,AuthModulePerfContext,HttpPipelineLatency,CalculateTargetBackEndLatency,`
          GlsLatencyBreakup,TotalGlsLatency,AccountForestLatencyBreakup,TotalAccountForestLatency,`
          ResourceForestLatencyBreakup,TotalResourceForestLatency,ADLatency,SharedCacheLatencyBreakup,TotalSharedCacheLatency,`
          ActivityContextLifeTime,ModuleToHandlerSwitchingLatency,ClientReqStreamLatency,BackendReqInitLatency,`
          BackendReqStreamLatency,BackendProcessingLatency,BackendRespInitLatency,BackendRespStreamLatency,`
          ClientRespStreamLatency,KerberosAuthHeaderLatency,HandlerCompletionLatency,RequestHandlerLatency,`
          HandlerToModuleSwitchingLatency,ProxyTime,CoreLatency,RoutingLatency,HttpProxyOverhead,TotalRequestTime,`
          RouteRefresherLatency,UrlQuery,BackEndGenericInfo,GenericInfo,GenericErrors,EdgeTraceId,DatabaseGuid

Mit den Objekten in kann ich dann per Skript weitere Auswertungen durchführen:

Die Datenmenge diese3r Logs ist nicht zu unterschätzen und wenn Sie noch mehrere Server haben, dann wird man sehr schnell die Daten per Skript erst einmal zusammenführen und auch etwas eindampfen. Hier sind doch sehr viele Informationen drin, die für eine Auswertung nicht weiter relevant sind. Mit den kleineren Dateien kann man dann per Excel oder auch PowerBI genauer nachschauen.

Auswertung IISLog und Time-Taken

Die Auswertung des Frontend HttpProxy-Logs liefert leider keine Informationen zur Latenzzeit des Clients. Der IIS protokolliert in dem Feld ja die gesamte Zeit für den Request und enthält ebenfalls Informationen zu dem Request.

Für die Auswertung von IISLogs oder WebServer-Logs im Allgemeinen gibt es natürlich jede Menge kostenfreie und auch kommerzielle Werkzeuge.
Aber auch per PowerShell und Logparser lassen sich diese Werte auswerten. Allerdings ist hier die Verknüpfung mit dem "X-RequestType" erforderlich. Ein großer "Time-Taken"-Wert ist völlig normal, wenn Outlook eine Frage nach "Gibt es was neues" gibt und der Server eben erst Minuten später bei einer Änderung antwortet. Als zweckmäßig habe ich hier den Befehl "EXECUTE" angesehen, da Probleme mit der Outlook Performance quasi immer mit dieser Aktion verbunden war.

Wer die Daten noch weiter Eindampfen will, kann natürlich schon beim Extrahieren der Daten einen Filter auf die Source-IP oder den angemeldeten Benutzer anlegen. Dies ist hilfreich, wenn ein bestimmter Benutzer sich über Performanceprobleme beklagt. Genauso interessant kann natürlich auch eine Gruppierung nach Subnetzen sein, die vielleicht noch auf AD-Standorte gemappt werden. Hier könnten dann auch Analysen der Mittelwerte Hinweise darauf geben, ob eine WAN-Verbindung langsam ist. Dann kommen wir aber doch wieder an ein umfangreicheres Monitoring, da diese Daten nicht nur bei Exchange anfallen, sondern auch SharePoint und andere Webdienste von so einer Analyse profitieren könnten.

Ein generisches Auswerteskript habe ich hier nicht entwickelt. Mit Logparser und PowerShell Import-CSV ist es in der Regel sehr einfach gezielt auf die Problemstellung die Daten zu extrahieren und für PowerBI und Co aufzubereiten.

Zukunft: permanentes Monitoring

Mit dem Wissen um die Zahlen in den Protokolldateien ist es natürlich interessant die Daten auch dauerhaft auszuwerten. Dazu müsste ein Task quasi kontinuierlich die Logs mitlesen, nachdem Sie vom Exchange oder IIS geschrieben wurden. Dann sollten die Daten eh noch im Cache sein und weniger Systemlast bedeuten. Dann könnte aber so einen Prozess z.B. die Daten auslesen und an PRTG, Nagios o.ä. melden. Zudem könnte es "Aussetzer" entsprechend erfassen und damit sehr viel aussagekräftigere Daten der Exchange Performance liefern.

Mich würde einmal interessieren, ob Microsoft in Office 365 solche Daten erhebt. Anhand der Client IP und geografischen Verortung könnte man sehr gut erkennen, in welchen Ecken der Welt die Anwender eine eher schlechte Performance haben.

Allerdings könnte schon eine generelle Auswertung des IIS (Time-Taken) ebenso interessant sein. Damit wären nämlich auch andere Dienste, die auf dem IIS aufsetzen, elegant zu überwachen. Ich denke da an SharePoint u.a.

Auswertung mit PowerBI

Ich arbeite für schnelle Auswertungen und Fehlersuchen gerne mit PowerBI, um Daten zu visualisieren. Da kommt es dann aber nicht auf einen einzelnen Request an, sondern auf den Überblick. ich möchte schon die ein oder andere Detailauswertung z.B.: nach Subnetz, nach User oder Outlook-Version anstellen. Allerdings produziert eine Umgebung mit 10.000 Benutzern auch gerne mal Logs mit einer Rate von 200-300 Zeilen/Sekunde bzw. 160kByte/Sek. Für solche Datenmengen ist eine Vorverarbeitung sinnvoll, um die Daten etwas einzustampfen, indem man die Auflösung reduziert.

Um die Datenmenge zu reduzieren können in der Regel mehrere Requests vom gleichen Anwender oder Source-IP z.B.: in 10 oder 60 Minuten-Blöcken zusammen. Dafür muss ich dann natürlich neue Spalten addieren um "Latenzgruppen" und z.B. "Anzahl" der 2xx, 3xx und 4xx Statuscodes zu erhalten. Andere Informationen wie RequestID etc. lasse ich dann entfallen. Zusatzinformationen wie z.B. die verwendete Outlook Version samt Benutzername und Client-IP landen in eigenen CSV-Dateien.

Diese Skripte möchte ich später auf einer eigenen Seite beschreiben. Bitte haben Sie noch etwas Geduld.

Einfluss der Garbage Collection

Ingo Gegenwarth hat mich auf seinen BLOG-Post aufmerksam gemacht, dass Windows und das .NET Framework natürlich auch immer mal wieder ihren Speicher reorganisieren müssen. Das kann einen Einfluss auf die Exchange Performance haben. Hier ein paar Links:

Es muss also gar nicht Exchange selbst sein, wenn das System manchmal stolpert. Die Garbage Collection ist aber nur eine Komponente im großen Spiel. Auch Netzwerkkartentreiber, Storage-Systeme aber acuh Virtualisierung, Virenscanner und andere Abhängigkeiten können Exchange derart ausbremsen, dass die Counter keine kritischen Werte melden

Wenn nichts hilft

Auf dieser Seite habe ich umfangreich beschrieben, wie Sie anhand der vorhandenen Counter Rückschlüsse auf die Exchange Performance erhalten können. Damit ist aber nicht sichergestellt, dass Sie auch die Ursache finden und das Problem beseitigen. Daher möchte ich hier noch ein paar Tipps geben, was Sie verändern können.

  • RPC/HTTP statt MAPI/HTP
  • Wireshark und Latenzermittlung
  • Loadbalancer umgehen
  • Eigener Server oder eigene Datenbank für Shared Mailbox

Vielleicht haben Sie so eine Veränderung feststellen können, anhand der Sie dann die nächsten Schritte einleiten können. Das Problem von schwankenden Reaktionszeiten ist aber überhaupt nicht einfach in den Griff zu bekommen, da Sie nicht zuverlässig reproduzierbar sind. Ein "Test" sorgt nämlich dafür, dass diese Information im Cache von Exchange landet und jeder folgende Zugriff ist damit schnell.

Weitere Links