Enterprise Library Logging Application Block - część III 

Autor: Piotr Zieliński

Opublikowano: 2013-12-02

Wprowadzenie

Semantic Logging Application nie stanowi kolejnej biblioteki do wykonywania logów, która po prostu zapisuje tekst we wskazanej lokalizacji (np. pliku tekstowym). Prezentuje bowiem zupełnie inne podejście niż Logging Application Block i pozostałe konkurencyjne biblioteki. Semantic Logging Application to rozwiązanie przydatne szczególnie w przypadku dużych i rozproszonych systemów. Biblioteka jest oparta na ETW (Event Tracking for Windows) – generycznym rozwiązaniu do publikacji logów.

Dlaczego aktualne rozwiązania są złe?

Wiele osób przyzwyczaiło się do prostych plików tekstowych zawierających logi i nie jest zainteresowanych nowym podejściem. W przypadku prostych aplikacji pliki tekstowe sprawują się dobrze, ale im większy system, tym więcej korzyści z ETW. Inwestycja w dobry mechanizm monitorowania aplikacji przyniesie oszczędności, gdy aplikacja trafi już do produkcji i administratorzy czy programiści nie będą mogli po prostu użyć debuggera.

Głównym problemem klasycznych rozwiązań jest trudność w analizowaniu logów. Bardzo trudno analizować plik tekstowy, ponieważ każdy wpis może mieć zupełnie inny format. Sytuacja komplikuje się jeszcze bardziej, gdy administrator chce monitorować aplikację w czasie rzeczywistym. W takich logach wszystko jest po prostu tekstem, więc zastosowanie zaawansowanych filtrów staje się bezużyteczne.

W klasycznym podejściu każda aplikacja definiuje swój format; nie jest on oczywiście silnie typowany. Z tego względu bardzo trudno napisać osobną aplikację, która podłączy się do pliku zawierającego logi i będzie mogła monitorować specyficzne wpisy w czasie rzeczywistym. W przypadku ETW istnieją gotowe narzędzia, które są w stanie zbierać logiki z jakiejkolwiek aplikacji wspierającej ETW.

ETW – zasada działania

ETW to infrastruktura umożliwiająca monitorowanie i diagnozowanie aplikacji. Główny element stanowi źródło logów. Tłumacząc na język c#, jest to klasa dziedzicząca po EventSource, która generuje logi (zdarzenia). Klasa EventSource została wprowadzona w .NET 4.5 i znacząco ułatwia pracę z ETW.

Rys. 1. Podstawowa architektura ETW.

Rysunek 1 przedstawia architekturę ETW, gdzie źródło zdarzeń i konsumenci znajdują się w tym samym procesie. Jeśli aplikacja chce stworzyć log, wywołuje odpowiednią metodę na EventSource. Następnie EventSource powiadamia wszystkie klasy TraceListener, które są zainteresowane monitorowaniem aplikacji. Z każdym „słuchaczem” może być skojarzonych kilka lokalizacji przechowywania zdarzeń – nazywa się je event sinks.

Całość działa na zasadzie producent/konsument. Producentem jest aplikacja, a konsumentem – TraceLister lub inne oprogramowanie monitujące (np. PerfView).

Alternatywnym podejściem jest umieszczenie konsumenta i producenta w różnych procesach:

Rys. 2. Rozwiązanie oparte na osobnym – dedykowanym – procesie.

Na rysunku 2 wyraźnie widać, że producent i konsument to dwa różne procesy połączone przez ETW (dostarczony przez system operacyjny). Ma to kilka zalet, a mianowicie: jeśli w aplikacji wystąpi wyjątek i zostanie ona zamknięta, to jest pewność, że logi zostaną dostarczone. Niektóre źródła danych wspierają buforowanie, więc nie od razu zapisują fizycznie dane. Jeśli ETW jest hostowany w tym samym procesie co aplikacja, istnieje ryzyko, że zawartość bufora zostanie utracona.

