C# - ETW를 이용한 Monitor Enter/Exit 감시

예전에도, Monitor Enter/Exit를 감시해 보려는 노력이 있었습니다. ^^

실행 시에 메서드 가로채기 - CLR Injection: Runtime Method Replacer 개선 - 세 번째 이야기(Monitor.Enter 후킹)
; https://www.sysnet.pe.kr/2/0/12165

하지만, 저런 것은 특정 프로그램을 대상으로 한다면 수용할 수도 있겠지만, 일반적인 범용 프로그램을 대상으로 하기에는 다소 위험한 코드입니다. 좀 더 시스템적으로 안정적인 방법이 필요한데 다행히 ETW로 목적을 달성할 수 있습니다. 이를 위해 필요한 코드는 지난 글에 설명한 ETW 예제 코드를 약간만 변형시키면 됩니다.

// ...[생략]...

using (var session = new TraceEventSession(sessionName, null))
{
    var restarted = session.EnableProvider(
        ClrTraceEventParser.ProviderGuid, TraceEventLevel.Verbose,
        (ulong)(ClrTraceEventParser.Keywords.Contention));

    Console.CancelKeyPress += delegate (object sender, ConsoleCancelEventArgs e) { session.Dispose(); };

    using (TraceLogEventSource traceLogSource = TraceLog.CreateFromTraceEventSession(session))
    {
        traceLogSource.Clr.ContentionStart += delegate (ContentionStartTraceData data)
        {
            if (data.ProcessID != _processId)
            {
                return;
            }

            Console.WriteLine($"[{data.TimeStamp}] {data.ThreadID} Start");
            _contentionStore.Push(data);
        };

        traceLogSource.Clr.ContentionStop += delegate (ContentionStopTraceData data)
        {
            if (data.ProcessID != _processId)
            {
                return;
            }

            Console.Write($"[{data.TimeStamp}] {data.ThreadID} Stop ");

            ContentionInfo info = _contentionStore.Pop(data);
            if (info == null)
            {
                Console.WriteLine("info == null");
                return;
            }

            Console.WriteLine($"[{data.ContentionFlags}]Lock-released: {(int)((data.TimeStampRelativeMSec - info.ContentionStartRelativeMSec))}");

        };

        traceLogSource.Process();
    }

    // ...[생략]...
}

얼마나 잘 동작하는지 실습을 위해 감시할 대상 프로그램을 다음의 예제 코드로 작성해 보면,

{
    int workerCount = ...;
    ThreadPool.SetMinThreads(workerCount, workerCount);

    Thread.Sleep(2000);

    Task [] workers = new Task[workerCount];
    for (int i = 0; i < workerCount; i++)
    {
        workers[i] = Task.Run(() =>
        {
            DateTime dt1 = DateTime.Now;

            Console.WriteLine($"[{dt1}] {AppDomain.GetCurrentThreadId()} {Thread.CurrentThread.ManagedThreadId} Before-lock");
            lock (lockObj)
            {
                DateTime dt2 = DateTime.Now;
                Console.WriteLine($"[{dt2}] {AppDomain.GetCurrentThreadId()} {Thread.CurrentThread.ManagedThreadId} After-lock {(int)(dt2 - dt1).TotalMilliseconds}");

                Thread.Sleep(1000);
            }
        });
    }

    foreach (Task task in workers)
    {
        task.Wait();
    }
}

실행 시, 출력 결과가 다음과 같이 나오지만,

