dotNETportal.cz

Předem bych nejprve chtěl uvést, že rozhodně nejsem žádný expert na ETW technologii (z článku to asi bude vidět), pouze zde popíši informace, které jsem získal, když jsem technologii chtěl použít v mé aplikaci. Také mé překvapilo, že jsem nikde nenašel právě takovýto popis pro programátory co s technologii začínají a chtějí v co nejkratším čase implementovat základní trace s využitím ETW do aplikace. Pokud tedy máte s technologii nějaké zkušenosti, rozhodně se o ně podělte v komentářích.

Rozšíření článku modrou barvou.

Event Tracing for Windows (ETW)

Technologie Event Tracing for Windows (ETW) je tady s námi od systému Windows Vista. Jedná se o technologii pro sběr a zápis trasovacích informací z aplikací. Hlavní důvod proč použít tuto technologii je to, že díky její implementaci přímo v jádře se jedná o extrémně výkonné řešení pro zápis trasovacích informací. Díky tomu není aplikace při používání trace skoro vůbec výkonnostně ovlivněná.

Technologie má širokou podporu napříč Windows platformou, je rozšiřitelná, připravená i na distribuované prostředí, technologii dnes využívá již velký počet aplikací a služeb Windows jako např. IIS, SQL Server a .NET samotný. Trasovací informace můžeme přímo zaznamenávat a analyzovat prostředky systému, nebo pro ETW existují i různé nástroje třetích stran. Dále pro řešení na platformě Microsoft Azure je možné záznamy ukládat do sdíleného úložiště pomocí technologie Windows Azure Diagnostic.

ETW Providers

Zápis událostí probíhá pomoci ETW Providers. Tyto poskytovatelé poskytuje daná aplikace a mohou být zaregistrované ve Windows.

Pro jejich výpis slouží příkaz:

xperf -providers I

nebo

logman query providers

Vidíme, že ve Windows je těchto providerů již docela hodně, samotný .NET Framework jich používá několik, zkuste si příkaz:

xperf -providers I | Findstr ".NET"

a669021c-c450-4609-a035-5af59af4df18                              : Microsoft-Windows-DotNETRuntimeRundown
aff081fe-0247-4275-9c4e-021f3dc1da35                              : ASP.NET Events
bd568f20-fccd-b948-054e-db3421115d61                              : DBNETLIB.1
e13c0d23-ccbc-4e12-931b-d9cc2eee27e4                              : .NET Common Language Runtime
e13c0d23-ccbc-4e12-931b-d9cc2eee27e4                              : Microsoft-Windows-DotNETRuntime

Všimněte si, že každý provider má svůj jedinečný GUID, např. pro .NET CLR slouží provider .NET Common Language Runtime s GUID: e13c0d23-ccbc-4e12-931b-d9cc2eee27e4.

Zaznamenání událostí

Zkusme si zaznamenat události z tohoto .NET Common Language Runtime provideru. Výhodou je, že zaznamenání můžeme zapnout klidně až poté co aplikace běží, nemusíme jí registrovat nebo restartovat. Pro zaznamenání použijeme jeden z příkazů:

xperf -start clr -on ".NET Common Language Runtime" -f clrevents.etl
xperf -start clr -on e13c0d23-ccbc-4e12-931b-d9cc2eee27e4 -f clrevents.etl

kde spouštíme zaznamenávání pod jménem clr z providera určeného buď jménem (první varianta) nebo GUIDem, do souboru clrevents.etl.

Zastavení provedeme příkazem:

xperf -stop clr

Pokud uložený soubor clrevents.etl otevřeme přímo, najede nám nástroj Windows Performance Analyzer, ve kterém sice vidíme časové rozložení událostí, ale události jsou bez veškerých popisů. Jak jsem pochopil tak by se muselo pomoci Windows Performance Toolkit vytvořit nějaké popisné xml (soubor .wprp).

Pro naší potřebu zobrazit zaznamenané události použijeme jiný nástroj - PerfView.exe – ke stažení je zde.

Po spuštění PerfView vybereme složku se souborem a v něm zvolíme prvek Events.

V Events okně pak již vidíme zaznamenané události, na obrázku jsou např. zobrazeny výskyty jedné událostí .NET Garbage Collectoru.

