Kiedy serwer transportowy działa wolno…

  • Article

W przypadku niewielkich instalacji Exchange raczej rzadko mamy do czynienia z problemami zwiazanymi z czasem przetwarzania wiadomosci przez serwery transportowe. Jesli, na co dzien pracujecie jednak z organizacjami, w których system pocztowy jest jednym z bardziej krytycznych systemów, prawdopodobnie predzej czy pózniej traficie na problem, w którym niedociagniecia w konfiguracji Exchange lub jakis agent transportowy beda znaczaco wplywac na czas dostarczania wiadomosci pocztowych.

W zwiazku z tym pojawia sie tylko pytanie – jak moge w prosty sposób zweryfikowac ile czasu trwa przesylanie wiadomosci z punktu A do punktu B? Który serwer jest potencjalnym waskim gardlem? A jesli juz wiem, który serwer jest waskim gardlem to, co tak naprawde wplywa na dlugi czas przetwarzania wiadomosci na danym serwerze?

Zacznijmy moze od odrobiny podstaw

Za przesylanie wiadomosci w obrebie organizacji Exchange odpowiadaja serwery pelniace role Hub Transport. Sa to jedyne serwery wewnatrz organizacji, które obsluguja ruch SMTP. Dodatkowo odpowiadaja one za dostarczanie i odbieranie wiadomosci z baz pracujacych na serwerach Mailbox.

Typowy scenariusz przetwarzania wiadomosci wyglada tak:

  1. Wiadomosc odbierana z pomoca protokolu SMTP lub z serwera Mailbox
  2. Wiadomosc trafia do kolejki Submission
  3. Wiadomosc jest przetwarzana (proces kategoryzacji)
  4. Wiadomosc trafia do docelowej kolejki
  5. Wiadomosc jest dostarczana do miejsca docelowego

Na pierwszych trzech etapach, wiadomosc moze byc dodatkowo przetwarzana przez tzw. Agentów Transportowych (np. agent programu antywirusowego, agent aplikacji dodajacej stopki do wiadomosci, lub agent systemowy odpowiadajacy za journaling).

Jesli chcielibysmy szybko przesledzic, jakie sa najwazniejsze etapy przetwarzania wiadomosci na serwerach transportowych i na jakim etapie uruchamiani sa Agenci Transportowi, mozemy uzyc komendy get-transportpipeline. Aby komenda zwrócila nam jakiekolwiek sensowne informacje musimy sie upewnic, ze przeslalismy z pomoca serwera przynajmniej jedna wiadomosc od ostatniego restartu uslugi transportowej.

Event TransportAgents
----- ---------------
OnConnectEvent {}
OnHeloCommand {}
OnEhloCommand {}
OnAuthCommand {}
OnEndOfAuthentication {}
OnMailCommand {}
OnRcptCommand {}
OnDataCommand {}
OnEndOfHeaders {}
OnEndOfData {}
OnHelpCommand {}
OnNoopCommand {}
OnReject {}
OnRsetCommand {}
OnDisconnectEvent {}
OnSubmittedMessage {Text Messaging Routing Agent}
OnResolvedMessage {}
OnRoutedMessage {Transport Rule Agent, My custom agent}
OnCategorizedMessage {}

Pierwsza grupa zdarzen, zaczynajaca sie od nawiazania polaczenia (OnConnectEvent) a konczaca sie na na rozlaczeniu sesji SMTP (OnDisconnectEvent), odpowiada poszczególnym etapom komunikacji SMTP.
Druga grupa, która zaczyna sie od zdarzenia OnSubmittedMessage odpowiada procesowi kategoryzacji wiadomosci (ustalania, kto jest nadawca, kto jest odbiorca, czy limity pozwalaja na przeslanie wiadomosci, jak wiadomosc powinna zostac dostarczona do miejsca docelowego).

W moim przykladzie widzimy agenta „My custom agent”, który uruchamiany jest, gdy w procesie kategoryzacji dla wiadomosci zostanie okreslona sciezka routing’u (czyli sciezka, wg. której serwer powinien przekazac wiadomosc do miejsca docelowego)

Gdzie moga postawac opóznienia i co moze je powodowac?

Opóznienia w przetwarzaniu wiadomosci moga zachodzic na kazdym z etapów

  1. Podczas komunikacji SMTP – ze wzgledu na wolne polaczenie sieciowe lub wolne dzialanie agenta transportowego, dzialajacego na tym etapie
  2. Podczas procesu kategoryzacji – ze wzgledu na duze obciazenie serwera, niewydolna infrastrukture Active Directory lub wolne dzialanie agenta transportowego, dzialajacego na tym etapie
  3. Podczas dostarczania wiadomosci do nastepnego serwera SMTP lub do serwera Maiblox – tutaj przyczyna moga byc problemy komunikacyjne, wolne polaczenie sieciowe lub problemy samego serwera docelowego

Jak moge sprawdzic, co wplywa na opóznienie wiadomosci, która znajduje sie w kolejce?

Spróbujmy wykonac to na przykladzie. Na moim serwerze wykonalem polecenie get-queue, aby zobaczyc ile wiadomosci znajduje sie w poszczególnych kolejkach. W wyniku dzialania komendy otrzymalem ponizsze zestawienie:

Identity DeliveryType Status MessageCount NextHopDomain
-------- ------------ ------ ------------ -------------
E2k10A\3 MapiDelivery Retry 1 mbxdb1
E2k10A\Submission Undefined Ready 0 Submission

Jak widac, w kolejce MapiDelivery, czyli w kolejce dostarczania do serwera Mailbox, mam jedna wiadomosc. Spróbujmy teraz zweryfikowac, ile czasu wiadomosc do tej pory spedzila na kazdym etapie przetwarzania. W tym celu uruchomimy nastepujace polecenie:

