Nota
O acceso a esta páxina require autorización. Pode tentar iniciar sesión ou modificar os directorios.
O acceso a esta páxina require autorización. Pode tentar modificar os directorios.
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 identificadores de actividad, un identificador opcional que se puede registrar con cada evento generado mediante System.Diagnostics.Tracing.EventSource. Para obtener una introducción, consulte Introducción a EventSource.
El desafío de registrar el trabajo simultáneo
Hace mucho tiempo, una aplicación típica puede haber sido simple y de un solo subproceso, lo que hace que el registro sea sencillo. Puede escribir cada paso en un archivo de registro en orden y, a continuación, volver a leer el registro exactamente en el orden en que se escribió para comprender lo que sucedió. Si la aplicación controla las solicitudes, solo se controló una solicitud a la vez. Todos los mensajes de registro de la solicitud A se imprimirían en orden, luego todos los mensajes de B, etc. Cuando las aplicaciones se vuelven multiproceso, esa estrategia ya no funciona porque se administran varias solicitudes al mismo tiempo. Sin embargo, si cada solicitud se asigna a un único subproceso que lo procesa por completo, puede resolver el problema mediante la grabación de un identificador 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 identificadores de subproceso sabe que el subproceso 12 estaba procesando la solicitud A y el subproceso 190 estaba procesando la solicitud B, por lo que el mensaje "uh-oh error se produjo" relacionado con la solicitud A. Sin embargo, la simultaneidad de aplicaciones ha continuado creciendo cada vez más sofisticada. Ahora es habitual usar async y await para que una única solicitud se pueda controlar parcialmente en muchos subprocesos diferentes antes de que se complete el trabajo. Los identificadores de subprocesos ya no son suficientes para correlacionar todos los mensajes generados para una solicitud. Los identificadores de actividad resuelven este problema. Proporcionan un identificador de grano más fino que puede realizar un seguimiento de las solicitudes individuales, o partes de las solicitudes, sin importar si el trabajo está distribuido entre distintos 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 la nomenclatura similar.
Seguimiento del trabajo mediante un identificador 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:
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 por el que el depurador de Visual Studio puede provocar que se generen identificadores 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 identificadores de actividad puede ver que todos los mensajes del elemento de trabajo A tienen identificador 00000011-... y todos los mensajes del elemento de trabajo B tienen el identificador 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 donde 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 nueva unidad de trabajo crea un nuevo identificador de actividad y comienza a registrar todos los eventos en el mismo subproceso con ese identificador de actividad hasta que se registre el evento stop. El identificador también sigue automáticamente el flujo de control asincrónico al usar async y await. Aunque recomendamos que use los sufijos de nomenclatura Start/Stop, puede asignar cualquier nombre a los eventos 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 desea 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, a continuación, 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();
}
}
}
}
Este ejemplo imprime un resultado 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
En este ejemplo solo se ejecutó una solicitud de nivel superior, a la que se asignó el identificador 00000011-...de actividad . A continuación, cada QueryStart evento 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 identificadores tienen algunos patrones claros entre los elementos padre e hijo y no son aleatorios. Aunque puede ayudar a detectar la relación visualmente en casos simples, es mejor que las herramientas no se basen en esto y traten los identificadores 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 confiablemente independientemente del nivel de anidamiento.
Dado que las solicitudes con árboles complejos de elementos de subtrabajo generarán muchos identificadores de actividad diferentes, estos identificadores suelen ser mejor analizados mediante software en lugar de intentar reconstruir manualmente el árbol. PerfView es una herramienta que sabe cómo correlacionar eventos anotados con estos identificadores.
Colaborar con nós en GitHub
A orixe deste contido pódese atopar en GitHub, onde tamén podes crear e revisar problemas e extraer solicitudes. Para obter máis información, consulta a guía para colaboradores.
