C# - ETW 관련 Win32 API 사용 예제 코드 (5) - Private Logger
C# - ETW 관련 Win32 API 사용 예제 코드 (1)
; https://www.sysnet.pe.kr/2/0/12292
C# - ETW 관련 Win32 API 사용 예제 코드 (2) NT Kernel Logger
; https://www.sysnet.pe.kr/2/0/12296
C# - ETW 관련 Win32 API 사용 예제 코드 (3) ETW Consumer 구현
; https://www.sysnet.pe.kr/2/0/12299
C# - ETW 관련 Win32 API 사용 예제 코드 (4) CLR ETW Consumer
; https://www.sysnet.pe.kr/2/0/12300
아래의 문서에 따르면,
Controlling Event Tracing Sessions
; https://learn.microsoft.com/en-us/windows/win32/etw/controlling-event-tracing-sessions
세션 방식의 제어를 다음과 같이 나눠 설명하고 있습니다.
반면 또 다른 문서를 보면,
Configuring and Starting an Event Tracing Session
; https://learn.microsoft.com/en-us/windows/win32/etw/configuring-and-starting-an-event-tracing-session
이렇게 분류를 합니다.
"Controlling"과 "Configuring and Starting"에 어떤 미묘한 차이가 차이가 있는지 현재의 저로서는 알 수 없지만... ^^; 암튼 크게 나눠보면 1) "Global Logger/Auto Logger 세션", 2) "SystemTraceProvider / NT Kernel Logger 세션", 3) "일반적인 세션", 4) "Private Logger 세션"으로 분류됩니다. 이 중에서 1번은 부팅 시점부터 작동하는 것으로 주로 device driver 개발자들을 위한 것이므로 SDK 개발자에게는 관심사가 아닙니다. 2번은 "
C# - ETW 관련 Win32 API 사용 예제 코드 (2) NT Kernel Logger"에서 다뤘고, 3번도 "
C# - ETW 관련 Win32 API 사용 예제 코드 (3) ETW Consumer 구현"에서 다뤘으므로 이제 남은 것은 "Private Logger"입니다.
사실, 개인적으로 더 관심이 있는 것은 "Private Logger"였습니다. (과거형입니다. ^^;)
A private event tracing session is a user-mode event tracing session that runs in the same process as its event trace providers
왜냐하면 다른 Logger 들과 달리 In-process 내에서 활성화하는 것이기 때문에 권한 문제도 없고 별다른 필터링 조건을 걸지 않아도 현재의 프로세스에서만 발생하는 ETW 이벤트를 취합할 수 있기 때문입니다.
구현 방법도 매우 간단한데, 기존 예제들의 소스코드에서 단순히 StartTrace와 EnableTraceEx2로 시작한 후 필요 없을 때 Close만 시키면 됩니다. 그래서 기본적인 소스 코드는 아래의 정도가 전부입니다.
string sessionName = "clrETWSession";
Guid clrProvider = new Guid("{e13c0d23-ccbc-4e12-931b-d9cc2eee27e4}");
int result = 0;
ulong sessionHandle = 0;
try
{
string logFilePath = "c:\\temp\\test.etl";
// https://chromium.googlesource.com/chromium/chromium/+/master/base/debug/trace_event_win_unittest.cc#120
EventTraceProperties prop = new EventTraceProperties(true, sessionName, Guid.Empty,
NativeMethods.EVENT_TRACE_PRIVATE_IN_PROC // In-proc for non-admin
| NativeMethods.EVENT_TRACE_PRIVATE_LOGGER_MODE // Process-private log
| NativeMethods.EVENT_TRACE_FILE_MODE_SEQUENTIAL);
prop.SetLogFileName(logFilePath, 100);
result = NativeMethods.StartTrace(out sessionHandle, sessionName, ref prop);
Console.WriteLine(result);
if (result == 0)
{
ENABLE_TRACE_PARAMETERS enableParameters = new ENABLE_TRACE_PARAMETERS();
enableParameters.Version = 1;
enableParameters.EnableProperty = (uint)EventEnableProperty.Sid;
ulong matchAnyKeywords = (ulong)ClrProviderKeywords.Exception;
result = NativeMethods.EnableTraceEx2(sessionHandle, ref clrProvider,
NativeMethods.EVENT_CONTROL_CODE_ENABLE_PROVIDER, (byte)TraceEventLevel.Informational,
matchAnyKeywords, 0, 0, ref enableParameters);
Console.WriteLine(result);
}
{
Console.WriteLine("Press ENTER key to exit...");
Console.ReadLine();
}
}
finally
{
EtwInterop.CloseActiveSession(sessionHandle);
}
기존 소스 코드와 달리 위의 예제에서는 ETW 이벤트를 로그 파일로 출력하고 있는데, 이건 Private Logger의 강제 사항입니다. (여기서 Private Logger의 매력이 확 떨어지는데) 즉, 이벤트 콜백을 받는 방식으로는 구현이 안 됩니다. 덕분에 (이벤트 콜백 함수를 지정하는) OpenTrace API 호출 및 콜백을 호출해주는 ProcessTrace API도 필요 없어 저렇게 구현이 간단합니다.
Private이라는 특성상, StartTrace를 했더라도 "logman query -ets"로 열거해도 해당 세션이 안 보이기 때문에 다른 프로세스에서는 Private Logger Session을 제어할 수 없습니다. 이로 인해 이름을 이용한 세션 닫기(EtwInterop.CloseActiveSession) 코드는,
public static int CloseActiveSession(string sessionName)
{
if (IsSessionActive(sessionName, out _) == true)
{
EventTraceProperties prop = new EventTraceProperties();
prop.Initialize();
return NativeMethods.ControlTrace(0, sessionName, ref prop, EVENT_TRACE_CONTROL_STOP);
}
return 0;
}
public static bool IsSessionActive(string sessionName, out EventTraceProperitesManaged propManaged)
{
EventTraceProperties prop = new EventTraceProperties();
prop.Initialize();
int status = NativeMethods.QueryTrace(0, sessionName, ref prop);
if (status == 0)
{
propManaged = prop.ReadAsManaged();
return true;
}
else if (status == EventTraceProperties.ERROR_WMI_INSTANCE_NOT_FOUND)
{
propManaged = new EventTraceProperitesManaged();
// The instance name passed was not recognized as valid by a WMI data provider.
return false;
}
throw new System.ComponentModel.Win32Exception(status);
}
QueryTrace API 자체에서 조회가 안 되기 때문에 실패합니다. 그래서 StartTrace로부터 반환받은 session handle로만 세션을 닫을 수 있습니다.
public static int CloseActiveSession(ulong sessionHandle)
{
EventTraceProperties prop = new EventTraceProperties();
prop.Initialize();
return NativeMethods.ControlTrace(sessionHandle, null, ref prop, EVENT_TRACE_CONTROL_STOP);
}
하지만, 어차피 프로세스 내에서만 활성화하는 것이기 때문에 다른 ETW 세션들과는 달리 프로세스가 종료하면 함께 삭제되기 때문에 굳이 닫을 필요가 많진 않을 것입니다. 그래도 프로세스 내에서는 세션 이름이 고유해야 하므로 (기존 세션이 닫히지 않은 상태에서) 만약 동일한 이름으로 StartTrace를 시도하면 0xb7(0n183: ERROR_ALREADY_EXISTS - Cannot create a file when that file already exists) 오류 코드로 실패합니다.
(
첨부한 파일은 이 글의 소스 코드를 포함합니다.)
참고로, 내부적으로 예외를 5초마다 발생시키는 닷넷 콘솔 예제에서,
C:\temp\Debug>ConsoleApp1.exe
PID == 8684
Exception occurred: 2020-08-27 오전 11:10:41
0
0
Press ENTER key to exit...
Exception occurred: 2020-08-27 오전 11:10:46
Exception occurred: 2020-08-27 오전 11:10:51
Exception occurred: 2020-08-27 오전 11:10:56
Exception occurred: 2020-08-27 오전 11:11:01
Exception occurred: 2020-08-27 오전 11:11:06
Exception occurred: 2020-08-27 오전 11:11:11
CLR Event Provider + Private Logger를 사용해 출력한 ETL 파일을
PrefView.exe로 확인한 결과 아래와 같은 식의 덤프가 나옵니다.
Started with command line: "C:\temp\PerfView.exe"
PerfView Version: 1.7.0.0 BuildDate: Thu 10/30/2014 6:41:18.79
Started: View
Warning: PdbScope not found at C:\temp\PerfViewExtensions\PdbScope.exe
Disabling the Image Size Menu Item.
Completed: View (Elapsed Time: 0.496 sec)
Started: Opening test.etl
Creating ETLX file %LOCALAPPDATA%\Temp\PerfView\test.etl_ec07ba5a.etlx from C:\temp\test.etl
MaxEventCount 0 < 1000, assumed in error, ignoring
[Opening a log file of size 0 MB of duration 32.3 sec.]
0 distinct processes.
Totals
26 events.
0 events with stack traces.
0 events with code addresses in them.
0 total code address instances. (stacks or other)
0 unique code addresses.
0 unique stacks.
0 unique activities.
0 unique managed methods parsed.
0 CLR method event records.
[Conversion complete 26 events. Conversion took 0 sec.]
ETL Size 0.012 MB ETLX Size 0.008 MB
Completed: Opening test.etl (Elapsed Time: 0.703 sec)
Started: Opening Events
Completed: Opening Events (Elapsed Time: 0.016 sec)
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.040 sec)
Histogram: _______________A_______________A______________A______________A_______________A______________A_______ Time Bucket 323.1 MSec
[Found 6 Records. 6 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.005 sec)
Histogram: _______________A_______________A______________A______________A_______________A______________A_______ Time Bucket 323.1 MSec
[Found 6 Records. 6 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.004 sec)
Histogram: _______________A_______________A______________A______________A_______________A______________A_______ Time Bucket 323.1 MSec
[Found 6 Records. 6 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.036 sec)
Histogram: _______________A_______________A______________A______________A_______________A______________A_______ Time Bucket 323.1 MSec
[Found 6 Records. 6 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.008 sec)
Histogram: _______________A_______________A______________A______________A_______________A______________A_______ Time Bucket 323.1 MSec
[Found 6 Records. 6 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.002 sec)
Histogram: _______________A_______________A______________A______________A_______________A______________A_______ Time Bucket 323.1 MSec
[Found 6 Records. 6 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.003 sec)
Histogram: A___________________________________________________________________________________________________ Time Bucket 323.1 MSec
[Found 1 Records. 1 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.001 sec)
Histogram: A___________________________________________________________________________________________________ Time Bucket 323.1 MSec
[Found 1 Records. 1 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.000 sec)
Histogram: A___________________________________________________________________________________________________ Time Bucket 323.1 MSec
[Found 1 Records. 1 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.000 sec)
Histogram: A___________________________________________________________________________________________________ Time Bucket 323.1 MSec
[Found 1 Records. 1 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.015 sec)
Histogram: _______________A_______________A______________A______________A_______________A______________A_______ Time Bucket 323.1 MSec
[Found 6 Records. 6 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.002 sec)
Histogram: _______________A_______________A______________A______________A_______________A______________A_______ Time Bucket 323.1 MSec
[Found 6 Records. 6 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.002 sec)
Histogram: _______________A_______________A______________A______________A_______________A______________A_______ Time Bucket 323.1 MSec
[Found 6 Records. 6 total events.]
Started: Opening TraceInfo
Completed: Opening TraceInfo (Elapsed Time: 0.019 sec)
Started: Opening Events
Completed: Opening Events (Elapsed Time: 0.026 sec)
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.005 sec)
Histogram: _______________A_______________A______________A______________A_______________A______________A_______ Time Bucket 323.1 MSec
[Found 6 Records. 6 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.003 sec)
Histogram: A___________________________________________________________________________________________________ Time Bucket 323.1 MSec
[Found 1 Records. 1 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.003 sec)
Histogram: A___________________________________________________________________________________________________ Time Bucket 323.1 MSec
[Found 1 Records. 1 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.001 sec)
Histogram: A___________________________________________________________________________________________________ Time Bucket 323.1 MSec
[Found 1 Records. 1 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.001 sec)
Histogram: _______________A_______________A______________A______________A_______________A______________A_______ Time Bucket 323.1 MSec
[Found 6 Records. 6 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.042 sec)
Histogram: _______________A_______________A______________A______________A_______________A______________A_______ Time Bucket 323.1 MSec
[Found 6 Records. 6 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.003 sec)
Histogram: _______________A_______________A______________A______________A_______________A______________A_______ Time Bucket 323.1 MSec
[Found 6 Records. 6 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.003 sec)
Histogram: _______________A_______________A______________A______________A_______________A______________A_______ Time Bucket 323.1 MSec
[Found 6 Records. 6 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.004 sec)
Histogram: _______________A_______________A______________A______________A_______________A______________A_______ Time Bucket 323.1 MSec
[Found 6 Records. 6 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.009 sec)
Histogram: _______________A_______________A______________A______________A_______________A______________A_______ Time Bucket 323.1 MSec
[Found 6 Records. 6 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.002 sec)
Histogram: _______________A_______________A______________A______________A_______________A______________A_______ Time Bucket 323.1 MSec
[Found 6 Records. 6 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.002 sec)
Histogram: _______________A_______________A______________A______________A_______________A______________A_______ Time Bucket 323.1 MSec
[Found 6 Records. 6 total events.]
Started: Scanning Events
Completed: Scanning Events (Elapsed Time: 0.003 sec)
Histogram: A___________________________________________________________________________________________________ Time Bucket 323.1 MSec
[Found 1 Records. 1 total events.]
Assuming total current time range
Started: Reading Events
Completed: Reading Events (Elapsed Time: 0.005 sec)
Error: Could not find stack source CPU
Assuming total current time range
Started: Reading Events
Completed: Reading Events (Elapsed Time: 0.002 sec)
Error: Could not find stack source Thread Time (with Tasks)
Assuming total current time range
Started: Reading Events
Completed: Reading Events (Elapsed Time: 0.001 sec)
Error: Could not find stack source Any
<Event MSec= "0.0000" PID="8684" PName="Process(8684)" TID="16300" EventName="EventTrace"
TimeStamp="08-27-20 11:10:41.708483" ID="Illegal" Version="0" Keywords="0x00000000" TimeStampQPC="3,003,918,568,692"
Level="Always" ProviderName="Windows Kernel" ProviderGuid="9e814aad-3204-11d2-9a82-006008a86939" ClassicProvider="True"
Opcode="0" TaskGuid="68fdd900-4a3e-11d1-84f4-0000f80464e3" Channel="0" PointerSize="8"
CPU="0" EventIndex="0" TemplateType="EventTraceHeaderTraceData">
<PrettyPrint>
<Event MSec= "0.0000" PID="8684" PName="Process(8684)" TID="16300" EventName="EventTrace" BufferSize="4,096" Version="0x0501000A" ProviderVersion="19,041" NumberOfProcessors="4" EndTime="2020-08-27 오전 11:11:14" TimerResolution="156,250" MaxFileSize="100" LogFileMode="0x00020801" BuffersWritten="3" StartBuffers="1" PointerSize="8" EventsLost="0" CPUSpeed="3,392" BootTime="2020-08-23 오후 11:45:04" PerfFreq="10,000,000" StartTime="1601-01-01 오전 9:00:00" ReservedFlags="0x00000001" BuffersLost="0" SessionName="clrETWSession" LogFileName="c:\temp\test.etl"/>
</PrettyPrint>
<Payload Length="342">
0: 0 10 0 0 a 0 1 5 | 61 4a 0 0 4 0 0 0 ........ aJ......
10: 1d a4 6 57 17 7c d6 1 | 5a 62 2 0 64 0 0 0 ...W.|.. Zb..d...
20: 1 8 2 0 3 0 0 0 | 1 0 0 0 8 0 0 0 ........ ........
30: 0 0 0 0 40 d 0 0 | 0 0 0 0 0 0 0 0 ....@... ........
40: 0 0 0 0 0 0 0 0 | e4 fd ff ff 40 0 74 0 ........ ....@.t.
50: 7a 0 72 0 65 0 73 0 | 2e 0 64 0 6c 0 6c 0 z.r.e.s. ..d.l.l.
60: 2c 0 2d 0 36 0 32 0 | 32 0 0 0 0 0 0 0 ,.-.6.2. 2.......
70: 0 0 0 0 0 0 0 0 | 0 0 0 0 0 0 0 0 ........ ........
80: 0 0 0 0 0 0 0 0 | 0 0 0 0 0 0 0 0 ........ ........
90: 0 0 0 0 0 0 0 0 | 0 0 0 0 0 0 0 0 ........ ........
a0: 40 0 74 0 7a 0 72 0 | 65 0 73 0 2e 0 64 0 @.t.z.r. e.s...d.
b0: 6c 0 6c 0 2c 0 2d 0 | 36 0 32 0 31 0 0 0 l.l.,.-. 6.2.1...
c0: 0 0 0 0 0 0 0 0 | 0 0 0 0 0 0 0 0 ........ ........
d0: 0 0 0 0 0 0 0 0 | 0 0 0 0 0 0 0 0 ........ ........
e0: 0 0 0 0 0 0 0 0 | 0 0 0 0 0 0 0 0 ........ ........
f0: c4 ff ff ff 0 0 0 0 | 40 e3 d7 fc 5b 79 d6 1 ........ @...[y..
100: 80 96 98 0 0 0 0 0 | a5 1 c5 43 17 7c d6 1 ........ ...C.|..
110: 1 0 0 0 0 0 0 0 | 63 0 6c 0 72 0 45 0 ........ c.l.r.E.
120: 54 0 57 0 53 0 65 0 | 73 0 73 0 69 0 6f 0 T.W.S.e. s.s.i.o.
130: 6e 0 0 0 63 0 3a 0 | 5c 0 74 0 65 0 6d 0 n...c.:. \.t.e.m.
140: 70 0 5c 0 74 0 65 0 | 73 0 74 0 2e 0 65 0 p.\.t.e. s.t...e.
150: 74 0 6c 0 0 0 | t.l...
</Payload>
</Event>
그나저나... 시간 데이터에 대해 덤프한 것을 보면 이상한 부분이 눈에 띄는 군요.
BootTime="2020-08-23 오후 11:45:04"
StartTime="1601-01-01 오전 9:00:00"
EndTime="2020-08-27 오전 11:11:14"
BootTime, EndTime은 올바르게 출력이 되었는데, StartTime은 그렇지 않습니다. 날짜 데이터인 듯한 필드를 Playload로부터 추출해서 C#으로 덤프해 보면,
{
byte[] buf = { 0x40, 0xe3, 0xd7, 0xfc, 0x5b, 0x79, 0xd6, 0x01 };
long result = BitConverter.ToInt64(buf, 0);
Console.WriteLine(DateTime.FromFileTime(result)); // 2020-08-23 오후 11:45:04
}
{
byte[] buf = { 0xa5, 0x01, 0xc5, 0x43, 0x17, 0x7c, 0xd6, 0x01 };
long result = BitConverter.ToInt64(buf, 0);
Console.WriteLine(DateTime.FromFileTime(result)); // 2020-08-27 오전 11:10:41
}
{
byte[] buf = { 0x1d, 0xa4, 0x06, 0x57, 0x17, 0x7c, 0xd6, 0x01 };
long result = BitConverter.ToInt64(buf, 0);
Console.WriteLine(DateTime.FromFileTime(result)); // 2020-08-27 오전 11:11:14
}
다행히 원본 데이터가 잘못된 것은 아니고 덤프하는 측의 오류입니다. 실제로
(github에 소스 코드까지 공개된) 최신 버전의 PerfView에서는 저런 문제가 없습니다. ^^
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]