Instalacja

Instalacja Semantic Logging Application jest bardzo prosta i odbywa się za pomocą NuGet (rysunek 3):

Rys. 3. Instalacja pakietu z NuGet.

Wszystkie wymagane biblioteki zostaną automatycznie zainstalowane.

Pierwsze kroki

Jak już zostało wspomniane, najpierw należy zaimplementować własne źródło logów, dziedzicząc po klasie EventSource. Najprostsza implementacja może wyglądać następująco:

class CustomEventSource : EventSource
{
    public void Startup() { WriteEvent(1); }
    public void OpenFileStart(string fileName) { WriteEvent(2, fileName); }
    public void OpenFileStop() { WriteEvent(3); }
}

Najważniejszą metodą jest oczywiście WriteEvent. Jako pierwszy parametr należy obowiązkowo przekazać unikalny identyfikator zdarzenia. Proszę zauważyć, że całość jest silnie typowana. Nie przekazuje się treści wiadomości bezpośrednio jako string – przekazuje się wyłącznie wartości, a reszta jest formatowana w z góry określony sposób.

WriteEvent jest chroniony i może zostać wywołany wyłącznie przez klasę rozszerzającą EventSource.

Jak już wspomniano, ETW to generyczna infrastruktura i każdy może konsumować logi. Jedną z aplikacji dostępnych w internecie jest PerfView (rysunek 4).

Rys. 4. Aplikacja PerfView przydatna w monitorowaniu logów ETW.

Interfejs PerfView jest bardzo toporny, ale na potrzeby testów w zupełności wystarczy. Przydałoby się jednak, aby kolejne wersje aplikacji cechowały się lepszym GUI.

Zaimplementowane wcześniej źródło logów generuje zdarzenia; aby jednak można było zobaczyć efekt, jakaś aplikacja musi je konsumować. Kolejna część artykułu wyjaśni, jak to zrobić za pomocą Semantic Logging Application. W tej chwili zostanie użyty po prostu PerfView jako odbiorca (konsument) zdarzeń. Wystarczy wybrać z menu głównego Collect->Collect (rysunek 5):

Rys. 5. Zbieranie zdarzeń za pomocą PerfView.

Należy pamiętać, aby w miejscu „Additional Providers” (rysunek 6) podać nazwę źródła logów, poprzedzając ją gwiazdką. Po kliknięciu „Start Collection” aplikacja będzie „konsumowała” wszystkie zdarzenia przechodzące przez infrastrukturę ETW:

Rys. 6. Określenie źródeł zdarzeń, które należy monitorować.

Kolejnym krokiem jest uruchomienie aplikacji i wysłanie kilku logów:

var logSource = new CustomEventSource();
logSource.Startup();
logSource.OpenFileStart("1.txt");

Po zatrzymaniu zbierania logów w PerfView można przejść do EventView i odnaleźć zebrane zdarzenia (rysunek 7):

Rys. 7. PerfView umożliwia wgląd w zebrane zdarzenia.

Podany parametr w metodzie c# jest tutaj wyświetlony w osobnej kolumnie. Każdy log w ETW ma z góry zdefiniowany format – silnie typowany. Jak to możliwe? Otóż każde źródło danych posiada manifest opisujący zmienne i ich typy. Manifest danego źródła łatwo sprawdzić – np. pisząc następujący kod:

string manifest = EventSource.GenerateManifest(typeof (CustomEventSource), null);

Rezultat:

<instrumentationManifest xmlns="https://schemas.microsoft.com/win/2004/08/events">
 <instrumentation xmlns:xs="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:win="http://manifests.microsoft.com/win/2004/08/windows/events">
  <events xmlns="https://schemas.microsoft.com/win/2004/08/events">
