Идентификаторы действий EventSource

Эта статья относится к : ✔️ .NET Core 3.1 и более поздних✔️ версий платформа .NET Framework версии 4.5 и более поздних версий.

В этом руководстве описываются идентификаторы действий, необязательный идентификатор, который можно регистрировать с каждым событием, созданным с помощью System.Diagnostics.Tracing.EventSource. Общие сведения см. в статье "Начало работы с EventSource".

Проблема параллельного ведения журнала

Давно обычное приложение, возможно, было простым и однопоточным, что делает ведение журнала простым. Вы можете записать каждый шаг в файл журнала по порядку, а затем прочитать журнал обратно в том порядке, в который он был записан, чтобы понять, что произошло. Если приложение обрабатывает запросы, то одновременно обрабатывается только один запрос. Все сообщения журнала для запроса A будут напечатаны по порядку, а затем все сообщения для B и т. д. Когда приложения становятся многопоточных, эта стратегия больше не работает, так как одновременно обрабатываются несколько запросов. Однако если каждый запрос назначается одному потоку, который обрабатывает его полностью, можно решить проблему, записав идентификатор потока для каждого сообщения журнала. Например, многопоточное приложение может регистрировано:

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

Считывая идентификаторы потоков, вы знаете, что поток 12 обрабатывал запрос A и поток 190 обрабатывал запрос B, поэтому сообщение об ошибке uh-oh произошло, связанное с запросом A. Однако параллелизм приложений продолжает расти все более сложно. Теперь часто asyncawait используется один запрос, и поэтому один запрос может обрабатываться частично во многих разных потоках до завершения работы. Идентификаторы потоков больше не достаточно для сопоставления всех сообщений, созданных для одного запроса. Идентификаторы действий решают эту проблему. Они предоставляют более точный идентификатор зерна, который может отслеживать отдельные запросы или части запросов независимо от того, распространяется ли работа по разным потокам.

Отслеживание работы с помощью идентификатора действия

Чтобы увидеть отслеживание действий в действии, можно запустить приведенный ниже код.

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

При запуске этот код выводит выходные данные:

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

Используя идентификаторы действий, вы увидите, что все сообщения для рабочего элемента A имеют идентификатор и все сообщения для рабочего элемента B имеют идентификатор 00000011-...00000012-.... Оба рабочих элемента сначала работали над потоком 21256, но затем каждый из них продолжал свою работу над отдельными потоками threadpool 11348 и 14728, поэтому попытка отслеживать запрос только с идентификаторами потоков не работала.

EventSource имеет автоматическую эвристика, где определение события с именем _Something_Start сразу после другого события с именем _Something_Stop считается началом и остановкой единицы работы. Ведение журнала события начала для новой единицы работы создает новый идентификатор действия и начинает регистрирование всех событий в одном потоке с этим идентификатором действия до тех пор, пока событие остановки не будет зарегистрировано. Идентификатор также автоматически следует асинхронным потокам управления при использовании async и await. Хотя рекомендуется использовать суффиксы именования start/Stop, вы можете назвать события, которые вам нравится, явно заметив их с помощью EventAttribute.Opcode свойства. Задайте для первого события EventOpcode.Start значение и второе значение EventOpcode.Stop.

Запросы журналов, выполняющие параллельную работу

Иногда один запрос может выполнять различные части своей работы параллельно, и вы хотите сгруппировать все события журнала и вложенные части. В приведенном ниже примере имитируется запрос, который выполняет два запроса базы данных параллельно, а затем выполняет некоторую обработку результатов каждого запроса. Вы хотите изолировать работу для каждого запроса, но также понять, какие запросы относятся к одному и тому же запросу, когда может выполняться множество одновременных запросов. Это моделировается как дерево, где каждый запрос верхнего уровня является корнем, а затем подпорты работы являются ветвями. Каждый узел в дереве получает собственный идентификатор действия, а первое событие, зарегистрированное с помощью нового дочернего идентификатора действия, записывает дополнительное поле с именем "Связанный идентификатор действия" для описания родительского элемента.

Выполните следующий код:

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

В этом примере выходные данные, такие как:

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

В этом примере выполняется только один запрос верхнего уровня, который был назначен идентификатором 00000011-...действия. Затем каждое QueryStart событие начало новую ветвь запроса с идентификаторами 00001011-... действий и 00002011-... соответственно. Эти идентификаторы являются дочерними элементами исходного запроса, так как оба события запуска регистрировали их родительский объект 00000011-... в поле "Идентификатор связанного действия".

Так как запросы со сложными деревьями вложенных элементов создают множество различных идентификаторов действий, эти идентификаторы обычно лучше всего анализировать средствами, а не пытаться восстановить дерево вручную. PerfView — это одно средство, которое знает, как сопоставлять события, аннотированные с этими идентификаторами.