성태의 닷넷 이야기
홈 주인
모아 놓은 자료
프로그래밍
질문/답변
사용자 관리
사용자
메뉴
아티클
외부 아티클
유용한 코드
온라인 기능
MathJax 입력기
최근 덧글
[정성태] Java - How to use the Foreign Funct...
[정성태] 제가 큰 실수를 했군요. ^^; Delegate를 통한 Bein...
[정성태] Working with Rust Libraries from C#...
[정성태] Detecting blocking calls using asyn...
[정성태] 아쉽게도, 커뮤니티는 아니고 개인 블로그입니다. ^^
[정성태] 질문이 잘 이해가 안 됩니다. 우선, 해당 소스코드에서 ILis...
[양승조
] var대신 dinamic으로 선언해서 해결은 했습니다. 맞는 해...
[양승조
] 또 막혔습니다. ㅠㅠ var list = props[i].Ge...
[양승조
] 아. 감사합니다. 어제는 안됐던것 같은데....정신을 차려야겠네...
[정성태] "props[i].GetValue(props[i])" 코드에서 ...
글쓰기
제목
이름
암호
전자우편
HTML
홈페이지
유형
제니퍼 .NET
닷넷
COM 개체 관련
스크립트
VC++
VS.NET IDE
Windows
Team Foundation Server
디버깅 기술
오류 유형
개발 환경 구성
웹
기타
Linux
Java
DDK
Math
Phone
Graphics
사물인터넷
부모글 보이기/감추기
내용
<div style='display: inline'> <h1 style='font-family: Malgun Gothic, Consolas; font-size: 20pt; color: #006699; text-align: center; font-weight: bold'>C# - ETW를 이용한 Monitor Enter/Exit 감시</h1> <p> 예전에도, Monitor Enter/Exit를 감시해 보려는 노력이 있었습니다. ^^<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 실행 시에 메서드 가로채기 - CLR Injection: Runtime Method Replacer 개선 - 세 번째 이야기(Monitor.Enter 후킹) ; <a target='tab' href='https://www.sysnet.pe.kr/2/0/12165'>https://www.sysnet.pe.kr/2/0/12165</a> </pre> <br /> 하지만, 저런 것은 특정 프로그램을 대상으로 한다면 수용할 수도 있겠지만, 일반적인 범용 프로그램을 대상으로 하기에는 다소 위험한 코드입니다. 좀 더 시스템적으로 안정적인 방법이 필요한데 다행히 ETW로 목적을 달성할 수 있습니다. 이를 위해 필요한 코드는 <a target='tab' href='https://www.sysnet.pe.kr/2/0/12255'>지난 글에 설명한 ETW 예제 코드</a>를 약간만 변형시키면 됩니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > // ...[생략]... using (var session = new TraceEventSession(sessionName, null)) { var restarted = session.EnableProvider( ClrTraceEventParser.ProviderGuid, TraceEventLevel.Verbose, (ulong)(<span style='color: blue; font-weight: bold'>ClrTraceEventParser.Keywords.Contention</span>)); Console.CancelKeyPress += delegate (object sender, ConsoleCancelEventArgs e) { session.Dispose(); }; using (TraceLogEventSource traceLogSource = TraceLog.CreateFromTraceEventSession(session)) { <span style='color: blue; font-weight: bold'>traceLogSource.Clr.ContentionStart</span> += delegate (ContentionStartTraceData data) { if (data.ProcessID != _processId) { return; } Console.WriteLine($"[{data.TimeStamp}] {data.ThreadID} Start"); _contentionStore.Push(data); }; <span style='color: blue; font-weight: bold'>traceLogSource.Clr.ContentionStop</span> += 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(); } // ...[생략]... } </pre> <br /> 얼마나 잘 동작하는지 실습을 위해 감시할 대상 프로그램을 다음의 예제 코드로 작성해 보면,<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > { 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(); } } </pre> <br /> <br /> 실행 시, 출력 결과가 다음과 같이 나오지만,<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > [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 <span style='color: blue; font-weight: bold'>[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</span> [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 </pre> <br /> ETW로 모니터링한 경우는,<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > [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 <span style='color: blue; font-weight: bold'>[2020-07-08 오전 12:21:57] 31500 Stop [Managed]Lock-released: 4015</span> [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 </pre> <br /> 원래 프로그램의 결과에서 1초, 2초, 3초에 해당하는 대기 시간이, 어떤 때는 출력이 되고 어떤 때는 출력이 안 됩니다. 그러니까, 100% 믿을 수는 없지만 그래도 성능 하락을 유발할 수 있는 정도는 알아낼 수 있으므로 그런대로 도움이 될 수 있습니다.<br /> <br /> <hr style='width: 50%' /><br /> <br /> 또 다른 경우로 다음과 같이 테스트를 해보면,<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > { 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); } } </pre> <br /> 분명히 lock으로 인해 지연이 있는데도 불구하고 ETW로는 저 상황을 못 잡아내는 경우가 종종 있습니다. 그러니까, ETW 이벤트를 100% 믿고 진단을 해서는 안 됩니다. 그래도 메서드 가로채기 등의 방법보다는 안전하므로 현재로서는 ETW를 이용하는 것이 가장 최선으로 보입니다.<br /> <br /> (<a target='tab' href='https://www.sysnet.pe.kr/bbs/DownloadAttachment.aspx?fid=1607&boardid=331301885'>첨부 파일은 이 글의 예제 코드를 포함</a>합니다.)<br /> </p><br /> <br /><hr /><span style='color: Maroon'>[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]</span> </div>
첨부파일
스팸 방지용 인증 번호
1340
(왼쪽의 숫자를 입력해야 합니다.)