Ještě je jiná možnost spuštění zaznamenání událostí přímo pomoci nástroje PrefView příkazem:
PerfView /onlyProviders=e13c0d23-ccbc-4e12-931b-d9cc2eee27e4 collect
PerfView /onlyProviders=".NET Common Language Runtime" collect

Tak to by jako krátký úvod stačilo, nyní se již podíváme jak ETW naimplementovat do naší .NET aplikace.

Implementace v .NET

V prostředí .NET je podpora pro technologii ETW až od verze .NET 4.5 pomoci třídy System.Diagnostics.Tracing.EventSource. Druhou možnosti je použít Nuget balíček Microsoft.Diagnostics.Tracing.EventSource, který nám jednak umožňuje technologii ETW využít i ve starších .NET Frameworkcích (ale pozor, že ve Windows XP technologie stejně dostupná není, takže není moc důvod nepřejít na .NET 4.5). Druhou volbou, proč po Nugetu šáhnout může být to, že v něm jsou některé rozšířené funkcionality, které se zatím do .NET Frameworku nedostali. Já zatím zůstanu u té standardní implementace součásti Frameworku.

Vytvořením vlastní třídy odvozené z třídy EventSource implementujeme náš vlastní ETW provider. V něm deklarujeme, které události budeme chtít v aplikaci tracovat. Ukážeme si to rovnou na příkladu takové třídy, kterou jsem v aplikaci použil:

/// <summary>
/// Event Tracing for Windows (ETW) event provider for application
/// </summary>
/// <remarks>
/// Capture events command:
/// xperf -start usersession -on 71C65474-E573-4117-B374-A8BC8205860A -f usersession.etl
/// xperf -stop usersession
/// </remarks>
[EventSource(Name = "MyApplication-Tracing-Provider", Guid = "{71C65474-E573-4117-B374-A8BC8205860A}")]
public sealed class MyTraceEventSource : EventSource
{
    public static MyTraceEventSource Trace = new MyTraceEventSource();

    private MyTraceEventSource() { }

    #region action methods
    //if the order of the methods don’t match ordinal number position in the class it would fail generating ETW traces.
    //The EventSource has dependency on the order of the methods in the class.

    [Event(1, Level = EventLevel.Informational)]
    public void ApplicationInfo(string message) { WriteTrace(1, message); }

    [Event(2, Level = EventLevel.Warning)]
    public void ApplicationWarning(string message) { WriteTrace(2, message); }

    [Event(3, Level = EventLevel.Error)]
    public void Exception(string message) { WriteTrace(3, message); }

    [Event(4, Level = EventLevel.Informational)]
    public void SQLTrace(string message) { WriteTrace(4, message); }
    #endregion

    #region private member functions
    private void WriteTrace(int id, string message)
    {
#if DEBUG
        string eventName = new System.Diagnostics.StackTrace().GetFrame(1).GetMethod().Name;
        var eventAttribute = (EventAttribute)new System.Diagnostics.StackTrace().GetFrame(1).GetMethod().GetCustomAttributes(typeof(EventAttribute), false)[0];

        System.Diagnostics.Debug.WriteLine($"{eventName} ({eventAttribute.Level.ToString()}): {message}");
#endif
        if (IsEnabled())
        {
            WriteEvent(id, message);
        }
    }
    #endregion
}

Při implementaci této třídy odvozené z EventSource to ale není tak jednoduché. Sice se po nás požaduje pouze volání metody WriteEvent. Já to zde tak činím ještě pomoci metody WriteTrace, ve které zapisuji i do standardního debug výstupu, aby se mi události vypisovali i ve Visual Studiu při laděni (protože Visual Studio nemá žádnou automatickou podporu na vypisování ETW událostí).

V čem je tedy problém s EventSource třídou? Všimněte si, že se nikde neuvádí jméno trace události, jméno události je totiž odvozeno samo pomoci reflekce z této třídy. Přičemž musí platit, že event id, se kterým se WriteEvent volá, musí být stejné jako to, které se uvede v Event atributu (pokud atribut použijeme, což doporučuji). Dále také záleží na pořadí metod ve třídě - ty musí být uvedeny ve stejném pořadí jako jsou použité event id v jejich volání. Z toho také plyne, že každý event musíme zavést natvrdo jako metodu, nemůžeme například mít jednu obecnou metodu, ve které by jsme event id posílali parametrem.

