Aracılığıyla paylaş

EventSource Etkinlik Kimlikleri

Bu makale şunlar için geçerlidir: ✔️ .NET Core 3.1 ve sonraki sürümleri .✔️ NET Framework 4.5 ve sonraki sürümleri

Bu kılavuzda, System.Diagnostics.Tracing.EventSource kullanılarak oluşturulan her olayla birlikte günlüğe kaydedilebilen opsiyonel bir tanımlayıcı olan Etkinlik Kimlikleri açıklanmaktadır. Giriş için bkz. EventSource'u Kullanmaya Başlama.

Eşzamanlı çalışmayı günlüğe kaydetme zorluğu

Uzun zaman önce, tipik bir uygulama basit ve tek iş parçacıklı olurdu, bu da günlük kaydını kolaylaştırırdı. Her adımı sırayla bir günlük dosyasına yazabilir ve ardından günlüğü tam olarak yazıldığı sırayla okuyarak ne olduğunu anlayabilirsiniz. Uygulama istekleri işlediyse aynı anda yalnızca bir istek işlenir. A isteği için tüm günlük iletileri sırayla yazdırılır, ardından B için tüm iletiler vb. Uygulamalar çok iş parçacıklı hale geldiğinde, birden çok istek aynı anda işlendiğinden bu strateji artık çalışmaz. Ancak, her istek tamamen işleyen tek bir iş parçacığına atanırsa, her günlük iletisi için bir iş parçacığı kimliği kaydederek sorunu çözebilirsiniz. Örneğin, çoklu iş parçacığı kullanan bir uygulama şunları günlüğe kaydedebilir:

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

İş parçacığı kimliklerini okuyarak, iş parçacığı 12'nin A isteğini işlediğini ve iş parçacığı 190'ın B isteğini işlediğini ve bu nedenle A isteğiyle ilgili 'uh-oh hatası oluştu' iletisinin olduğunu biliyorsunuz. Ancak uygulama eşzamanlılığı giderek daha karmaşık hale geldi. Artık yaygın olarak kullanılır async ve await böylece iş tamamlanmadan önce tek bir istek birçok farklı iş parçacığında kısmen işlenebilir. Thread ID'leri artık tek bir istek için oluşturulan tüm iletileri ilişkilendirmek için yeterli değildir. Etkinlik kimlikleri bu sorunu çözer. Tek tek istekleri veya isteklerin bölümlerini, çalışmanın farklı iş parçacıklarına yayılıp yayılmadığını fark etmeksizin izleyebilen daha ince taneli bir tanımlayıcı sağlar.

Uyarı

Burada başvuruda bulunılan Etkinlik Kimliği kavramı, benzer adlandırmaya rağmen System.Diagnostics.Tracing.Activity ile aynı değildir.

Etkinlik Kimliği kullanarak çalışmayı izleme

Etkinlik izlemenin nasıl çalıştığını görmek için aşağıdaki kodu çalıştırabilirsiniz.

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();
            }
        }
    }
}

Bu kod çalıştırıldığında çıktıyı yazdırır:

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

Uyarı

Visual Studio hata ayıklayıcının geçersiz Etkinlik Kimliklerinin oluşturulmasına neden olabileceği bilinen bir sorun vardır. Bu örneği hata ayıklayıcının altında çalıştırmayın veya Main'ın başında bir kesme noktası ayarlamayın ve sorunu geçici olarak çözmeden önce anlık pencerede 'System.Threading.Tasks.TplEventSource.Log.TasksSetActivityIds = false' ifadesini değerlendirin.

Etkinlik Kimliklerini kullanarak, A iş öğesi için tüm iletilerin kimliği 00000011-... ve B iş öğesi için tüm iletilerin kimliği 00000012-...olduğunu görebilirsiniz. Her iki iş öğesi de önce iş parçacığı 21256 üzerinde bazı çalışmalar yaptı, ancak daha sonra her biri çalışmalarına iş parçacığı havuzunda yer alan ayrı iş parçacıkları 11348 ve 14728 üzerinde devam etti; bu nedenle, isteği sadece iş parçacığı kimlikleriyle izlemeye çalışmak işe yaramazdı.