<provider name="CustomEventSource" guid="{ff6a40d2-5116-5555-675b-4468e821162e}" symbol="CustomEventSource">
 <tasks>
  <task name="OpenFileStop" value="65531"/>
  <task name="OpenFileStart" value="65532"/>
  <task name="Startup" value="65533"/>
 </tasks>
 <opcodes>
 </opcodes>
 <events>
  <event value="1" version="0" level="win:Informational" task="Startup"/>
  <event value="2" version="0" level="win:Informational" task="OpenFileStart" template="OpenFileStartArgs"/>
  <event value="3" version="0" level="win:Informational" task="OpenFileStop"/>
 </events>
 <templates>
  <template tid="OpenFileStartArgs">
   <data name="fileName" inType="win:UnicodeString"/>
  </template>
 </templates>
</provider>
</events>
</instrumentation>
<localization>
 <resources culture="en-GB">
  <stringTable>
  </stringTable>
 </resources>
</localization>
</instrumentationManifest>

Wszystkie pola mają zdefiniowane typy. Liczba całkowita, zatem zawsze musi być typem numerycznym, a nie np. string.

W praktyce, tworząc EventSource, również definiuje się atrybuty opisujące źródło (przykład z dokumentacji MSDN):

[EventSource(Name = "MyCompany")]
internal class MyCompanyEventSource : EventSource
{
    public class Keywords
    {
        public const EventKeywords Page = (EventKeywords) 1;
        public const EventKeywords DataBase = (EventKeywords) 2;
        public const EventKeywords Diagnostic = (EventKeywords) 4;
        public const EventKeywords Perf = (EventKeywords) 8;
    }

     public class Tasks
    {
        public const EventTask Page = (EventTask) 1;
        public const EventTask DBQuery = (EventTask) 2;
    }

    [Event(1, Message = "Application Falure: {0}", Level = EventLevel.Error, Keywords = Keywords.Diagnostic)]
    public void Failure(string message)
    {
        WriteEvent(1, message);
    }

    [Event(2, Message = "Starting up.", Keywords = Keywords.Perf, Level = EventLevel.Informational)]
    public void Startup()
    {
        WriteEvent(2);
    }

    [Event(3, Message = "loading page {1} activityID={0}", Opcode = EventOpcode.Start,Task = Tasks.Page, Keywords = Keywords.Page, Level = EventLevel.Informational)]
    public void PageStart(int ID, string url)
    {
        if (IsEnabled()) WriteEvent(3, ID, url);
    }

    [Event(4, Opcode = EventOpcode.Stop, Task = Tasks.Page, Keywords = Keywords.Page, Level = EventLevel.Informational)]
    public void PageStop(int ID)
    {
        if (IsEnabled()) WriteEvent(4, ID);
    }

    [Event(5, Opcode = EventOpcode.Start, Task = Tasks.DBQuery, Keywords = Keywords.DataBase,
        Level = EventLevel.Informational)]
    public void DBQueryStart(string sqlQuery)
    {
        WriteEvent(5, sqlQuery);
    }

    [Event(6, Opcode = EventOpcode.Stop, Task = Tasks.DBQuery, Keywords = Keywords.DataBase,
        Level = EventLevel.Informational)]
    public void DBQueryStop()
    {
        WriteEvent(6);
    }

    [Event(7, Level = EventLevel.Verbose, Keywords = Keywords.DataBase)]
    public void Mark(int ID)
    {
        if (IsEnabled()) WriteEvent(7, ID);
    }
}

Pierwszą różnicą jest dodanie atrybutu EventSource, za pomocą którego można podać dowolną nazwę. Domyślnie manifest jest generowany na podstawie nazw metod i klasy, co nie zawsze okazuje się odpowiednie. Kolejny atrybut to EventAttribute, dodawany do każdej metody. Pewną niedogodność stanowi to, że trzeba pamiętać, aby identyfikator zdarzenia przekazany w atrybucie pokrywał się z tym wykorzystywanym w WriteEvent.

