Olvasás angol nyelven

Megosztás a következőn keresztül:

EventSource-tevékenységazonosítók

  • Cikk

Ez a cikk a .NET Core 3.1 és újabb verzióira ✔️ ✔️ vonatkozik, .NET-keretrendszer 4.5-ös és újabb verziókra

Ez az útmutató ismerteti a tevékenységazonosítókat, egy opcionális azonosítót, amely naplózható minden, a használatával létrehozott eseménysel System.Diagnostics.Tracing.EventSource. Bevezetésként tekintse meg az EventSource használatának első lépéseit.

Az egyidejű naplózási munka kihívása

Régen egy tipikus alkalmazás lehet egyszerű és egyszálú, ami megkönnyíti a naplózást. Minden lépést megírhat egy naplófájlba sorrendben, majd pontosan abban a sorrendben olvashatja vissza a naplót, hogy megértse, mi történt. Ha az alkalmazás kezelte a kérelmeket, akkor egyszerre csak egy kérést kezeltek. Az A kéréshez tartozó összes naplóüzenetet a rendszer sorrendben nyomtatja ki, majd a B összes üzenetét stb. Ha az alkalmazások többszálúvá válnak, ez a stratégia már nem működik, mert egyszerre több kérést is kezelnek. Ha azonban minden kérés egyetlen szálhoz van rendelve, amely teljes egészében feldolgozza azt, akkor a problémát úgy oldhatja meg, hogy rögzít egy szálazonosítót az egyes naplóüzenetekhez. Egy többszálas alkalmazás például naplózható:

Thread Id      Message
---------      -------
12             BeginRequest A
12             Doing some work
190            BeginRequest B
12             uh-oh error happened
190            Doing some work

A szálazonosítók olvasásával tudja, hogy a 12. szál feldolgozta az A kérést, a 190. szál pedig a B kérést, ezért az "uh-oh hiba történt" üzenet az A kéréssel kapcsolatos. Az alkalmazás egyidejűsége azonban egyre kifinomultabbá vált. Most már gyakran használják async , és await így egyetlen kérést lehet kezelni részben több különböző szálon, mielőtt a munka befejeződött volna. A szálazonosítók már nem elegendőek az egy kéréshez létrehozott összes üzenet egymással való összekapcsolásához. A tevékenységazonosítók megoldják ezt a problémát. Finomabb szemcsés azonosítót biztosítanak, amely nyomon követheti az egyes kéréseket vagy a kérések egyes részeit, függetlenül attól, hogy a munka különböző szálakon oszlik-e el.

Megjegyzés

Az itt említett tevékenységazonosító fogalma nem ugyanaz, mint a System.Diagnostics.Tracing.Activity, a hasonló elnevezés ellenére.

Tevékenységazonosítóval végzett munka nyomon követése

Az alábbi kód futtatásával működés közben láthatja a tevékenységkövetést.

using System.Diagnostics.Tracing;

public static class Program
{
    public static async Task Main(string[] args)
    {
        ConsoleWriterEventListener listener = new ConsoleWriterEventListener();

        Task a = ProcessWorkItem("A");
        Task b = ProcessWorkItem("B");
        await Task.WhenAll(a, b);
    }

    private static async Task ProcessWorkItem(string requestName)
    {
        DemoEventSource.Log.WorkStart(requestName);
        await HelperA();
        await HelperB();
        DemoEventSource.Log.WorkStop();
    }

    private static async Task HelperA()
    {
        DemoEventSource.Log.DebugMessage("HelperA");
        await Task.Delay(100); // pretend to do some work
    }

    private static async Task HelperB()
    {
        DemoEventSource.Log.DebugMessage("HelperB");
        await Task.Delay(100); // pretend to do some work
    }
}

[EventSource(Name ="Demo")]
class DemoEventSource : EventSource
{
    public static DemoEventSource Log = new DemoEventSource();

    [Event(1)]
    public void WorkStart(string requestName) => WriteEvent(1, requestName);
    [Event(2)]
    public void WorkStop() => WriteEvent(2);

    [Event(3)]
    public void DebugMessage(string message) => WriteEvent(3, message);
}

class ConsoleWriterEventListener : EventListener
{
    protected override void OnEventSourceCreated(EventSource eventSource)
    {
        if(eventSource.Name == "Demo")
        {
            Console.WriteLine("{0,-5} {1,-40} {2,-15} {3}", "TID", "Activity ID", "Event", "Arguments");
            EnableEvents(eventSource, EventLevel.Verbose);
        }
        else if(eventSource.Name == "System.Threading.Tasks.TplEventSource")
        {
            // Activity IDs aren't enabled by default.
            // Enabling Keyword 0x80 on the TplEventSource turns them on
            EnableEvents(eventSource, EventLevel.LogAlways, (EventKeywords)0x80);
        }
    }

