Message Tracking Latenz

Der Exchange Transport Stack bekommt Mails per SMTP oder vom Postfach und die Mail verlässt den Transport wieder per SMTP oder Richtung einem Postfach. Die Zeit, die so eine Mail durch die Exchange Transport Stationen läuft, ist ein wichtiger Indikator für die Qualität, Performance und Probleme ihres Systems. Diese Seite beschreibt, wie man die Daten ermitteln und auswerten kann

Datenquellen

Das Messagetracking ist ein wahrer Schatz was die Auswertung von Nachrichten im System betrifft. Für ein Exchange Sizing kann ich so ermitteln, wie viele Mails in welcher Größe zu welcher Stunde auf einem System durchlaufen, was für ein Sizing wichtig ist. Anhand von FAIL-Events sind Problemadressen auszumachen und natürlich lässt sich auch der Weg einer Mail nachverfolgen.

Daher habe schon schon früher mir die Zeitstempel von Mails geholt, die das System erstmalig erreichen und auf der anderen Seite den Eintrag gesucht, bei dem die Mail aus Sicht von Exchange final zugestellt worden war. Aber halt; so einfach ist das nicht, denn eine einzelne eingehende Mail kann ja zu mehreren Mails aufgefächert werden (Verteiler) und letztlich viele "Exit"-Einträge erzeugen. Zudem kann eine Umgebung durch mehrere Server sehr umfangreich werden und irgendwann kommt auch PowerShell an seine Grenzen. Daran haben sich aber auch schon Andere versucht

Aber wen Sie sich so einen MessageTracking-Eintrag einmal anschauen, dann finden Sie zwei interessante Felder

get-messagetrackinglog -resultsize 1 | fl messagelaten*

MessageLatencyType
MessageLatency

Nur war der Wert in meinem Beispiel leer. Also habe ich schnell mal geschaut, bei welchen Events der Wert einen Inhalt hat:

Get-messagetrackinglog `
   -resultsize unlimited `
| group MessageLatencyType `
   -NoElement

Count Name
----- ----
12555 None
 2512 LocalServer
 2390 EndToEnd

Es gibt also "wenige" Einträge bei denen das Feld "MessageLatencyType" gefüllt ist. Ich habe mir dann natürlich auch ein paar Einträge mit dem Wert "None" mal genauer angeschaut und gefunden habe ich nur Events, die ein "MAPI Submit" oder ein "SMTP Receive" sind. Da ist ja klar, dass da noch keine Informationen über eine "Latenzzeit" vorhanden ist. Interessant ist hier natürlich die „Ende zu Ende“-Latenzzeit die logischerweise nur bei Elementen erscheinen kann, die auch abschließend verarbeitet wurden. Also habe ich mit die Events angeschaut, bei denen "EndToEnd" drin steht.

Get-messagetrackinglog `
   -resultsize unlimited `
| where { $_.MessageLatencyType -eq „EndtoEnd“} `
| select @{Name="type";Expression={$_.source + ":"+$_.eventid }} `
| group type -noelement
 
Count Name
----- ----
  600 SMTP:SEND
 1790 STOREDRIVER:DELIVER

Das habe ich mir schon fast gedacht. Diese beiden Events "SMTP:SEND" und "STOREDRIVER:DELIVER" sind genau die beiden Events, die nur am Ende der Verarbeitung durch den Transport erstellt werden. Mit einer kleinen Konvertierung des Timespan-Werts erhält man schnell die Latenzzeiten der letzten Stunde.

Get-messagetrackinglog `
   -start (get-date).addhours(-1) `
   -resultsize unlimited `
| where { $_.MessageLatencyType -eq "EndtoEnd"} `
| select @{Name="End2EndLatency";Expression={$_. MessageLatency.totalseconds }} `
| measure-object `
   -property End2EndLatency `
   -average `
   -maximum `
   -minimum

Count    : 2390
Average  : 10,36125666074589
Sum      :
Maximum  : 70,256
Minimum  : 0,065
Property : End2EndLatency

So kann ich für eine Zeitspanne sehr schnell ermitteln, wie "schnell" mein Exchange Server Nachrichten von Ende zu Ende verarbeitet. Nun ist da ja eine Mail mit 70Sek dabei. Da würde ich schon mal nachschauen. Ganz allgemein ist ein gesamter Mittelwert nicht wirklich aussagekräftig. Ich hätte schon gerne eine Aufschlüsselung in verschiedene Laufzeiten, z.B.  0-10ms, 10-100ms, 100ms-1sek, 1-10sek-10-100sek > 100Sek. Für so eine Auswertung ist natürlich eine Logarithmus-Funktion zur Basis 10 mit etwas Runden passend.

