Zine.net online

Witaj na Zine.net online Zaloguj się | Rejestracja | Pomoc
w Szukaj

mgrzeg.net - Admin on Rails :)

ETW - providery + target dla NLoga

Jednym z podstawowych elementów architektury ETW są dostawcy zdarzeń, czyli ETW providers. Dostawca ma nazwę, guid i parę innych rzeczy, a jego podstawowym zadaniem jest dostarczanie zdarzeń w ramach sesji ETW (zwanej także loggerem). Sesja zostaje utworzona przez kontroler (ETW controller), czyli narzędzie takie jak np. xperf, logman, wpr, czy perfview, którym dzisiaj trochę się pobawimy. Po zakończeniu sesji możemy przejrzeć zawartość logu, korzystając z narzędzia do parsowania i analizy logów (ETW consumer) - czyli np. omawianymi w poprzednim wpisie xperf, xperfview, wpa, ale także perfview, czy event viewer, żeby wymienić tylko kilka.

Listę aktywnych sesji w systemie, wraz z wieloma informacjami (nazwa, rozmiar bufora, flagi, etc.) możemy uzyskać za pomocą:

>xperf -loggers
Logger Name           : Circular Kernel Context Logger
Logger Id             : 2
Logger Thread Id      : 0000000000000000
Buffer Size           : 4
Maximum Buffers       : 2
Minimum Buffers       : 2
Number of Buffers     : 2
Free Buffers          : 1
Buffers Written       : 0
Events Lost           : 0
Log Buffers Lost      : 0
Real Time Buffers Lost: 0
Flush Timer           : 0
Age Limit             : 0
Log File Mode         : Secure Buffered <0x10000000>
Maximum File Size     : 0
Log Filename          :
Trace Flags           : LOADER+HARD_FAULTS
PoolTagFilter         : *

Logger Name           : Audio
Logger Id             : 4
Logger Thread Id      : 0000000000000000
Buffer Size           : 4
Maximum Buffers       : 2
Minimum Buffers       : 2
Number of Buffers     : 2
Free Buffers          : 1
Buffers Written       : 0
Events Lost           : 0
Log Buffers Lost      : 0
Real Time Buffers Lost: 0
Flush Timer           : 0
Age Limit             : 0
Log File Mode         : Buffered LocalSeqNo <0x10000000>
Maximum File Size     : 2
Log Filename          :
Trace Flags           : e27950eb-1768-451f-96ac-cc4e14f6d3d0:0x7fffffff:0x4
[CIACH]

W systemie może być aktywna tylko jedna sesja jądra, która ma specjalną nazwę: “NT Kernel Logger”. Ze względu na to ograniczenie nie można np. mieć równocześnie uruchomionego procmona (process hackera) i np. utworzyć sesji jądra w perfview, ponieważ taką zainicjował już wcześniej procmon (PH). Można jednak do takiej sesji podłączyć się innym konsumentem i ewentualnie ją zmodyfikować (dodając np. dodatkowe flagi).
Listę wszystkich dostawców możemy otrzymać przy pomocy:

>xperf -providers
Known User Mode Providers:
 0063715b-eeda-4007-9429-ad526f62696e   : Microsoft-Windows-Services
 01090065-b467-4503-9b28-533766761087   : Microsoft-Windows-ParentalControls
 014de49f-ce63-4779-ba2b-d616f6963a87   : Microsoft-Windows-NetworkConnectivityStatus
 01578f96-c270-4602-ade0-578d9c29fc0c   : Microsoft-Windows-VAN
 017247f2-7e96-11dc-8314-0800200c9a66   : Microsoft-Windows-ErrorReportingConsole
 017ba13c-9a55-4f1f-8200-323055aac810   : Microsoft-Windows-Registry-SQM-Provider
 01979c6a-42fa-414c-b8aa-eee2c8202018   : Microsoft-Windows-WindowsBackup
 02012a8a-adf5-4fab-92cb-ccb7bb3e689a   : Microsoft-Windows-ShareMedia-ControlPanel
 02fe721a-0725-469e-a26d-37b3c09faac1   : Portable Device Connectivity API Trace
