C# - ETW를 이용한 ThreadPool 스레드 감시
ETW를 이용해 ThreadPool을 감시하는 것은 1) Worker 스레드를 위한 ThreadPoolWorkerThreadStart, ThreadPoolWorkerThreadStop 이벤트와 2) I/O 스레드를 위한 IOThreadCreationStart, IOThreadCreationStop 이벤트를 구독하면 됩니다.
using (var session = new TraceEventSession(sessionName, null))
{
var restarted = session.EnableProvider(
ClrTraceEventParser.ProviderGuid, TraceEventLevel.Verbose,
(ulong)(ClrTraceEventParser.Keywords.Threading));
Console.CancelKeyPress += delegate (object sender, ConsoleCancelEventArgs e) { session.Dispose(); };
using (TraceLogEventSource traceLogSource = TraceLog.CreateFromTraceEventSession(session))
{
traceLogSource.Clr.ThreadPoolWorkerThreadStart += delegate (ThreadPoolWorkerThreadTraceData data)
{
if (data.ProcessID != _processId)
{
return;
}
Console.WriteLine($"[{data.TimeStamp}] {data.ThreadID} Worker Start");
};
traceLogSource.Clr.ThreadPoolWorkerThreadStop += delegate (ThreadPoolWorkerThreadTraceData data)
{
if (data.ProcessID != _processId)
{
return;
}
Console.WriteLine($"[{data.TimeStamp}] {data.ThreadID} Worker Stop");
};
traceLogSource.Clr.IOThreadCreationStart += delegate (IOThreadTraceData data)
{
if (data.ProcessID != _processId)
{
return;
}
Console.WriteLine($"[{data.TimeStamp}] {data.ThreadID} IO Start");
};
traceLogSource.Clr.IOThreadCreationStop += delegate (IOThreadTraceData data)
{
if (data.ProcessID != _processId)
{
return;
}
Console.WriteLine($"[{data.TimeStamp}] {data.ThreadID} IO Stop");
};
traceLogSource.Process();
}
// ...[생략]...}
}
테스트할 수 있는 예제로 다음과 같이 Worker 스레드와
I/O 스레드를 사용하는 코드를 넣고,
using System;
using System.Diagnostics;
using System.IO;
using System.Threading;
using System.Threading.Tasks;
namespace TestApp
{
class Program
{
static async Task Main(string[] args)
{
Debug.Assert(ThreadPool.SetMinThreads(2, 1));
Debug.Assert(ThreadPool.SetMaxThreads(4, 4)); // 4개로 제한
Thread.Sleep(5000);
Console.WriteLine(Process.GetCurrentProcess().Id);
for (int i = 0; i < 4; i++)
{
ThreadPool.QueueUserWorkItem(async (arg) =>
{
// 이 코드는 닷넷 프레임워크 환경에서 테스트한 것입니다. (참고: 닷넷 런타임에 따라 달라지는 AppDomain.GetCurrentThreadId의 반환값)
Console.WriteLine($"[{DateTime.Now}] {AppDomain.GetCurrentThreadId()} {Thread.CurrentThread.ManagedThreadId} WorkerThread: " + arg);
await ReadFileAsync();
Console.WriteLine($"[{DateTime.Now}] {AppDomain.GetCurrentThreadId()} {Thread.CurrentThread.ManagedThreadId} WorkerThread: " + arg + ": End");
}, i);
}
Console.ReadLine();
}
static async Task ReadFileAsync()
{
string filePath = typeof(Program).Assembly.Location;
FileStream fs = new FileStream(filePath, FileMode.Open, FileAccess.Read, FileShare.ReadWrite, 4096, true);
byte[] buf = new byte[1024];
await fs.ReadAsync(buf, 0, buf.Length);
fs.Dispose();
Console.WriteLine($"[{DateTime.Now}] {AppDomain.GetCurrentThreadId()} {Thread.CurrentThread.ManagedThreadId} Done");
}
}
}
실행해 보면,
[2020-07-08 오전 9:04:02] 44576 3 WorkerThread: 0
[2020-07-08 오전 9:04:02] 27876 6 WorkerThread: 3
[2020-07-08 오전 9:04:02] 24556 5 WorkerThread: 2
[2020-07-08 오전 9:04:02] 11376 4 WorkerThread: 1
[2020-07-08 오전 9:04:02] 24556 5 Done
[2020-07-08 오전 9:04:02] 11376 4 Done
[2020-07-08 오전 9:04:02] 11376 4 WorkerThread: 0: End
[2020-07-08 오전 9:04:02] 11376 4 Done
[2020-07-08 오전 9:04:02] 11376 4 WorkerThread: 2: End
[2020-07-08 오전 9:04:02] 27876 6 Done
[2020-07-08 오전 9:04:02] 27876 6 WorkerThread: 3: End
[2020-07-08 오전 9:04:02] 24556 5 WorkerThread: 1: End
위의 상황에 대한 ETW 모니터링 결과가 다소 실망스럽습니다.
[2020-07-08 오전 9:04:02] 44576 Worker Start
[2020-07-08 오전 9:04:02] 11376 Worker Start
[2020-07-08 오전 9:04:02] 24556 Worker Start
[2020-07-08 오전 9:04:02] 27876 Worker Start
[2020-07-08 오전 9:04:02] 11376 IO Start
[2020-07-08 오전 9:04:02] 24556 IO Start
[2020-07-08 오전 9:04:02] 44576 IO Start
[2020-07-08 오전 9:04:17] 55484 IO Stop
[2020-07-08 오전 9:04:17] 53212 IO Stop
[2020-07-08 오전 9:04:22] 44576 Worker Stop
[2020-07-08 오전 9:04:22] 24556 Worker Stop
[2020-07-08 오전 9:04:22] 27876 Worker Stop
[2020-07-08 오전 9:04:22] 11376 Worker Stop
보는 바와 같이 IO Start/Stop의 짝이 안 맞을뿐더러, 테스트 코드를 약간 바꿔서,
static async Task Main(string[] args)
{
Debug.Assert(ThreadPool.SetMinThreads(2, 1));
Debug.Assert(ThreadPool.SetMaxThreads(4, 4)); // 4개로 제한
Thread.Sleep(5000);
Console.WriteLine(Process.GetCurrentProcess().Id);
for (int i = 0; i < 4; i++)
{
ThreadPool.QueueUserWorkItem(async (arg) =>
{
Console.WriteLine($"[{DateTime.Now}] {AppDomain.GetCurrentThreadId()} {Thread.CurrentThread.ManagedThreadId} WorkerThread: " + arg);
ReadFile();
Console.WriteLine($"[{DateTime.Now}] {AppDomain.GetCurrentThreadId()} {Thread.CurrentThread.ManagedThreadId} WorkerThread: " + arg + ": End");
}, i);
}
Console.ReadLine();
}
static void ReadFile()
{
string filePath = typeof(Program).Assembly.Location;
FileStream fs = new FileStream(filePath, FileMode.Open, FileAccess.Read, FileShare.ReadWrite, 4096, true);
byte[] buf = new byte[1024];
fs.BeginRead(buf, 0, buf.Length, (obj) =>
{
IAsyncResult result = obj as IAsyncResult;
fs.EndRead(result);
fs.Dispose();
Console.WriteLine($"[{DateTime.Now}] {AppDomain.GetCurrentThreadId()} {Thread.CurrentThread.ManagedThreadId} Done");
}, fs);
}
실행해 보면, BeginRead의 콜백 메서드가 출력한 I/O 스레드의 thread id가,
[2020-07-08 오전 9:18:13] 9180 5 WorkerThread: 1
[2020-07-08 오전 9:18:13] 38904 6 WorkerThread: 2
[2020-07-08 오전 9:18:13] 20752 4 WorkerThread: 3
[2020-07-08 오전 9:18:13] 53232 3 WorkerThread: 0
[2020-07-08 오전 9:18:13] 38904 6 WorkerThread: 2: End
[2020-07-08 오전 9:18:13] 20752 4 WorkerThread: 3: End
[2020-07-08 오전 9:18:13] 9180 5 WorkerThread: 1: End
[2020-07-08 오전 9:18:13] 53232 3 WorkerThread: 0: End
[2020-07-08 오전 9:18:13] 20752 4 Done
[2020-07-08 오전 9:18:13] 20752 4 Done
[2020-07-08 오전 9:18:13] 53232 3 Done
[2020-07-08 오전 9:18:13] 9180 5 Done
ETW 모니터링의 IO Stop 이벤트에서는 연결이 안 됩니다.
[2020-07-08 오전 9:18:13] 53232 Worker Start
[2020-07-08 오전 9:18:13] 9180 Worker Start
[2020-07-08 오전 9:18:13] 38904 Worker Start
[2020-07-08 오전 9:18:13] 20752 Worker Start
[2020-07-08 오전 9:18:13] 9180 IO Start
[2020-07-08 오전 9:18:13] 20752 IO Start
[2020-07-08 오전 9:18:13] 38904 IO Start
[2020-07-08 오전 9:18:13] 53232 IO Start
[2020-07-08 오전 9:18:28] 3664 IO Stop
[2020-07-08 오전 9:18:28] 13716 IO Stop
[2020-07-08 오전 9:18:28] 3980 IO Stop
[2020-07-08 오전 9:18:33] 38904 Worker Stop
[2020-07-08 오전 9:18:33] 9180 Worker Stop
[2020-07-08 오전 9:18:33] 53232 Worker Stop
[2020-07-08 오전 9:18:33] 20752 Worker Stop
위의 결과만으로는, IO Start와 IO Stop의 정보를 연결할 단서가 없어 모니터링으로써의 효과가 거의 없습니다. 그래도 일단 이번에는 여기까지라도 알아두고. ^^
(
첨부 파일은 이 글의 예제 코드를 포함합니다.)
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]