Get-messagetrackinglog `
   -start (get-date).addhours(-1) `
   -resultsize unlimited `
| where { $_.MessageLatencyType  -eq "EndtoEnd"} `
| select @{Name="End2EndLatency";Expression={[long](([math]::log10($_. MessageLatency.totalmilliseconds))+0.5) }} `
| group End2EndLatency `
   -noelement `
| sort name

Entsprechend sind die Daten dann gruppiert wobei 1= 1-9ms, 2=10-99ms usw.. bedeutet . Diese Daten kann man nun schon schöner als Diagramm oder in ein Monitoring eintüten. Denn neben der durchschnittlichen Laufzeit aller Mails interessiert mich natürlich auch Anzahl der Mails, die meine Obergrenze überschreiten.

Dabei sollten sie auch daran denken, dass Exchange selbst "Health-Mails" sendet, die in der Regel von Server zu Server nur kurz unterwegs sind. Wenn Sie mit "Journalierung" arbeiten, dann werden diese Journalmails auch auf dem Server generiert und landen recht schnell im Postfach oder extern. Diese Mails drücken daher den Durchschnitt nach unten. Sie könnte diese natürlich auch beim Einsammeln vorab heraus filtern.

Eine weitere Komponente, die hier Einfluss nicht, ist das Throttling. Ich habe z.B. über das "Pickup-Verzeichnis sehr viele Testmails gesendet und mich gewundert, warum die Mails am Anfang schnell und dann immer langsamer versendet wurden. In der TechNet findet sich aber schnell die Antwort:

By default, the Pickup directory can process 100 messages per minute The Pickup directory and the Replay directory scan for new message files once every 5 seconds, or 12 times per minute. This 5-second polling interval isn't configurable.
Quelle: Understanding Message Throttling https://technet.microsoft.com/en-us/library/bb232205(v=exchg.141).aspx

Hier ist per Default ein Limit aktiv und meine 100 Mails wurden eben zwar schnell "gesehen" aber in kleinen Chargen in den Transport eingesaugt. Die End2End-Latenz wurde aber nicht erst dann gestartet, wenn die Mail eingelesen wurde, sondern schon aus dem Zeitpunkt, wann ich die Datei im Ordner bereit gestellt habe.

End2 End Details

Wenn Sie sich so einen Messagetracking-Eintrag noch mal genauer anschauen, dann finden Sie noch zwei weitere Felder, die für eine genauere Untersuchung von "Langläufern" interessant sind. Das Feld "MessageInfo" als auch das Feld "EventDate" enthalten aufschlussreiche Informationen über die Verzögerungen in den verschiedenen Stationen.

MessageInfo             : 2017-09-14T14:04:19.390Z;SRV=ex2013.msxfaq.de:TOTAL-HUB=60.299|PCK=58.096|CRSL=0.002|CATRS
                          -Transport Rule Agent=0.027|CATRS-Index Routing Agent=0.496|CATRS=0.524|CATRT-Journal
                          Agent=0.161|CATRT=0.161|CAT=0.692|QDE=1.252|SMS=0.175
MessageLatency          : 00:01:00.2990000
MessageLatencyType      : EndToEnd
EventData               : {[E2ELatency, 60.299], [ExternalSendLatency, 58.831],
                          [Microsoft.Exchange.Transport.MailRecipient.RequiredTlsAuthLevel, Opportunistic],
                          [Microsoft.Exchange.Transport.MailRecipient.EffectiveTlsAuthLevel, EncryptionOnly],
                          [DeliveryPriority, Low], [PrioritizationReason, AMS:40530303/1048576|ARC:198/50;200],
                          [AccountForest, msxfaq.de]}

Es also gar nicht erforderlich sich durch das Messagetrackinglog aller Server auf dem Weg zu lesen um Details zu erhalten. Aus dem Feld "Eventdata" habe ich den folgenden Eintrag gesehen:

[ExternalSendLatency, 58.831],

Das war bei mir eine PICKUP-Mail, die aufgrund von Throttling verzögert wurde. Zu den anderen Einträgen im Feld "Messageinfo" habe ich aktuell noch keine autoritative Liste gefunden. Man kann aber schon erahnen, was wofür steht:

  • PCK=58,096
    dürfte für die Latenzzeit in Sek bei Pickup stehen
  • TOTAL-HUB
    für die Gesamtzeit im Hub-Transport-System
  • CATRS=0.524
    könnte für "Categoizer/Resolver) stehen
  • CATRS-Transport Rule Agent=0.027
    Die Verarbeitung von Transportregeln war nach 27ms abgeschlossen
  • CATRT-Journal 
    würde ich zu Categorizer Routing zum Journal übersetzen. Diese Mail wurde journaliert
  • CAT=0.692
    Ich würde sagen, dass dies die Summe aller CATR-Events ist
  • QDE=1.252
    Kann ich nicht zuordnen. vielleicht "Quality delivery Experience :-)
  • SMS=0.175
    Kann ich ebenso wenig zuordnen Ich tippe mal auf etwas mit "Store" als letzter Schritt der Zustellung.

Letztlich brauchen Sie aber mal eine Mail, die hier viel länger unterwegs ist als nur Bruchteile von Sekunden. Sie können dann natürlich immer noch die MessageID der Mail nehmen und über alle Transportserver nach den Events suchen.

get-transportservice  | getrlmessagetrackinglog -messageid <id>

Hier können Sie dann wieder jede einzelne Station im Detail analysieren.

Latenzzeiten und Monitoring

Da Sie ja nun wissen, wie Sie ganz einfach aus dem Message Tracking die Latenzzeiten ermitteln können, ist es nur ein kleiner Schritt diese Daten an ein vorhandenes Monitoring-System zu übergeben.

Weitere Links