[2020-07-08 오전 12:21:53] 26072 4 Before-lock
[2020-07-08 오전 12:21:53] 29048 5 Before-lock
[2020-07-08 오전 12:21:53] 30468 3 Before-lock
[2020-07-08 오전 12:21:53] 9148 6 Before-lock
[2020-07-08 오전 12:21:53] 31500 9 Before-lock
[2020-07-08 오전 12:21:53] 30732 8 Before-lock
[2020-07-08 오전 12:21:53] 25124 11 Before-lock
[2020-07-08 오전 12:21:53] 26072 4 After-lock 2
[2020-07-08 오전 12:21:53] 22400 10 Before-lock
[2020-07-08 오전 12:21:53] 16732 12 Before-lock
[2020-07-08 오전 12:21:53] 23136 7 Before-lock
[2020-07-08 오전 12:21:53] 336 18 Before-lock
[2020-07-08 오전 12:21:53] 12152 17 Before-lock
[2020-07-08 오전 12:21:53] 19224 20 Before-lock
[2020-07-08 오전 12:21:53] 25960 22 Before-lock
[2020-07-08 오전 12:21:53] 18180 21 Before-lock
[2020-07-08 오전 12:21:53] 20160 13 Before-lock
[2020-07-08 오전 12:21:53] 15896 19 Before-lock
[2020-07-08 오전 12:21:53] 29252 15 Before-lock
[2020-07-08 오전 12:21:53] 5088 14 Before-lock
[2020-07-08 오전 12:21:53] 7164 16 Before-lock
[2020-07-08 오전 12:21:54] 29048 5 After-lock 1008
[2020-07-08 오전 12:21:55] 30468 3 After-lock 2014
[2020-07-08 오전 12:21:56] 9148 6 After-lock 3015
[2020-07-08 오전 12:21:57] 31500 9 After-lock 4016
[2020-07-08 오전 12:21:58] 30732 8 After-lock 5022
[2020-07-08 오전 12:21:59] 25124 11 After-lock 6035
[2020-07-08 오전 12:22:00] 22400 10 After-lock 7044
[2020-07-08 오전 12:22:01] 16732 12 After-lock 8046
[2020-07-08 오전 12:22:02] 23136 7 After-lock 9053
[2020-07-08 오전 12:22:03] 336 18 After-lock 10056
[2020-07-08 오전 12:22:04] 12152 17 After-lock 11057
[2020-07-08 오전 12:22:05] 19224 20 After-lock 12062
[2020-07-08 오전 12:22:06] 25960 22 After-lock 13076
[2020-07-08 오전 12:22:07] 18180 21 After-lock 14090
[2020-07-08 오전 12:22:08] 20160 13 After-lock 15110
[2020-07-08 오전 12:22:09] 15896 19 After-lock 16123
[2020-07-08 오전 12:22:10] 29252 15 After-lock 17138
[2020-07-08 오전 12:22:11] 5088 14 After-lock 18147
[2020-07-08 오전 12:22:12] 7164 16 After-lock 19155

ETW로 모니터링한 경우는,

