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 하나 정도가 불리는 것 정도로는 성능상 손실이 없으므로 그런 의미에서 본다면 이런 차이는 감안할 수 있을 것입니다.

(첨부 파일은 이 글의 예제 코드를 포함합니다.)

---

[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]

[최초 등록일: 7/6/2020 ]
[최종 수정일: 7/7/2020 ]


이 저작물은 크리에이티브 커먼즈 코리아 저작자표시-비영리-변경금지 2.0 대한민국 라이센스에 따라 이용하실 수 있습니다.

by SeongTae Jeong, mailto:techsharer@outlook.com