    protected override void OnEventWritten(EventWrittenEventArgs eventData)
    {
        lock (this)
        {
            Console.Write("{0,-5} {1,-40} {2,-15} ", eventData.OSThreadId, eventData.ActivityId, eventData.EventName);
            if (eventData.Payload.Count == 1)
            {
                Console.WriteLine(eventData.Payload[0]);
            }
            else
            {
                Console.WriteLine();
            }
        }
    }
}

Futtatáskor ez a kód a következő kimenetet nyomtatja ki:

TID   Activity ID                              Event           Arguments
21256 00000011-0000-0000-0000-00006ab99d59     WorkStart       A
21256 00000011-0000-0000-0000-00006ab99d59     DebugMessage    HelperA
21256 00000012-0000-0000-0000-00006bb99d59     WorkStart       B
21256 00000012-0000-0000-0000-00006bb99d59     DebugMessage    HelperA
14728 00000011-0000-0000-0000-00006ab99d59     DebugMessage    HelperB
11348 00000012-0000-0000-0000-00006bb99d59     DebugMessage    HelperB
11348 00000012-0000-0000-0000-00006bb99d59     WorkStop
14728 00000011-0000-0000-0000-00006ab99d59     WorkStop

Megjegyzés

Van egy ismert probléma, amely miatt a Visual Studio hibakeresője érvénytelen tevékenységazonosítókat okozhat. Vagy ne futtassa ezt a mintát a hibakereső alatt, vagy állítson be töréspontot a Main elején, és értékelje ki a "System.Threading.Tasks.TplEventSource.Log.TasksSetActivityIds = false" kifejezést a közvetlen ablakban, mielőtt folytatná a probléma megkerülését.

A tevékenységazonosítók használatával láthatja, hogy az A munkaelem összes üzenete rendelkezik azonosítóval 00000011-... , a B munkaelemhez tartozó összes üzenet pedig azonosítóval 00000012-.... Mindkét munkaelem először a 21256-os szálon végzett némi munkát, de aztán mindegyikük folytatta a munkát az 11348-ban és az 14728-ban, így a kérés nyomon követése csak szálazonosítókkal nem működött volna.

Az EventSource egy automatikus heurisztikus megoldással rendelkezik, amely egy _Something_Start nevű eseményt határoz meg, amelyet közvetlenül egy másik, _Something_Stop nevű esemény követ, amely egy munkaegység kezdetének és leállításának tekinthető. Az új munkaegység kezdési eseményének naplózása új tevékenységazonosítót hoz létre, és megkezdi az összes esemény naplózását ugyanazon a szálon a tevékenységazonosítóval, amíg a leállítási esemény nem lesz naplózva. Az azonosító automatikusan követi az aszinkron vezérlőfolyamatot a használat async és awaita . Bár azt javasoljuk, hogy használja a Start/Stop elnevezési utótagokat, az eseményeket tetszés szerint nevezheti el úgy, hogy explicit módon jegyzeteli őket a EventAttribute.Opcode tulajdonság használatával. Állítsa be az első eseményt a következőre EventOpcode.Start , a másodikat pedig a következőre EventOpcode.Stop.

Párhuzamos munkát igénylő naplókérések

Előfordulhat, hogy egy kérelem a munka különböző részeit hajtja végre párhuzamosan, és az összes naplóeseményt és alrészt csoportosítani szeretné. Az alábbi példa egy olyan kérést szimulál, amely két adatbázis-lekérdezést végez párhuzamosan, majd feldolgozza az egyes lekérdezések eredményét. El szeretné különíteni az egyes lekérdezések munkáját, de azt is tudni szeretné, hogy mely lekérdezések tartoznak ugyanahhoz a kéréshez, amikor több egyidejű kérés is futhat. Ez egy faként van modellezve, ahol minden legfelső szintű kérés gyökér, majd a munka részjelentései ágak. A fa minden csomópontja saját tevékenységazonosítót kap, és az új gyermektevékenység-azonosítóval naplózott első esemény naplóz egy további, Kapcsolódó tevékenységazonosító nevű mezőt a szülő leírásához.

Futtassa az alábbi kódot:

using System.Diagnostics.Tracing;

public static class Program
{
    public static async Task Main(string[] args)
    {
        ConsoleWriterEventListener listener = new ConsoleWriterEventListener();

        await ProcessWorkItem("A");
    }

    private static async Task ProcessWorkItem(string requestName)
    {
        DemoEventSource.Log.WorkStart(requestName);
        Task query1 = Query("SELECT bowls");
        Task query2 = Query("SELECT spoons");
        await Task.WhenAll(query1, query2);
        DemoEventSource.Log.WorkStop();
    }

