Бөлісу құралы:

Идентификаторы активности 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. Тем не менее, параллельная обработка в приложениях становится все сложнее. Теперь обычно используют async и await, чтобы один запрос мог частично обрабатываться в различных потоках до полного завершения работы. Идентификаторов потоков больше недостаточно для корреляции всех сообщений, созданных для одного запроса. Идентификаторы действий решают эту проблему. Они предоставляют более точный идентификатор зерна, который может отслеживать отдельные запросы или части запросов независимо от того, распространяется ли работа по разным потокам.

Замечание

Понятие идентификатора действия, называемое здесь, не совпадает с именем System.Diagnostics.Tracing.Activity, несмотря на аналогичное именование.

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

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

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

Замечание

Существует известная проблема, из-за которой отладчик Visual Studio может привести к созданию недопустимых идентификаторов действий. Либо не запускать этот пример под отладчиком, либо установите точку останова в начале Main и оцените выражение 'System.Threading.Tasks.TplEventSource.Log.TasksSetActivityIds = false' в окне немедленных вычислений, чтобы обойти проблему прежде чем продолжить работу.

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

EventSource имеет автоматическую эвристику, при которой определение события с именем _Something_Start, сразу следующим за событием с именем _Something_Stop, считается началом и завершением единицы работы. Ведение журнала события начала для новой единицы работы создает новый идентификатор действия и начинает регистрирование всех событий в одном потоке с этим идентификатором действия до тех пор, пока событие остановки не будет зарегистрировано. Идентификатор также автоматически следует асинхронным потокам управления при использовании async и await. Хотя мы рекомендуем использовать суффиксы именования "начало/остановка", вы можете называть события как вам угодно, явно аннотируя их с помощью свойства 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 — это одно средство, которое знает, как сопоставлять события, аннотированные с этими идентификаторами.

  • Last updated on