Použití třídy pro volání zápisu trace události pak bude v naší aplikaci například takto:

MyTraceEventSource.Trace.ApplicationInfo("Initializing...");

Po spuštění aplikace necháme události zaznamenat dříve popsaným způsobem, např. příkazy:

xperf -start usersession -on 71C65474-E573-4117-B374-A8BC8205860A -f usersession.etl

xperf -stop usersession

Zde volám providera určeného pomoci GUID, které je uvedeno v atributu u naší EventSource třídy, což funguje. Nepřišel jsem ale na to, jak našeho providera zaregistrovat do systému (aby byl v providerech seznamu xperf -providers I) a jak mu přiřadit nějaké jméno, aby šlo zaznamenávání volat kromě GUIDu i s určením tohoto jména.

Abychom nepotřebovali GUID, tak můžeme zaznamenávání spustit pomoci
PerfView /onlyProviders=*MyApplication-Tracing-Provider collect

A na to jak event zaregistrovat do systému jsem také už našel odpověď, je to spojeno s funkcí ETW Channel. Nejprve musíme nechat při kompilaci vytvořit soubory .man a manifest .dll. To provedeme tak, že to projektu nainstalujeme NuGet balíček Microsoft.Diagnostics.Tracing.EventRegister. Tento balíček vloží do MSBuild procesu volání utility eventRegister.exe, která po kompilaci ve výstupním adresáři vytvoří soubory:
<AssemblyName>.<EventSourceTypeName>.etwManifest.man
<AssemblyName>.<EventSourceTypeName>.etwManifest.dll
K tomu je ještě nutné, aby byla v EventSource třídě alespoň jedna událost v atributu Event s parametrem Channel (a při EventChannel.Admin ještě parametr Message). Také se doporučuje při tomto postupu GUID ve třídě neuvádět.

Nyní musíme tyto soubory zaregistrovat příkazem:
wevtutil.exe im "<EtwManifestManFile>" /rf:"<EtwManifestDllFullPathName>" /mf:"<EtwManifestDllFullPathName>"
neboli
wevtutil.exe im "c:\..\ETWTest.MyApplication-Tracing-Provider.etwManifest.man" /rf:"c:\..\ETWTest.MyApplication-Tracing-Provider.etwManifest.dll" /mf:"c:\..\ETWTest.MyApplication-Tracing-Provider.etwManifest.dll"
Nyní xperf -providers I | Findstr "MyApplication" bude vracet zaregistrovaný provider v systému.

Pokud použijeme Channel Admin nebo Operational, tak se zároveň budou události zapisovat i do EventLogu, který se registrací vytvoří v sekci Application and Services Logs podle názvu našeho EventSource:

K odregistraci pak slouží příkaz:
wevtutil.exe um <EtwManifestManFile>

Tak a ještě jedna možnost jak zaznamenávat události, přímo pomoci Performance Monitoru. V sekci Data Collector Sets\Event Trace Sessions můžeme v definici nového Data Collection Set vybrat náš zaregistrovaný EventSource.

Po zaznamenání a zobrazení v PerfView opravdu vidíme v seznamu naše události definované jednotlivými metodami naší třídy.

Další zroje

Některé další zdroje, ze kterých jsem čerpal:

http://geekswithblogs.net/akraus1/archive/2013/08/21/153804.aspx
http://blogs.msdn.com/b/vancem/archive/2012/07/09/logging-your-own-etw-events-in-c-system-diagnostics-tracing-eventsource.aspx
http://naveensrinivasan.com/category/net/etw-net/
http://blogs.msdn.com/cfs-filesystemfile.ashx/__key/communityserver-components-postattachments/00-10-44-08-22/_5F00_EventSourceUsersGuide.docx
https://github.com/mspnp/azure-guidance/blob/master/Monitoring.md
Velkým zdrojem jsou příklady a dokumentace obsažené v NuGet balíčku Microsoft EventSource Library Samples.