Kolejną dobrą praktyką jest sprawdzanie, czy źródło zostało włączone za pomocą IsEnabled.

Za pomocą właściwości Message można określić wiadomość, która zostanie automatycznie wygenerowana. Przykładowo:

[Event(3, Message = "loading page {1} activityID={0}", Opcode = EventOpcode.Start,Task = Tasks.Page, Keywords = Keywords.Page, Level = EventLevel.Informational)]
public void PageStart(int ID, string url)
{
    if (IsEnabled()) WriteEvent(3, ID, url);
}

Ze zdarzeniem zostanie skojarzona wiadomość. Przekazane parametry (ID oraz url) zostaną wstawione odpowiednio w {0} i {1} – po prostu string. Format będzie wywołany na Message.

Właściwość Level jest chyba łatwa do zrozumienia – można przekazać takie wartości, jak Critical, Error, Informational czy Warning.

Wyjaśnienia wymagają za to właściwości Keywords oraz Task. Najpierw jako zagnieżdżoną klasę zdefiniowano słowa kluczowe, tj.:

public class Keywords
{
    public const EventKeywords Page = (EventKeywords) 1;
    public const EventKeywords DataBase = (EventKeywords) 2;
    public const EventKeywords Diagnostic = (EventKeywords) 4;
    public const EventKeywords Perf = (EventKeywords) 8;
}

Stanową one dość ważny element ETW. Za ich pomocą konsumenci mogą decydować, jakiego typu zdarzenia chcą monitować. Jeśli np. administratorzy chcą śledzić aplikację, bardzo często interesują ich wyłącznie specyficzne fragmenty systemu. Słowa kluczowe kojarzy się ze zdarzeniami za pomocą atrybutu:

[Event(3, Message = "loading page {1} activityID={0}", Opcode = EventOpcode.Start,Task = Tasks.Page, Keywords = Keywords.Page, Level = EventLevel.Informational)]

Analogicznie wygląda to w przypadku Tasks, które opisują, jaki typ zadania reprezentują zdarzenia. Z kolei EventOpcCode definiują konkretną operację w ramach zdefiniowanego zadania.

Zakończenie

ETW to znakomita infrastruktura, całkowicie zmieniająca podejście do monitorowania aplikacji. Nie jest to nowa technologia (była dość długo wspierana przez Windows), ale brak prostego API spowodował, że nie została spopularyzowana wśród programistów.

W artykule przedstawiono przede wszystkim czysty ETW – to niezbędne, aby w kolejnej części zająć się udogodnieniami dostarczonymi przez Enterprise Library i Semantic Logging Application. ETW przydaje się w scenariuszach, gdy niezbędne są analiza logów oraz monitorowanie aplikacji w czasie rzeczywistym. Jeśli aplikacja jest prosta, prawdopodobnie wystarczy zwykły plik tekstowy i nie dostrzeże się zalet nowej infrastruktury.

 

---

          

Piotr Zieliński

Absolwent informatyki o specjalizacji inżynieria oprogramowania Uniwersytetu Zielonogórskiego. Posiada szereg certyfikatów z technologii Microsoft (MCP, MCTS, MCPD). W 2011 roku wyróżniony nagrodą MVP w kategorii Visual C#. Aktualnie pracuje w General Electric pisząc oprogramowanie wykorzystywane w monitorowaniu transformatorów . Platformę .NET zna od wersji 1.1 – wcześniej wykorzystywał głównie MFC oraz C++ Builder. Interesuje się wieloma technologiami m.in. ASP.NET MVC, WPF, PRISM, WCF, WCF Data Services, WWF, Azure, Silverlight, WCF RIA Services, XNA, Entity Framework, nHibernate. Oprócz czystych technologii zajmuje się również wzorcami projektowymi, bezpieczeństwem aplikacji webowych i testowaniem oprogramowania od strony programisty. W wolnych chwilach prowadzi blog o .NET i tzw. patterns & practices.