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