[CIACH]

przy czym możemy także zawęzić listę do np. zainstalowanych (znanych), lub zarejestrowanych w danym momencie w systemie (pełna lista opcji w xperf -help providers). Gdy chcemy zobaczyć, jacy dostawcy zarejestrowani są przez dany proces, to korzystamy z:

>logman query providers -pid [PID]

np.:

>tlist | findstr -i notepad.exe
7844 notepad.exe       Default IME

>logman query providers -pid 7844

Dostawca                   Identyfikator GUID
-------------------------------------------------------------------------------
Microsoft-Windows-Documents              {C89B991E-3B48-49B2-80D3-AC000DFC9749}
Microsoft-Windows-Dwm-Api                {92AE46D7-6D9C-4727-9ED5-E49AF9C24CBF}
Microsoft-Windows-KnownFolders           {8939299F-2315-4C5C-9B91-ABB86AA0627D}
Microsoft-Windows-PrintService           {747EF6FD-E535-4D16-B510-42C90F6873A1}
Microsoft-Windows-Shell-Core             {30336ED4-E327-447C-9DE0-51B652C86108}
Microsoft-Windows-TSF-msctf              {4FBA1227-F606-4E5F-B9E8-FAB9AB5740F3}
Microsoft-Windows-UxTheme                {422088E6-CD0C-4F99-BD0B-6985FA290BDF}
{2955E23C-4E0B-45CA-A181-6EE442CA1FC0}   {2955E23C-4E0B-45CA-A181-6EE442CA1FC0}
{6097799C-99DF-4C32-BF88-A32958C6421A}   {6097799C-99DF-4C32-BF88-A32958C6421A}
{69D3F5B6-6605-4EF9-B6A0-BC0233BD2CA6}   {69D3F5B6-6605-4EF9-B6A0-BC0233BD2CA6}
{A323CDC2-81B0-48B2-80C8-B749A221478A}   {A323CDC2-81B0-48B2-80C8-B749A221478A}
{BCEBF131-E4E6-4BA4-82FA-9C406002F769}   {BCEBF131-E4E6-4BA4-82FA-9C406002F769}
{BDA92AE8-9F11-4D49-BA1D-A4C2ABCA692E}   {BDA92AE8-9F11-4D49-BA1D-A4C2ABCA692E}
{C9BF4A02-D547-4D11-8242-E03A18B5BE01}   {C9BF4A02-D547-4D11-8242-E03A18B5BE01}

Polecenie zostało wykonane pomyślnie.

Z każdym z powyższych providerów skojarzony jest jeden, lub więcej uchwytów (rączek ;)), które z łatwością dostrzeżemy w Process Hackerze w zakładce Handles jako “EtwRegistration”.

Rys 1. EtwRegistration widoczne na liście uchwytów otwartych przez aplikację

Kiedyś jeszcze wrócimy do tych narzędzi, a teraz przejdźmy do czegoś ciekawszego.

Własny provider - przykład z NLogiem

Wraz z pojawieniem się .NET Framework 4.5 i przestrzeni System.Diagnostics.Tracing tworzenie własnego providera stało się bardzo proste. Z pomocą klasy EventSource możemy w kilku linijkach dodać możliwość logowania w ramach ETW.

W lipcu b.r. Vance Morrison (architekt w zespole zajmującym się wydajnością środowiska uruchomieniowego - .NET Runtime Team) zapowiedział na swoim blogu nowości oraz udostępnił bibliotekę, która zawiera wspomnianą przestrzeń i jest dostępna dla wcześniejszych wersji .NET Framework (3.5+).

Korzystając z niej przygotowałem prosty target dla NLoga, który pozwala na logowanie komunikatów wprost do ETW.

using System;
using System.Diagnostics;
using System.Diagnostics.Tracing;

using NLog;
using NLog.Targets;

