ETW(Event Tracing for Windows)를 이용한 Finalizer 실행 감시
ETW를 이용해 예외를 먹은 것도 찾아냈는데,
ETW(Event Tracing for Windows)를 이용한 닷넷 프로그램의 내부 이벤트 활용
; https://www.sysnet.pe.kr/2/0/12244
이번엔 Finalizer를,
windbg로 확인하는 Finalizer를 가진 객체의 GC 과정
; https://www.sysnet.pe.kr/2/0/11510
감시해 보겠습니다. 이를 위해 필요한 것은 GCFinalizeObject 이벤트를 구독하면 되는데, 그 이벤트를 발생하려면 ClrTraceEventParser.Keywords.GC 항목을 활성화시키면 됩니다.
class Program
{
    static void Main(string[] args)
    {
        Thread t = new Thread(threadFunc);
        t.IsBackground = true;
        t.Start();
        ClrEventSourceMonitor.Run();
    }
}
class ClrEventSourceMonitor
{
    public static int Run()
    {
        // ...[생략]...
        var restarted = session.EnableProvider(
	        ClrTraceEventParser.ProviderGuid, TraceEventLevel.Verbose,
	        (ulong)(ClrTraceEventParser.Keywords.GC));
        using (TraceLogEventSource traceLogSource = TraceLog.CreateFromTraceEventSession(session))
        {
            // 이벤트 발생: ClrTraceEventParser.Keywords.GC
            traceLogSource.Clr.GCFinalizeObject += delegate (FinalizeObjectTraceData data)
            {
                if (_processId == 0 || data.ProcessID != _processId)
                {
                    return;
                }
                Out.WriteLine($"{data.TimeStamp}, {data.TypeID}");
            };
            traceLogSource.Process();
        }
        // ...[생략]...
    }
}
그리고, 
원 글에서는 Finalizer를 소유한 TypeName을 알아내려면 ClrTraceEventParser.Keywords.Type을 구독하고 TypeBulkType 이벤트에서 미리 보관해 두라고 합니다.
public static int Run()
{
    // ...[생략]...
    var restarted = session.EnableProvider(
	    ClrTraceEventParser.ProviderGuid, TraceEventLevel.Verbose,
	    (ulong)(ClrTraceEventParser.Keywords.GC
				| ClrTraceEventParser.Keywords.Type)));
    using (TraceLogEventSource traceLogSource = TraceLog.CreateFromTraceEventSession(session))
    {
        traceLogSource.Clr.TypeBulkType += delegate (GCBulkTypeTraceData data)
        {
            if (data.ProcessID != processId)
            {
                return;
            }
            for (int currentType = 0; currentType < data.Count; currentType++)
            {
                GCBulkTypeValues value = data.Values(currentType);
                _types[value.TypeID] = value.TypeName;
            }
        };}
		// ...[생략]...
        traceLogSource.Process();
    }
    // ...[생략]...
}
그런데, 위의 작업을 굳이 하지 않아도 "ClrTraceEventParser.Keywords.GCHeapAndTypeNames" 옵션을 주는 것만으로 구할 수 있습니다. 그래서 다음과 같이만 구성하면 됩니다.
public static int Run()
{
    // ...[생략]...
    var restarted = session.EnableProvider(
	    ClrTraceEventParser.ProviderGuid, TraceEventLevel.Verbose,
	    (ulong)(ClrTraceEventParser.Keywords.GC
            | ClrTraceEventParser.Keywords.GCHeapAndTypeNames));
    using (TraceLogEventSource traceLogSource = TraceLog.CreateFromTraceEventSession(session))
    {
        traceLogSource.Clr.GCFinalizeObject += delegate (FinalizeObjectTraceData data)
        {
            if (_processId == 0 || data.ProcessID != _processId)
            {
                return;
            }
            Out.WriteLine($"{data.TimeStamp}, {data.TypeID}");
        };
        traceLogSource.Process();
    }
    // ...[생략]...
}
일단 이렇게 구성하고 예제 프로젝트를 하나 돌리면,
using System;
using System.Diagnostics;
namespace TestApp
{
    class Program
    {
        static void Main(string[] args)
        {
            Console.WriteLine(Process.GetCurrentProcess().Id);
            for (int i = 0; i < 5; i++)
            {
                TestFinalizer t = new TestFinalizer();
                t.ToString();
            }
            GC.Collect();
        }
    }
    class TestFinalizer
    {
        ~TestFinalizer()
        {
            Console.WriteLine("~TestFinalizer Called!");
        }
    }
}
이런 출력 결과를 얻게 됩니다.
2020-06-26 오후 12:01:25, 7298040, 
2020-06-26 오후 12:01:25, 7298040, TestApp.TestFinalizer
2020-06-26 오후 12:01:25, 7298040, TestApp.TestFinalizer
2020-06-26 오후 12:01:25, 7298040, TestApp.TestFinalizer
2020-06-26 오후 12:01:25, 1725203260, 
2020-06-26 오후 12:01:25, 7298040, TestApp.TestFinalizer
2020-06-26 오후 12:01:25, 1813589520, 
2020-06-26 오후 12:01:25, 1813595776, 
2020-06-26 오후 12:01:25, 1813583760, 
위의 내용에서 재미있는 것은, 어떤 식으로든 GCFinalizeObject가 한 번은 발생해야 그 이후 이벤트에서 TypeName을 알 수 있다는 점입니다. 현실적인 기준에서 봤을 때, Finalizer 하나 정도가 불리는 것 정도로는 성능상 손실이 없으므로 그런 의미에서 본다면 이런 차이는 감안할 수 있을 것입니다.
(
첨부 파일은 이 글의 예제 코드를 포함합니다.)
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]