Identificadores de actividad EventSource
Este artículo se aplica a: ✔️ .NET Core 3.1 y versiones posteriores ✔️ .NET Framework 4.5 y versiones posteriores
En esta guía se explican los Id. de actividad, un identificador opcional que se puede registrar con cada evento generado mediante System.Diagnostics.Tracing.EventSource. Para obtener una introducción, vea Introducción a EventSource.
El desafío de registrar el trabajo simultáneo
Hace mucho tiempo, una aplicación típica podía ser sencilla y de un solo subproceso, lo que hacía que el registro fuera fácil. Podía escribir cada paso en un archivo de registro en orden y, después, volver a leer el registro exactamente en el orden en que se escribió para comprender lo que ocurrió. Si la aplicación controlaba las solicitudes, solo se controlaba una solicitud a la vez. Todos los mensajes de registro de la solicitud A se imprimirían en orden; luego, todos los mensajes de la B, etc. Ahora que las aplicaciones son multiproceso, esa estrategia ya no funciona porque se administran varias solicitudes al mismo tiempo. Pero si cada solicitud se asigna a un único subproceso que lo procesa por completo, puede resolver el problema registrando un id. de subproceso para cada mensaje de registro. Por ejemplo, una aplicación multiproceso podría registrar lo siguiente:
Thread Id Message
--------- -------
12 BeginRequest A
12 Doing some work
190 BeginRequest B
12 uh-oh error happened
190 Doing some work
Al leer los id. de subproceso sabe que el subproceso 12 estaba procesando la solicitud A y el subproceso 190 estaba procesando la solicitud B, por lo que ha generado el mensaje "uh-oh error happened" relacionado con la solicitud A. Pero la simultaneidad de aplicaciones ha continuado creciendo cada vez de forma más sofisticada. Ahora es habitual usar async y await de modo que una única solicitud se pueda controlar parcialmente en muchos subprocesos diferentes antes de que se complete el trabajo. Los id. de subprocesos ya no son suficientes para correlacionar todos los mensajes generados para una solicitud. Los Id. de actividad resuelven este problema. Proporcionan un identificador más preciso que puede realizar un seguimiento de las solicitudes individuales o partes de las solicitudes, independientemente de si el trabajo se distribuye entre diferentes subprocesos.
Nota
El concepto de id. de actividad al que se hace referencia aquí no es el mismo que System.Diagnostics.Tracing.Activity, a pesar de contar con una nomenclatura similar.
Seguimiento del trabajo mediante un Id. de actividad
Puede ejecutar el código siguiente para ver el seguimiento de actividad en acción.
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();
}
}
}
}
Cuando se ejecuta, este código imprime la salida siguiente:
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
Hay un problema conocido que hace que el depurador de Visual Studio pueda provocar que se generen Id. de actividad no válidos. No ejecute este ejemplo en el depurador ni establezca un punto de interrupción al principio de Main, y evalúe la expresión "System.Threading.Tasks.TplEventSource.Log.TasksSetActivityIds = false" en la ventana inmediata antes de continuar resolviendo el problema.
Con los Id. de actividad puede ver que todos los mensajes del elemento de trabajo A tienen id. 00000011-... y todos los mensajes del elemento de trabajo B tienen id. 00000012-.... Ambos elementos de trabajo funcionaron primero en el subproceso 21256, pero cada uno de ellos continuó su trabajo en subprocesos de los grupos de subprocesos independientes 11348 y 14728, por lo que intentar realizar un seguimiento de la solicitud solo con id. de subprocesos no habría funcionado.
EventSource tiene una heurística automática en la que definir un evento denominado _Something_Start, seguido inmediatamente de otro evento denominado _Something_Stop, se considera el inicio y la detención de una unidad de trabajo. El registro del evento de inicio de una unidad de trabajo nueva crea un Id. de actividad y comienza a registrar todos los eventos en el mismo subproceso con ese Id. de actividad hasta que se registre el evento de detención. El id. también sigue automáticamente el flujo de control asincrónico al usar async y await. Aunque se recomienda usar los sufijos de nomenclatura Inició/Detención, puede asignar un nombre a los eventos que quiera anotándolos explícitamente mediante la propiedad EventAttribute.Opcode. Establezca el primer evento en EventOpcode.Start y el segundo en EventOpcode.Stop.
Solicitudes de registro que realizan trabajos en paralelo
A veces, una sola solicitud podría realizar diferentes partes de su trabajo en paralelo y quiere agrupar todos los eventos de registro y las subpartes. En el ejemplo siguiente se simula una solicitud que realiza dos consultas de base de datos en paralelo y, después, realiza algún procesamiento en el resultado de cada consulta. Quiere aislar el trabajo de cada consulta, pero también comprender qué consultas pertenecen a la misma solicitud cuando se podrían ejecutar muchas solicitudes simultáneas. Esto se modela como un árbol en el que cada solicitud de nivel superior es una raíz y, después, las subpartes de trabajo son ramas. Cada nodo del árbol obtiene su propio Id. de actividad y el primer evento registrado con el nuevo Id. de actividad secundario registra un campo adicional denominado Id. de actividad relacionada para describir su elemento primario.
Ejecute el código siguiente:
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();
}
}
}
}
En este ejemplo se imprime la salida, como la siguiente:
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
En este ejemplo solo se ejecutó una solicitud de nivel superior, a la que se asignó el Id. de actividad 00000011-.... Después, cada evento QueryStart inició una nueva rama de la solicitud con Id. de actividad 00001011-... y 00002011-... respectivamente. Puede identificar estos id. como elementos secundarios de la solicitud original porque ambos eventos de inicio registraron su clase 00000011-... primaria en el campo Id. de actividad relacionada.
Nota
Es posible que haya observado que los valores numéricos de los id. tienen algunos patrones claros entre los elementos primarios y secundarios, y que no son aleatorios. Aunque puede ayudar a detectar la relación visualmente en casos sencillos, es mejor que las herramientas no se basen en esto y traten los id. como identificadores opacos. A medida que el nivel de anidamiento aumenta, el patrón de bytes cambiará. El uso del campo Id. de actividad relacionada es la mejor manera de garantizar que las herramientas funcionen de forma fiable, independientemente del nivel de anidamiento.
Dado que las solicitudes con árboles complejos de elementos de subtrabajo generarán muchos Id. de actividad diferentes, estos id. suelen analizarse mejor mediante herramientas en lugar de intentar reconstruir el árbol a mano. PerfView es una herramienta que sabe cómo correlacionar eventos anotados con estos id.
