IDs de atividade EventSource
Este artigo se aplica a: ✔️ .NET Core 3.1 e versões posteriores ✔️ .NET Framework 4.5 e versões posteriores
Este guia explica as IDs de Atividade, um identificador opcional que pode ser registrado com cada evento gerado usando System.Diagnostics.Tracing.EventSource. Para obter uma introdução, consulte Introdução a EventSource.
O desafio de registrar em log trabalho simultâneo
Há muito tempo, um aplicativo típico podia ser simples e de thread único, o que tornava o registro em log simples. Você pode gravar cada etapa em um arquivo de log na ordem e ler o log exatamente na ordem em que ele foi gravado para entender o que aconteceu. Se o aplicativo manipulava solicitações, apenas uma solicitação era manipulada por vez. Todas as mensagens de log para a solicitação A seriam impressas na ordem, em seguida, todas as mensagens para B e assim por diante. Quando os aplicativos se tornam multi-threaded, essa estratégia deixa de funcionar porque várias solicitações estão sendo tratadas ao mesmo tempo. No entanto, se cada solicitação for atribuída a um thread que a processa inteiramente, você poderá resolver o problema gravando uma ID de thread para cada mensagem de log. Por exemplo, um aplicativo multi-threaded pode registrar em log:
Thread Id Message
--------- -------
12 BeginRequest A
12 Doing some work
190 BeginRequest B
12 uh-oh error happened
190 Doing some work
Ao ler as 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' está relacionada à solicitação A. No entanto, a simultaneidade do aplicativo continuou a ficar cada vez mais sofisticada. Agora, é comum usar async e await para que uma solicitação possa ser manipulada parcialmente em muitos threads diferentes antes que o trabalho seja concluído. As IDs de thread não são mais suficientes para correlacionar todas as mensagens produzidas para uma solicitação. As IDs de Atividade resolvem esse problema. Elas fornecem um identificador de granularidade mais fina que pode acompanhar solicitações individuais, ou partes de solicitações, independentemente de o trabalho estar distribuído entre threads diferentes.
Observação
O conceito de ID de Atividade usado aqui não é o mesmo que System.Diagnostics.Tracing.Activity, apesar da nomenclatura semelhante.
Acompanhando o trabalho usando uma ID de Atividade
Você pode executar o código abaixo para ver o acompanhamento da Atividade 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, esse 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
Observação
Há um problema conhecido em que o depurador do Visual Studio pode fazer com que IDs de Atividade inválidas sejam geradas. Não execute este exemplo no depurador nem 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 as IDs de Atividade, você pode ver que todas as mensagens do item de trabalho A têm a ID 00000011-... e todas as mensagens do item de trabalho B têm a ID 00000012-.... Ambos os itens de trabalho primeiro fizeram algum trabalho no thread 21256, mas então cada um deles continuou seu trabalho nos threads de threadpool separados 11348 e 14728, portanto, tentar acompanhar a solicitação apenas com IDs de thread não teria funcionado.
EventSource tem uma heurística automática em que definir um evento chamado _Something_Start seguido imediatamente por outro evento chamado _Something_Stop é considerado o início e a parada de uma unidade de trabalho. Registrar o evento de início em uma nova unidade de trabalho cria uma ID de Atividade e começa a registrar em log todos os eventos no mesmo thread com essa ID de Atividade, até que o evento de parada seja registrado. A ID também segue automaticamente o fluxo de controle assíncrono ao usar async e await. Embora seja recomendável usar os sufixos de nomenclatura Start/Stop, você pode nomear os eventos como quiser anotando-os explicitamente usando a propriedade EventAttribute.Opcode. Defina o primeiro evento como EventOpcode.Start e o segundo como EventOpcode.Stop.
Registrar solicitações que fazem trabalhos paralelos
Às vezes, apenas uma solicitação pode fazer partes diferentes de seu trabalho em paralelo e você deseja agrupar todos os eventos de log e as subpartes. O exemplo a seguir 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 de cada consulta, mas também quer entender quais consultas pertencem à mesma solicitação quando muitas solicitações simultâneas podem estar em execução. Isso é modelado como uma árvore em que cada solicitação de nível superior é uma raiz e as partes secundárias do trabalho são galhos. Cada nó na árvore recebe a 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 código a seguir:
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 uma saída 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, que recebeu a ID de Atividade 00000011-.... Em seguida, cada evento QueryStart iniciou um novo galho da solicitação com as IDs de Atividade 00002011-... e 00001011-..., respectivamente. Você pode identificar que essas IDs são filhos da solicitação original porque ambos os eventos iniciais registraram seus 00000011-... pais no campo ID da Atividade Relacionada.
Observação
Talvez você tenha notado que os valores numéricos das IDs têm alguns padrões claros entre pai e filho e não são aleatórios. Embora isso possa ajudar a detectar a relação visualmente em casos simples, é melhor que as ferramentas não confiem nisso e trate as IDs como identificadores opacos. À medida que o nível de aninhamento se aprofundar, o padrão de bytes mudará. Usar o campo ID de Atividade Relacionada é a melhor maneira de garantir que as ferramentas funcionem de modo 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. PerfView é uma ferramenta que sabe correlacionar eventos anotados com essas IDs.