namespace Zine.ETWNlogTarget
{
  [Target("ETW")]
  public sealed class ETWTarget : TargetWithLayout
  {
    sealed class NLogETWTargetSource : EventSource
    {
      public static NLogETWTargetSource Log = new NLogETWTargetSource();
      public void Message(string Message) {
        WriteEvent(1, Message);
      }
    }

    protected override void Write(LogEventInfo logEvent)
    {
      string logMessage = this.Layout.Render(logEvent);
      Write(logMessage);
    }

    private void Write(string logMsg)
    {
      if (string.IsNullOrEmpty(logMsg)) return;
      NLogETWTargetSource.Log.Message(logMsg);
    }
  }
}

Weźmy teraz przykład prostej aplikacji:

using System;

using NLog;

namespace ZineNlogTester
{
 class Program
 {
  private static Logger logger = LogManager.GetCurrentClassLogger();

  static void Main(string[] args)
  {
   using (new OperationTimer("Debug"))
   {
    for (int i = 0; i < 10000; i++)
    {
     logger.Debug(i.ToString());
    }
   }
  }
 }
}

(gdzie OperationTimer wykorzystuje Stopwatch do pomiaru czasu pomiędzy początkiem i końcem pętli) i skorzystajmy z przygotowanego wcześniej targeta, który dołączymy do aplikacji następującym plikiem nlog.config:

<?xml version="1.0" encoding="utf-8" ?>
<
nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">

 <extensions>
  <
add assembly="Zine.ETWNlogTarget"/>
 </
extensions>

 <
targets>
  <
target name="etw" type="ETW" layout="NLOG: ${message}" />
 </targets>

 <
rules>
  <
logger name="*" minLevel="Debug" writeTo="etw"/>
 </
rules>

</
nlog> 

Do zebrania tak wygenerowanych komunikatów użyjemy Perfview, przy czym w ustawieniach zbieracza dodamy nasz provider dopisując *{nazwa_klasy} 

Rys 2. Ustawienia sesji logowania w PerfView

Testy

Zróbmy teraz kilka testów:

1. Uruchamiamy aplikację testową bez włączonego Collecta (zdarzenia ETW trafiają w próżnię). Czas: 0,0179 sek., co sprowadza się do możliwości wygenerowania ok. pół miliona zdarzeń w ciągu sekundy.

2. Włączamy ‘Start collection’ i uruchamiamy aplikację. Czas: 0,0373 sek, czyli możemy zebrać ok. ćwierć miliona zdarzeń na sekundę.

3. Zmieniamy target na File:

<target name="file" xsi:type="File" layout="NLOG: ${message}" fileName="${basedir}/logs/logfile.txt" keepFileOpen="true" encoding="iso-8859-2" />

i dostajemy logfile.txt, a czas: 0,1450 sek, czyli ok. 70 tys. zdarzeń na sekundę.

4. I na sam koniec bierzemy target Null:

<target name="null" type="Null" layout="NLOG: ${message}" />

i czasy: 0,0051 sek., czyli NLog na moim komputerze może wygenerować ok. 2 mln zdarzeń trafiających w próżnię, przy podanej aplikacji i ustawieniach NLoga.

Po zatrzymaniu zbieracza wygenerowany zostanie zestaw plików .etl, przy czym interesujące nas dane znajdują się w pliku PerfViewData.etl. Po otwarciu go zaglądamy do Events, gdzie w filtrze wpisujemy NLog i zaglądamy do zdarzeń zebranych jako NLogETWTargetSource/Message

Rys 3. Zdarzenia związane z targetem dołączonym do NLoga

Kod jest nasz, więc w CPU Stacks dla naszego procesu możemy ustawić ścieżkę do symboli, po czym grzecznie je wczytać i następnie zajrzeć do zakładki CallTree. Po trafieniu na naszą funkcję możemy zajrzeć do źródła, w których PerfView dodatkowo dopisuje własne metryki.

Rys 4. Stacks + źródło w PerfView

Przyznaję szczerze, że walka z ‘broken stacks’ dla kodu zarządzanego w Windows 7 x64 jest ciężka i wyczerpująca (podobno pod Win8 wszystko działa bez problemu) i nie udało mi się nad tym zapanować (choć na rysunku powyżej stos wywołań niby jest).

