EventSource 작업 ID
이 문서의 적용 대상: ✔️ .NET Core 3.1 이상 버전 ✔️ .NET Framework 4.5 이상 버전
이 가이드에서는 작업 ID에 대해 설명합니다. 이 ID는 System.Diagnostics.Tracing.EventSource를 사용하여 생성된 각 이벤트와 함께 기록할 수 있는 선택적 식별자입니다. 소개 관련 내용은 EventSource 시작을 참조하세요.
동시 작업 로깅의 문제
오래 전에는 일반적인 애플리케이션이 단순한 단일 스레드였을 수 있으므로 로깅이 간단했습니다. 각 단계를 로그 파일에 순서대로 쓴 다음, 로그가 기록된 순서대로 정확하게 다시 읽어 무슨 일이 일어났는지 파악할 수 있었습니다. 앱이 요청을 처리한 경우 한 번에 하나의 요청만 처리되었습니다. 요청 A에 대한 모든 로그 메시지가 순서대로 인쇄된 다음, B에 대한 모든 메시지가 인쇄되는 식으로 인쇄됩니다. 앱이 다중 스레드가 되면 여러 요청이 동시에 처리되기 때문에 이러한 전략이 더 이상 유효하지 않습니다. 그러나 각각의 요청을 완전히 처리하는 단일 스레드에 할당된 경우 각 로그 메시지에 대한 스레드 ID를 기록하여 이러한 문제를 해결할 수 있습니다. 예를 들어 다중 스레드 앱은 다음을 로그할 수 있습니다.
Thread Id Message
--------- -------
12 BeginRequest A
12 Doing some work
190 BeginRequest B
12 uh-oh error happened
190 Doing some work
스레드 ID를 읽으면 스레드 12가 요청 A를 처리하고 스레드 190이 요청 B를 처리하고 있다는 것을 알 수 있으므로 요청 A와 관련된 'uh-oh error happened' 메시지가 표시됩니다. 그러나 애플리케이션 동시성은 점점 더 정교해지고 있습니다. 이제는 async 및 await를 흔하게 사용하므로 작업이 완료되기 전에 여러 스레드에서 단일 요청을 부분적으로 처리할 수 있습니다. 스레드 ID는 더 이상 하나의 요청에 대해 생성된 모든 메시지를 서로 연결하기에 충분하지 않습니다. 작업 ID는 이 문제를 해결합니다. 작업이 서로 다른 스레드에 분산되는지 여부에 관계없이 개별 요청 또는 요청 부분을 추적할 수 있는 더 세밀한 식별자를 제공합니다.
참고 항목
여기에 언급된 작업 ID 개념은 이름이 비슷함에도 불구하고 System.Diagnostics.Tracing.Activity와 동일하지는 않습니다.
작업 ID를 사용하여 작업 추적
아래 코드를 실행하여 작업 추적이 어떻게 작동하는지 확인할 수 있습니다.
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 디버거로 인해 잘못된 작업 ID가 생성될 수 있는 알려진 문제가 있습니다. 디버거에서 이 샘플을 실행하지 않거나 Main의 시작 부분에 중단점을 설정하고 즉시 창에서 'System.Threading.Tasks.TplEventSource.Log.TasksSetActivityIds = false' 식을 평가한 후 문제를 계속 해결합니다.
작업 ID를 사용하면 작업 항목 A에 대한 모든 메시지에 ID 00000011-...이 있고 작업 항목 B의 모든 메시지에 ID 00000012-...가 있는 것을 볼 수 있습니다. 두 작업 항목 모두 먼저 스레드 21256에서 일부 작업을 수행했지만 각 항목은 별도의 스레드 풀 스레드 11348 및 14728에서 작업을 계속했으므로 스레드 ID로만 요청을 추적하려고 하면 작동하지 않습니다.
EventSource에는 작업 단위의 시작 및 중지로 간주되는 _Something_Stop이라는 다른 이벤트가 바로 뒤에 오는 _Something_Start 이벤트를 정의하는 자동 추론이 있습니다. 새 작업 단위에 대한 시작 이벤트를 로그하면 새 작업 ID가 생성되고 중지 이벤트가 기록될 때까지 해당 작업 ID를 사용하여 동일한 스레드의 모든 이벤트 로깅을 시작합니다. 또한 ID는 async 및 await 사용 시 비동기 제어 흐름을 자동으로 따릅니다. 시작/중지 이름 지정 접미사를 사용하는 것이 좋으나 EventAttribute.Opcode 속성을 사용해 명시적으로 주석을 추가하여 원하는 이벤트의 이름을 지정할 수 있습니다. 첫 번째 이벤트를 EventOpcode.Start로 설정하고 두 번째 이벤트를 EventOpcode.Stop으로 설정합니다.
병렬 작업을 수행하는 요청 로그
경우에 따라 단일 요청이 작업의 다른 부분을 병렬로 수행할 수 있으며, 이 경우 모든 로그 이벤트 및 하위 파트를 그룹화하려고 합니다. 아래 예제에서는 두 개의 데이터베이스 쿼리를 병렬로 수행하는 요청을 시뮬레이션한 다음 각 쿼리의 결과에 대해 일부 처리를 수행합니다. 각 쿼리에 대한 작업을 격리할 뿐만 아니라 많은 동시 요청이 실행될 수 있을 때 동일한 요청에 속하는 쿼리도 파악하려고 합니다. 각 최상위 요청이 루트이고 작업의 하위 보고서가 분기인 트리로 모델링됩니다. 트리의 각 노드는 자체 작업 ID를 가져오고 새 자식 작업 ID로 기록된 첫 번째 이벤트는 관련 작업 ID라는 추가 필드를 기록하여 부모를 설명합니다.
다음 코드를 실행하세요.
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
이 예제에서는 작업 ID 00000011-...이 할당된 최상위 요청 하나만 실행했습니다. 그런 다음 각 QueryStart 이벤트는 각각 작업 ID 00001011-... 및 00002011-...을 사용하여 요청의 새 분기를 시작했습니다. 시작 이벤트 둘 다 관련 작업 ID 필드에 부모 00000011-...을 로그했으므로 이러한 ID가 원래 요청의 자식인 것을 식별할 수 있습니다.
참고 항목
ID의 숫자 값에 부모와 자식 사이에 명확한 패턴이 있고 임의로 표시되지 않는 것을 확인할 수 있습니다. 간단한 경우에 관계를 시각적으로 확인하는 데 도움이 될 수 있지만 도구에서 이를 사용하지 않고 ID를 불투명 식별자로 취급하는 것이 가장 좋습니다. 중첩 수준이 더 깊어지면 바이트 패턴이 변경됩니다. 관련 작업 ID 필드를 사용하는 것이 중첩 수준에 관계없이 도구가 안정적으로 작동하도록 하는 가장 좋은 방법입니다.
하위 작업 항목의 복잡한 트리가 있는 요청은 다양한 작업 ID를 생성하므로 이러한 ID는 일반적으로 직접 트리를 재구성하는 것보다 도구로 구문 분석하는 것이 가장 좋습니다. PerfView는 주석이 지정된 이벤트를 이러한 ID와 상호 연결하는 방법을 알고 있는 도구 중 하나입니다.
.NET