[2020-07-08 오전 12:21:53] 26072 Start
[2020-07-08 오전 12:21:53] 26072 Stop [Native]Lock-released: 0
[2020-07-08 오전 12:21:53] 30468 Start
[2020-07-08 오전 12:21:53] 30468 Stop [Native]Lock-released: 0
[2020-07-08 오전 12:21:53] 30468 Start
[2020-07-08 오전 12:21:53] 30468 Stop [Native]Lock-released: 0
[2020-07-08 오전 12:21:53] 26072 Start
[2020-07-08 오전 12:21:53] 26072 Stop [Native]Lock-released: 0
[2020-07-08 오전 12:21:53] 29048 Start
[2020-07-08 오전 12:21:53] 29048 Stop [Native]Lock-released: 0
[2020-07-08 오전 12:21:53] 29048 Start
[2020-07-08 오전 12:21:53] 29048 Stop [Native]Lock-released: 0
[2020-07-08 오전 12:21:53] 29048 Start
[2020-07-08 오전 12:21:53] 26072 Start
[2020-07-08 오전 12:21:53] 26072 Stop [Native]Lock-released: 0
[2020-07-08 오전 12:21:53] 26072 Start
[2020-07-08 오전 12:21:53] 26072 Stop [Native]Lock-released: 0
[2020-07-08 오전 12:21:53] 29048 Stop [Native]Lock-released: 0
[2020-07-08 오전 12:21:53] 9148 Start
[2020-07-08 오전 12:21:53] 9148 Stop [Native]Lock-released: 0
[2020-07-08 오전 12:21:53] 26072 Start
[2020-07-08 오전 12:21:53] 23136 Start
[2020-07-08 오전 12:21:53] 31500 Start
[2020-07-08 오전 12:21:53] 25124 Start
[2020-07-08 오전 12:21:53] 25124 Stop [Native]Lock-released: 0
[2020-07-08 오전 12:21:53] 30732 Start
[2020-07-08 오전 12:21:53] 25124 Start
[2020-07-08 오전 12:21:53] 26072 Stop [Managed]Lock-released: 0
[2020-07-08 오전 12:21:53] 22400 Start
[2020-07-08 오전 12:21:53] 22400 Stop [Managed]Lock-released: 0
[2020-07-08 오전 12:21:53] 5088 Start
[2020-07-08 오전 12:21:53] 20160 Start
[2020-07-08 오전 12:21:53] 29252 Start
[2020-07-08 오전 12:21:53] 22400 Start
[2020-07-08 오전 12:21:53] 16732 Start
[2020-07-08 오전 12:21:53] 23136 Stop [Managed]Lock-released: 2
[2020-07-08 오전 12:21:53] 336 Start
[2020-07-08 오전 12:21:53] 336 Stop [Native]Lock-released: 0
[2020-07-08 오전 12:21:53] 15896 Start
[2020-07-08 오전 12:21:53] 15896 Stop [Native]Lock-released: 0
[2020-07-08 오전 12:21:53] 336 Start
[2020-07-08 오전 12:21:53] 15896 Start
[2020-07-08 오전 12:21:53] 12152 Start
[2020-07-08 오전 12:21:53] 7164 Start
[2020-07-08 오전 12:21:53] 23136 Start
[2020-07-08 오전 12:21:53] 336 Stop [Managed]Lock-released: 0
[2020-07-08 오전 12:21:53] 18180 Start
[2020-07-08 오전 12:21:53] 25960 Start
[2020-07-08 오전 12:21:53] 19224 Start
[2020-07-08 오전 12:21:53] 336 Start
[2020-07-08 오전 12:21:53] 12152 Stop [Managed]Lock-released: 1
[2020-07-08 오전 12:21:53] 12152 Start
[2020-07-08 오전 12:21:53] 19224 Stop [Managed]Lock-released: 0
[2020-07-08 오전 12:21:53] 19224 Start
[2020-07-08 오전 12:21:53] 25960 Stop [Managed]Lock-released: 1
[2020-07-08 오전 12:21:53] 25960 Start
[2020-07-08 오전 12:21:53] 18180 Stop [Managed]Lock-released: 2
[2020-07-08 오전 12:21:53] 18180 Start
[2020-07-08 오전 12:21:53] 20160 Stop [Managed]Lock-released: 8
[2020-07-08 오전 12:21:53] 20160 Start
[2020-07-08 오전 12:21:53] 15896 Stop [Managed]Lock-released: 9
[2020-07-08 오전 12:21:53] 29252 Stop [Managed]Lock-released: 11
[2020-07-08 오전 12:21:53] 15896 Start
[2020-07-08 오전 12:21:53] 29252 Start
[2020-07-08 오전 12:21:53] 5088 Stop [Managed]Lock-released: 11
[2020-07-08 오전 12:21:53] 5088 Start
[2020-07-08 오전 12:21:53] 7164 Stop [Managed]Lock-released: 10
[2020-07-08 오전 12:21:53] 7164 Start
[2020-07-08 오전 12:21:54] 28292 Start
[2020-07-08 오전 12:21:57] 31500 Stop [Managed]Lock-released: 4015
[2020-07-08 오전 12:21:58] 30732 Stop [Managed]Lock-released: 5022
[2020-07-08 오전 12:21:59] 25124 Stop [Managed]Lock-released: 6034
[2020-07-08 오전 12:22:00] 22400 Stop [Managed]Lock-released: 7043
[2020-07-08 오전 12:22:01] 16732 Stop [Managed]Lock-released: 8046
[2020-07-08 오전 12:22:02] 23136 Stop [Managed]Lock-released: 9049
[2020-07-08 오전 12:22:03] 336 Stop [Managed]Lock-released: 10053
[2020-07-08 오전 12:22:04] 12152 Stop [Managed]Lock-released: 11053
[2020-07-08 오전 12:22:05] 19224 Stop [Managed]Lock-released: 12060
[2020-07-08 오전 12:22:06] 25960 Stop [Managed]Lock-released: 13073
[2020-07-08 오전 12:22:07] 18180 Stop [Managed]Lock-released: 14085
[2020-07-08 오전 12:22:08] 20160 Stop [Managed]Lock-released: 15099
[2020-07-08 오전 12:22:09] 15896 Stop [Managed]Lock-released: 16113
[2020-07-08 오전 12:22:10] 29252 Stop [Managed]Lock-released: 17126
[2020-07-08 오전 12:22:11] 5088 Stop [Managed]Lock-released: 18135
[2020-07-08 오전 12:22:12] 7164 Stop [Managed]Lock-released: 19144
[2020-07-08 오전 12:22:13] 28292 Stop [Managed]Lock-released: 19163
[2020-07-08 오전 12:22:32] 23136 Start
[2020-07-08 오전 12:22:32] 23136 Stop [Native]Lock-released: 0
[2020-07-08 오전 12:22:33] 31500 Start
[2020-07-08 오전 12:22:33] 31500 Stop [Native]Lock-released: 0