Rys 5. Komunikat o problemach z analizą stosu wywołań

Na koniec lista sesji ustawionych przez PerfView w trakcie zbierania danych:

Logger Name           : NT Kernel Logger
Logger Id             : ffff
Logger Thread Id      : 000000000000161C
Buffer Size           : 1024
Maximum Buffers       : 256
Minimum Buffers       : 64
Number of Buffers     : 64
Free Buffers          : 56
Buffers Written       : 11
Events Lost           : 0
Log Buffers Lost      : 0
Real Time Buffers Lost: 0
Flush Timer           : 10
Age Limit             : 0
Log File Mode         : Circular Secure
Maximum File Size     : 500
Log Filename          : C:\Roboczy\Dumps\ETL\NLog\PerfViewData.kernel.etl
Trace Flags           : PROC_THREAD+LOADER+PERF_COUNTER+DISK_IO+DISK_IO_INIT+HARD_FAULTS+FILENAME+NETWORKTRACE+PROFILE
PoolTagFilter         : *


Logger Name           : PerfViewSession
Logger Id             : f
Logger Thread Id      : 0000000000002394
Buffer Size           : 1024
Maximum Buffers       : 256
Minimum Buffers       : 64
Number of Buffers     : 64
Free Buffers          : 60
Buffers Written       : 1
Events Lost           : 0
Log Buffers Lost      : 0
Real Time Buffers Lost: 0
Flush Timer           : 10
Age Limit             : 0
Log File Mode         : Circular
Maximum File Size     : 400
Log Filename          : C:\Roboczy\Dumps\ETL\NLog\PerfViewData.etl
Trace Flags           : d9b1ff2e-1e4a-5db6-f885-423ece896a35:0xffffffffffffffff:0x5+57277741-3638-4a4b-bdba-0ac6e45da56c:0xffffffffffffffff:0x5+"Microsoft-Windows-Application Server-Applications":0xffffffffffffffff:0x4+"ASP.NET Events":0xfffffffffffffffd:0x5+a8a71ac1-040f-54a2-07ca-00a89b5ab761:0xffffffffffffffff:0x5+2e5dba47-a3d2-4d16-8ee0-6671ffdcd7b5:0xffffffffffffffff:0x5+763fd754-7086-4dfe-95eb-c01a46faf4ca:0x40020001:0x5+".NET Common Language Runtime":0x4007cc9d:0x5+"Microsoft-PerfTrack-MSHTML":0xffffffffffffffff:0x5+"Microsoft-PerfTrack-IEFRAME":0xffffffffffffffff:0x5+"Microsoft-Windows-WinINet":0x2:0x5

Interesujący nas provider kryje się oczywiście w sesji użytkownika i włączony jest przez PerfView następująco:
d9b1ff2e-1e4a-5db6-f885-423ece896a35:0xffffffffffffffff:0x5

(składnia: ProviderName:Keyword:Level:’stack[,]sid[,]tsid’ (za ‘Inside Windows Debugging’))

Jeśli kogoś zainteresowały możliwości PerfView, to polecam gorąco serię videocastów poświęconą temu właśnie narzędziu: [Vance Morrison o PerfView]

Zagadka

Dla wytrwałych i gotowych do drążenia tematu - zagadka.

Provider rejestrowany jest przez aplikację dynamicznie, skąd więc PerfView wie jaki jest guid naszego providera jeszcze przed uruchomieniem aplikacji?

Opublikowane 23 października 2012 20:35 przez mgrzeg
Filed under: , ,

Powiadamianie o komentarzach

Jeżeli chciałbyś otrzymywać email gdy ta wypowiedź zostanie zaktualizowana, to zarejestruj się tutaj

Subskrybuj komentarze za pomocą RSS

Co o tym myślisz?

(wymagane) 
(opcjonalne)
(wymagane) 

  
Wprowadź kod: (wymagane)
Wyślij

Subskrypcje

W oparciu o Community Server (Personal Edition), Telligent Systems