EventSource, _Something_Start adlı bir olayı tanımlamanın ve hemen ardından _Something_Stop adlı başka bir olayın bir iş biriminin başlangıç ve bitişi olarak değerlendirildiği otomatik bir yöntem içerir. Yeni bir iş birimi için başlangıç olayını günlüğe kaydetmek yeni bir Etkinlik Kimliği oluşturur ve durdurma olayı günlüğe kaydedilene kadar bu Etkinlik Kimliği ile aynı iş parçacığındaki tüm olayları günlüğe kaydetmeye başlar. Kimlik ayrıca async ve await kullanıldığında otomatik olarak asenkron kontrol akışını izler. Başlat/Durdur adlandırma soneklerini kullanmanızı önersek de, özelliğini kullanarak EventAttribute.Opcode açıkça açıklama ekleyerek olayları istediğiniz şekilde adlandırabilirsiniz. İlk olayı olarak EventOpcode.Start , ikincisini olarak EventOpcode.Stopayarlayın.

Paralel çalışma yapacak günlük istekleri

Bazen tek bir istek, işinin farklı parçalarını paralel olarak gerçekleştirebilir ve tüm günlük kayıt olaylarını ve alt bölümleri gruplandırmak isteyebilirsiniz. Aşağıdaki örnek, iki veritabanı sorgusunu paralel olarak çalıştıran ve ardından her sorgunun sonucu üzerinde işlem gerçekleştirmeye yönelik bir isteğin benzetimini yapar. Her sorgunun çalışmasını yalıtmak, ancak aynı zamanda birçok eşzamanlı istek çalıştırılabilirken hangi sorguların aynı isteğe ait olduğunu anlamak istiyorsunuz. Bu, her üst düzey isteğin bir kök olduğu ve sonra işin alt dallarının dal olduğu bir ağaç olarak modellenir. Ağaçtaki her düğüm kendi Etkinlik Kimliğini alır ve yeni alt Etkinlik Kimliği ile günlüğe kaydedilen ilk olay, üst öğesini tanımlamak için İlgili Etkinlik Kimliği adlı ek bir alanı günlüğe kaydeder.

Aşağıdaki kodu çalıştırın:

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();
            }
        }
    }
}

Bu örnek aşağıdaki gibi bir çıktı yazdırır:

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

Bu örnekte yalnızca bir üst düzey istek çalıştırıldı ve bu istek Etkinlik Kimliği 00000011-...olarak atandı. Ardından her QueryStart olay, etkinlik kimlikleri 00001011-... ve 00002011-... sırasıyla isteğin yeni bir dalını başlattı. Bu kimliklerin özgün isteğin alt öğeleri olduğunu belirleyebilirsiniz çünkü başlangıç olaylarının her ikisi de üst 00000011-... öğelerini İlgili Etkinlik Kimliği alanına kaydetmiş olur.

Uyarı

Kimlik numaralarının sayısal değerlerinde ebeveyn ve çocuk öğeler arasında bazı net kalıplar olduğunu ve rastgele olmadığını fark etmiş olabilirsiniz. Basit durumlarda ilişkiyi görsel olarak saptamaya yardımcı olsa da, araçların buna güvenmemesi ve kimlikleri opak tanımlayıcılar olarak ele almaması en iyisidir. İç içe yerleştirme düzeyi daha derine indikçe bayt deseni değişir. İç içe yerleştirme düzeyinden bağımsız olarak araçların güvenilir bir şekilde çalışmasını sağlamanın en iyi yolu İlgili Etkinlik Kimliği alanını kullanmaktır.

Alt çalışma öğelerinin karmaşık ağaçlarını içeren istekler birçok farklı Etkinlik Kimlikleri oluşturacağından, bu kimlikler genellikle ağacı el ile yeniden oluşturmaya çalışmak yerine araçlar tarafından ayrıştırılır. PerfView, bu kimliklerle etiketlenen olayları birbirleriyle ilişkilendirmeyi bilen bir araçtır.

  • Last updated on