원래 프로그램의 결과에서 1초, 2초, 3초에 해당하는 대기 시간이, 어떤 때는 출력이 되고 어떤 때는 출력이 안 됩니다. 그러니까, 100% 믿을 수는 없지만 그래도 성능 하락을 유발할 수 있는 정도는 알아낼 수 있으므로 그런대로 도움이 될 수 있습니다.

또 다른 경우로 다음과 같이 테스트를 해보면,

{
    Thread t1 = new Thread(threadFunc);
    Thread t2 = new Thread(threadFunc);

    t1.Start(lockObj);
    t2.Start(lockObj);

    t1.Join();
    t2.Join();
}

private static void threadFunc(object objLock)
{
    lock (objLock)
    {
        Thread.Sleep(2000);
    }
}

분명히 lock으로 인해 지연이 있는데도 불구하고 ETW로는 저 상황을 못 잡아내는 경우가 종종 있습니다. 그러니까, ETW 이벤트를 100% 믿고 진단을 해서는 안 됩니다. 그래도 메서드 가로채기 등의 방법보다는 안전하므로 현재로서는 ETW를 이용하는 것이 가장 최선으로 보입니다.

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

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

[다음 글] 기타: 77. DataDog APM 간략 소개
[이전 글] .NET Framework: 924. C# - Reflection으로 변경할 수 없는 readonly 정적 필드

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

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

by SeongTae Jeong, mailto:techsharer at outlook.com