Get-Queue 3 | Get-Message -IncludeComponentLatencyInfo | fl *messageid, *latency

W wyniku dzialania dostalem nastepujace dane:

InternetMessageId : <MessageID>
ComponentLatency : {0;
SMTP Receive;False;00:00:12, 1;
Categorizer Routing;False;00:00:05,2;
Categorizer;False;00:00:06,3;
Store Driver Delivery;False;00:00:02, 4;
Delivery Queue;True;00:08:39}
MessageLatency : 00:09:05,0

Co z tego wynika?

Pierwsze, na co mozemy zwrócic uwage, ze ilosc informacji widoczna w ComponentLatency jest niewspólmierna do ilosci etapów, jakie przechodzi wiadomosc na serwerach transportowych. Wynika to z faktu, ze Exchange loguje tylko informacje na temat etapów/komponentów, w których przetwarzanie trwalo dluzej niz 1 sekunde. Jest to domyslna konfiguracja, której zmiana nie jest zalecana na serwerach produkcyjnych.

Druga informacja, to to, ze w naszym przypadku:

  • Przetwarzanie wiadomosci trwalo juz 9 minut i 5 sekund
  • Sesja SMTP trwala 12 sekund
  • Kategoryzacja wiadomosci trwala nieco ponad 6 sekund, z czego etap ustalania sciezki routingu trwal 5 sekund
  • Wiadomosc jest juz w kolejce delivery of 8 minut i 39 sekund

A co jesli chce zobaczyc podobne informacje dla wiadomosci, które zostaly juz dostarczone?

Tutaj Exchange tez przychodzi nam z pomoca. Serwery Exchange 2010 zapisuja w logach message tracking dodatkowe dane dotyczace czasu przetwarzania wiadomosci przez poszczególne serwery oraz komponenty na serwerach. Aby odczytac te informacje, nalezy uzyc skryptu ConvertToMessageLatency.ps1 dostepnego w folderze scripts w katalogu, w którym zostal zainstalowany serwer Exchange.

W jaki sposób go uzywac?

Get-MessageTrackingLog -messageid MessageID | .\ConvertTo-MessageLatency.ps1 | ft *MessageId, ServerHostName, ComponentCode, componentName, Componentlatency -a

W wyniku dzialania otrzymamy zestawienie podobne do tego ponizej:

ServerHostname ComponentCode ComponentName ComponentLatency
-------------- ------------- ------------- ----------------
E2k10A TOTAL Total Server Latency 00:15:33
E2k10A SMR SMTP Receive 00:00:01
E2k10A SMSC SMTP Send Connect 00:00:21
E2k10A QD Delivery Queue 00:01:01
…

Podobnie jak w poprzednim przypadku mamy informacje na temat poszczególnych etapów, w których przetwarzanie trwalo dluzej niz 1 sekunde.

To teraz kilka przykladów praktycznego wykorzystania

Zebranie informacji na temat wiadomosci przeslanych w ciagu ostatnich 7 dni, których przetwarzanie trwalo dluzej niz 5 minut. Dla tych serwerów wyswietlenie calkowitego czasu przetwarzania na poszczególnych serwerach. Z pomoca tego polecenia szybko namierzycie serwer, który jest potencjalnym waskim gardlem w komunikacji.

Get-MessageTrackingLog -start (Date).AddDays(-7) | .\ConvertTo-MessageLatency.ps1 | ?{$_.MessageLatency -gt "00:05:00" -and $_.ComponentCode -eq "TOTAL"} | ft MessageId, ComponentServerFQDN, ComponentLatency

Zebranie informacji na temat komponentów, które przetwarzaly wiadomosc dluzej niz minute w ciagu ostatnich 7 dni. Jesli problemem jest np. agent transportowy, ta metoda szybko go zidentyfikujecie.

Get-MessageTrackingLog -start (Date).AddDays(-7) | .\ConvertTo-MessageLatency.ps1 | ?{$_.componentLatency -gt "00:05:00" -and $_.ComponentCode -ne "TOTAL"} | ft MessageId, ComponentServerFQDN, ComponentName, ComponentLatency

Przy analizie wiekszej ilosci danych, przydatnym jest ich eksport do pliku CSV i analiza z pomoca programu Excel. Aby wyeksportowac dane do pliku CSV, uzywamy komendy:

Get-MessageTrackingLog -start (Date).AddDays(-7) | .\ConvertTo-MessageLatency.ps1 | ?{$_.componentLatency -gt "00:05:00" -and $_.ComponentCode -ne "TOTAL"} | export-csv c:\temp\latency.csv -notypeinformation

Podsumowujac

Component Latency Tracking w Exchange 2010 jest prostym, ale poteznym narzedziem wspomagajacym diagnozowanie problemów wydajnosciowych serwerów transportowych. Jesli wiec nastepnym razem zobaczycie w Event Logu ostrzezenie informujace o agencie transportowym, który przetwarzal wiadomosc dluzej niz X sekund… nie panikujcie.

Po prostu korzystajac z informacji z tego artykulu wyciagnijcie wiecej informacji statystycznych z Message Tracking, przeanalizujcie jak czesto taki problem wystepowal, czy ten wlasnie agent rzeczywiscie regularnie generuje problemy, czy widzicie zbieznosc czasowa pomiedzy dlugim przetwarzaniem wiadomosci przez agenta a utylizacja zasobów na serwerze. Na tej podstawie wyciagnijcie logiczne wnioski i rozwiazcie problem.

Powodzenia!