IDs de atividade EventSource
Este artigo aplica-se a: ✔️ .NET Core 3.1 e versões ✔️ posteriores .NET Framework 4.5 e versões posteriores
Este guia explica os IDs de atividade, um identificador opcional que pode ser registrado com cada evento gerado usando System.Diagnostics.Tracing.EventSourceo . Para obter uma introdução, consulte Introdução ao EventSource.
O desafio de registrar o trabalho simultâneo
Há muito tempo, um aplicativo típico pode ter sido simples e de thread único, o que torna o registro direto. Você pode escrever cada etapa em um arquivo de log em ordem e, em seguida, ler o log de volta exatamente na ordem em que foi escrito para entender o que aconteceu. Se o aplicativo lidou com solicitações, apenas uma solicitação foi tratada de cada vez. Todas as mensagens de log para a solicitação A seriam impressas em ordem, então todas as mensagens para B e assim por diante. Quando os aplicativos se tornam multi-threaded, essa estratégia não funciona mais porque várias solicitações estão sendo tratadas ao mesmo tempo. No entanto, se cada solicitação for atribuída a um único thread que a processa inteiramente, você poderá resolver o problema gravando um ID de thread para cada mensagem de log. Por exemplo, um aplicativo multi-threaded pode registrar:
Thread Id Message
--------- -------
12 BeginRequest A
12 Doing some work
190 BeginRequest B
12 uh-oh error happened
190 Doing some work
Ao ler os IDs de thread, você sabe que o thread 12 estava processando a solicitação A e o thread 190 estava processando a solicitação B, portanto, a mensagem 'uh-oh error happened' relacionada à solicitação A. No entanto, a simultaneidade de aplicações tem continuado a tornar-se cada vez mais sofisticada. Agora é comum usar async e await para que uma única solicitação possa ser tratada parcialmente em muitos threads diferentes antes que o trabalho seja concluído. Os IDs de thread não são mais suficientes para correlacionar todas as mensagens produzidas para uma solicitação. Os IDs de atividade resolvem esse problema. Eles fornecem um identificador de grão mais fino que pode rastrear solicitações individuais ou partes de solicitações, independentemente de o trabalho estar espalhado por diferentes threads.
Nota
O conceito de ID de atividade mencionado aqui não é o mesmo que System.Diagnostics.Tracing.Activity, apesar da nomenclatura semelhante.
Acompanhamento do trabalho usando um ID de atividade
Você pode executar o código abaixo para ver o acompanhamento de atividades em ação.
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();
}
}
}
}
Quando executado, este código imprime a saída:
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
Nota
Há um problema conhecido em que o depurador do Visual Studio pode gerar IDs de atividade inválidas. Não execute este exemplo no depurador ou defina um ponto de interrupção no início de Main e avalie a expressão 'System.Threading.Tasks.TplEventSource.Log.TasksSetActivityIds = false' na janela imediata antes de continuar a contornar o problema.
Usando os IDs de atividade, você pode ver que todas as mensagens para o item de trabalho A têm ID 00000011-... e todas as mensagens para o item de trabalho B têm ID 00000012-.... Ambos os itens de trabalho primeiro fizeram algum trabalho no thread 21256, mas depois cada um deles continuou seu trabalho em threads de threadpool separados 11348 e 14728, portanto, tentar rastrear a solicitação apenas com IDs de thread não teria funcionado.
EventSource tem uma heurística automática onde a definição de um evento chamado _Something_Start seguido imediatamente por outro evento chamado _Something_Stop é considerado o início e o fim de uma unidade de trabalho. O registro do evento start para uma nova unidade de trabalho cria uma nova ID de atividade e começa a registrar todos os eventos no mesmo thread com essa ID de atividade até que o evento stop seja registrado. O ID também segue automaticamente o fluxo de controle assíncrono ao usar async e await. Embora recomendemos que você use os sufixos de nomenclatura Iniciar/Parar, você pode nomear os eventos como quiser, anotando explicitamente eles usando a EventAttribute.Opcode propriedade. Defina o primeiro evento como EventOpcode.Start e o segundo como EventOpcode.Stop.
Solicitações de log que fazem trabalho paralelo
Às vezes, uma única solicitação pode fazer diferentes partes de seu trabalho em paralelo e você deseja agrupar todos os eventos de log e as subpartes. O exemplo abaixo simula uma solicitação que faz duas consultas de banco de dados em paralelo e, em seguida, faz algum processamento no resultado de cada consulta. Você deseja isolar o trabalho para cada consulta, mas também entender quais consultas pertencem à mesma solicitação quando muitas solicitações simultâneas podem estar em execução. Isso é modelado como uma árvore onde cada solicitação de nível superior é uma raiz e, em seguida, subporções de trabalho são ramificações. Cada nó na árvore recebe sua própria ID de Atividade, e o primeiro evento registrado com a nova ID de Atividade filho registra um campo extra chamado ID de Atividade Relacionada para descrever seu pai.
Execute o seguinte código:
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();
}
}
}
}
Este exemplo imprime saídas como:
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
Este exemplo executou apenas uma solicitação de nível superior, à qual foi atribuída a ID de 00000011-...atividade . Em seguida, cada QueryStart evento iniciou uma nova ramificação da solicitação com IDs 00001011-... de atividade e 00002011-... respectivamente. Você pode identificar esses IDs como filhos da solicitação original porque ambos os eventos de início registraram seu pai 00000011-... no campo ID de atividade relacionada.
Nota
Você deve ter notado que os valores numéricos dos IDs têm alguns padrões claros entre pai e filho e não são aleatórios. Embora possa ajudar a identificar a relação visualmente em casos simples, é melhor que as ferramentas não confiem nisso e tratem os IDs como identificadores opacos. À medida que o nível de aninhamento se aprofunda, o padrão de bytes muda. Usar o campo ID de atividade relacionada é a melhor maneira de garantir que as ferramentas funcionem de forma confiável, independentemente do nível de aninhamento.
Como as solicitações com árvores complexas de itens de subtrabalho gerarão muitas IDs de atividade diferentes, essas IDs geralmente são melhor analisadas por ferramentas em vez de tentar reconstruir a árvore manualmente. O PerfView é uma ferramenta que sabe como correlacionar eventos anotados com esses IDs.