No	Writer	Date	Cnt.	Title	File(s)
11331	정성태	10/16/2017	18743	디버깅 기술: 103. windbg - .NET 4.0 이상의 환경에서 모든 DLL에 대한 심벌 파일을 로드하는 파이썬 스크립트
11330	정성태	10/16/2017	17866	디버깅 기술: 102. windbg - .NET 4.0 이상의 환경에서 DLL의 심벌 파일 로드 방법 [1]
11329	정성태	10/15/2017	22623	.NET Framework: 693. C# - 오피스 엑셀 97-2003 .xls 파일에 대해 32비트/64비트 상관없이 접근 방법	1
11328	정성태	10/15/2017	25618	.NET Framework: 692. C# - 하나의 바이너리로 환경에 맞게 32비트/64비트 EXE를 실행하는 방법	1
11327	정성태	10/15/2017	19396	.NET Framework: 691. AssemblyName을 .csproj에서 바꾼 경우 빌드 오류 발생하는 문제	1
11326	정성태	10/15/2017	19464	.NET Framework: 690. coreclr 소스코드로 알아보는 .NET 4.0의 모듈 로딩 함수 [1]
11325	정성태	10/14/2017	20203	.NET Framework: 689. CLR 4.0 환경에서 DLL 모듈의 로드 주소(Base address) 알아내는 방법
11324	정성태	10/13/2017	21695	디버깅 기술: 101. windbg - "*** WARNING: Unable to verify checksum for" 경고 없애는 방법
11322	정성태	10/13/2017	19738	디버깅 기술: 100. windbg - .NET 4.0 응용 프로그램의 Main 메서드에 Breakpoint 걸기
11321	정성태	10/11/2017	21178	.NET Framework: 688. NGen 모듈과 .NET Profiler
11320	정성태	10/11/2017	22025	.NET Framework: 687. COR_PRF_USE_PROFILE_IMAGES 옵션과 NGen의 "profiler-enhanced images" [1]
11319	정성태	10/11/2017	29714	.NET Framework: 686. C# - string 배열을 담은 구조체를 직렬화하는 방법
11318	정성태	10/7/2017	21904	VS.NET IDE: 122. 비주얼 스튜디오에서 관리자 권한을 요구하는 C# 콘솔 프로그램 제작 [1]
11317	정성태	10/4/2017	27412	VC++: 120. std::copy 등의 함수 사용 시 _SCL_SECURE_NO_WARNINGS 에러 발생
11316	정성태	9/30/2017	24862	디버깅 기술: 99. (닷넷) 프로세스(EXE)에 디버거가 연결되어 있는지 아는 방법 [4]
11315	정성태	9/29/2017	41346	기타: 68. "시작하세요! C# 6.0 프로그래밍: 기본 문법부터 실전 예제까지" 구매하신 분들을 위한 C# 7.0/7.1 추가 문법 PDF [8]
11314	정성태	9/28/2017	23070	디버깅 기술: 98. windbg - 덤프 파일로부터 닷넷 버전 확인하는 방법
11313	정성태	9/25/2017	20708	디버깅 기술: 97. windbg - 메모리 덤프로부터 DateTime 형식의 값을 알아내는 방법	1
11312	정성태	9/25/2017	23974	.NET Framework: 685. C# - 구조체(값 형식)의 필드를 리플렉션을 이용해 값을 바꾸는 방법	1
11311	정성태	9/20/2017	17394	.NET Framework: 684. System.Diagnostics.Process 객체의 명시적인 해제 권장
11310	정성태	9/19/2017	21866	.NET Framework: 683. WPF의 Window 객체를 생성했는데 GC 수집 대상이 안 되는 이유 [3]
11309	정성태	9/13/2017	19232	개발 환경 구성: 335. Octave의 명령 창에서 실행한 결과를 복사하는 방법
11308	정성태	9/13/2017	20933	VS.NET IDE: 121. 비주얼 스튜디오에서 일부 텍스트 파일을 무조건 메모장으로만 여는 문제	1
11307	정성태	9/13/2017	23388	오류 유형: 421. System.Runtime.InteropServices.SEHException - 0x80004005
11306	정성태	9/12/2017	21514	.NET Framework: 682. 아웃룩 사용자를 위한 중국어 스팸 필터 Add-in
11305	정성태	9/12/2017	23016	개발 환경 구성: 334. 기존 프로젝트를 Visual Studio를 이용해 Github의 신규 생성된 repo에 올리는 방법 [1]

AD BLOCK 해제 요청

C# - ETW를 이용한 Monitor Enter/Exit 감시