    private static async Task Query(string query)
    {
        DemoEventSource.Log.QueryStart(query);
        await Task.Delay(100); // pretend to send a query
        DemoEventSource.Log.DebugMessage("processing query");
        await Task.Delay(100); // pretend to do some work
        DemoEventSource.Log.QueryStop();
    }
}

[EventSource(Name = "Demo")]
class DemoEventSource : EventSource
{
    public static DemoEventSource Log = new DemoEventSource();

    [Event(1)]
    public void WorkStart(string requestName) => WriteEvent(1, requestName);
    [Event(2)]
    public void WorkStop() => WriteEvent(2);
    [Event(3)]
    public void DebugMessage(string message) => WriteEvent(3, message);
    [Event(4)]
    public void QueryStart(string query) => WriteEvent(4, query);
    [Event(5)]
    public void QueryStop() => WriteEvent(5);
}

class ConsoleWriterEventListener : EventListener
{
    protected override void OnEventSourceCreated(EventSource eventSource)
    {
        if (eventSource.Name == "Demo")
        {
            Console.WriteLine("{0,-5} {1,-40} {2,-40} {3,-15} {4}", "TID", "Activity ID", "Related Activity ID", "Event", "Arguments");
            EnableEvents(eventSource, EventLevel.Verbose);
        }
        else if (eventSource.Name == "System.Threading.Tasks.TplEventSource")
        {
            // Activity IDs aren't enabled by default.
            // Enabling Keyword 0x80 on the TplEventSource turns them on
            EnableEvents(eventSource, EventLevel.LogAlways, (EventKeywords)0x80);
        }
    }

    protected override void OnEventWritten(EventWrittenEventArgs eventData)
    {
        lock (this)
        {
            Console.Write("{0,-5} {1,-40} {2, -40} {3,-15} ", eventData.OSThreadId, eventData.ActivityId, eventData.RelatedActivityId, eventData.EventName);
            if (eventData.Payload.Count == 1)
            {
                Console.WriteLine(eventData.Payload[0]);
            }
            else
            {
                Console.WriteLine();
            }
        }
    }
}

Ez a példa a következő kimenetet nyomtatja ki:

TID   Activity ID                              Related Activity ID                      Event           Arguments
34276 00000011-0000-0000-0000-000086af9d59     00000000-0000-0000-0000-000000000000     WorkStart       A
34276 00001011-0000-0000-0000-0000869f9d59     00000011-0000-0000-0000-000086af9d59     QueryStart      SELECT bowls
34276 00002011-0000-0000-0000-0000868f9d59     00000011-0000-0000-0000-000086af9d59     QueryStart      SELECT spoons
32684 00002011-0000-0000-0000-0000868f9d59     00000000-0000-0000-0000-000000000000     DebugMessage    processing query
18624 00001011-0000-0000-0000-0000869f9d59     00000000-0000-0000-0000-000000000000     DebugMessage    processing query
18624 00002011-0000-0000-0000-0000868f9d59     00000000-0000-0000-0000-000000000000     QueryStop
32684 00001011-0000-0000-0000-0000869f9d59     00000000-0000-0000-0000-000000000000     QueryStop
32684 00000011-0000-0000-0000-000086af9d59     00000000-0000-0000-0000-000000000000     WorkStop

Ez a példa csak egy legfelső szintű kérelmet futtatott, amely tevékenységazonosítót 00000011-...kapott. Ezután minden QueryStart esemény a kérelem egy új ágát kezdte el tevékenységazonosítókkal 00001011-... és 00002011-... azok alapján. Ezek az azonosítók az eredeti kérés gyermekei, mivel mindkét kezdő esemény a szülőt 00000011-... a Kapcsolódó tevékenységazonosító mezőben naplózza.

Megjegyzés

Észrevehette, hogy az azonosítók numerikus értékei egyértelmű mintákkal rendelkeznek a szülő és a gyermek között, és nem véletlenszerűek. Bár egyszerű esetekben segíthet vizuálisan észlelni a kapcsolatot, a legjobb, ha az eszközök nem támaszkodnak erre, és átlátszatlan azonosítóként kezelik az azonosítókat. Ahogy a beágyazási szint egyre mélyebbre nő, a bájtminta megváltozik. A Kapcsolódó tevékenységazonosító mező használata a legjobb módja annak, hogy az eszközök a beágyazási szinttől függetlenül megbízhatóan működjenek.

Mivel az almunkaelemek összetett fáival kapcsolatos kérések számos különböző tevékenységazonosítót hoznak létre, ezeket az azonosítókat általában az eszközök elemzik ahelyett, hogy kézzel próbálnák rekonstruálni a fát. A PerfView egy olyan eszköz, amely képes korrelálni az ezekkel az azonosítókkal jegyzett eseményeket.