当社では、PCの運用管理を支援する製品「V-Recover」 ⧉を開発しています。「V-Recover」は環境復元システムであり、PC上で行った変更を再起動後に元に戻します。

現在、本製品では一部のログ出力にWindowsのイベントログを使用していますが、これは重い操作であり、特に大量のログを短時間で書き込む場合にはパフォーマンスが低下します。またログを出力し続けるため、解析用の粒度の細かいログを出しにくいという問題があります。

そこで、より高パフォーマンスでデバッグに近いログを出しつつ運用できる手法として、Event Tracing for Windows（ETW）を紹介します。

Windowsにおけるトレース

現代のコンピュータシステムにおいて、問題の診断やパフォーマンスの解析は非常に重要です。特にWindows環境では、システムの動作やアプリケーションの挙動を詳細に追跡するための「トレース」機能が充実しています。

トレースとは、システムやアプリケーションが実行中に発生するイベントや動作を記録する行為です。この記録を分析することで、パフォーマンスのボトルネックやエラーの原因を特定することができます。Windowsでは、以下のようなツールや機能がトレースに利用されます。

これらのツールの中でも、特にWPRやProcMonはEvent Tracing for Windows（ETW）を利用しています。

Event Tracing for Windowsについて

Event Tracing for Windows（ETW）は、Windowsの主要な機能の一つであり、アプリケーションやカーネルモードドライバーにログとトレースイベントを提供し、それらの使用や管理をサポートします。

高速で効率的なトレースが可能であり、Windowsをベースにした多くのトレースツールやパフォーマンス監視ツールで使用されています。この記事では、ETWについて解説し、実際に使用方法を紹介します。

アーキテクチャ、仕組み、全体像

ETWの機能は主にカーネルで実装されていますが、ユーザーモードとカーネルモード両方のアプリケーションでETWのトレースイベント機能を利用することができます。

ETWは以下の4つの要素から成り立っています。

ETWのアーキテクチャは以下のようになっています。

ETWセッションの開始と停止は、イベントがシステムの整合性を悪用される可能性があるシステムデータを含めることができるため、特権の高い操作とみなされています。
ETWによって行われる各操作には、セッション、プロバイダー、プロバイダーのグループを保護するセキュリティ記述子によって許可されていなければならず、明確に定義されたアクセス権が必要です。セキュリティ記述子はHKLM\SYSTEM\CurrentControlSet\Control\WMI\Securityレジストリキーを参照します。
SYSTEMアカウント、Administrators、LOCAL SERVICE、NETWORK SERVICEグループには、ほとんどのアクセス権が自動的に付与されているのでETWの機能を使用できますが、一般ユーザーはアクセス権がないのでETWの機能を使用することはできません。一般ユーザーでもETWの機能を使用したい場合は、すべてのアクセス権が付与されているPerformance Log Userグループに加えることで使用できるようになります。

カーネルモードを含んだ場合の全体像は以下のようになっています。

グローバルセッションの作成やプロバイダーの登録と有効化といったETWの機能はカーネル内にあります。NTDLLは、ユーザーモードアプリケーションがカーネルモードの機能を呼び出すためのインターフェースを提供しており、ユーザーモードのアプリケーションがカーネル内の機能を使う場合に使用されます。NTDLLにはこのほかにも、ETWセッションの作成やプロバイダーの有効化といった一部のAPIが直接実装されており、ライブラリを介して呼び出すことで各アプリケーションにユーザーモードのAPIが提供されています。

図の中に挙げているライブラリの役割は以下の通りです。

• Sechost.dllは、ETWセッションの管理やプロバイダーの制御に関連するAPIを提供する
• Advapi32.dllは、ユーザーモードでETWのトレースイベントを生成するためのAPIを提供する
• TDH.dll(Trace Data Helper)は、イベントのメタデータを解析するためのAPIを提供する
• WevtApi.dllは、Windowsのイベントログシステムにアクセスし、操作するためのAPIを提供する

カーネルドライバーはカーネルモードのETW APIを使用してETWイベントを生成します。カーネルモードのETWセッションは、主にカーネルドライバーやシステムコンポーネントによって生成されるイベントを収集します。

セキュアカーネルは、システムのセキュリティを強化し、信頼性の高いイベントトレースを実現するために使用されています。主にデータの保護、信頼性の確保、アクセス制御、セキュアなイベント記録といった役割を果たします。これにより、システムの重要なイベントデータが安全に収集・管理され、セキュリティインシデントの追跡や解析が容易になります。

各仕組みの説明

アーキテクチャの解説で出てきた用語についての詳細や、ETWの仕組みについて解説を行います。

セッション

セッションはプロバイダーとコンシューマーをつなぐ大事な要素の1つであり、コントローラーが有効にした1つ以上のプロバイダーからのイベントを記録します。また、セッションには通常、どのプロバイダーがどのイベントを記録する必要があるか、イベントをどのように処理する必要があるかを表す情報が含まれており、特定のGUIDのイベントを受け入れるように構成することができます。プロバイダーが生成したイベントは、イベントレベルやキーワード、イベントID等の値からフィルタリングを行うことができます。

Win32の場合、セッションはStartTraceAPIを使用して作成・開始され、ControlTraceAPIおよびEnableTraceExAPIを使用して構成されます。ControlTraceAPIではプロパティの値が更新され、EnableTraceExAPIではプロバイダーがイベントをトレースセッションに記録する方法を構成します。Xperf、Logmanといったコマンドラインツールは、これらのAPIを使用してトレースセッションを開始または制御します。

コントローラー

コントローラーでは以下のことが行えます。

• セッションの作成
• セッションの開始および停止
• ログファイルのサイズと場所の定義
• バッファプールのサイズ管理
• イベントのフィルタリング
• プロバイダーがイベントをセッションに記録できるよう有効化

コントローラーの例として、パフォーマンスモニターやlogman、Xperf、Tracelogなどがあります。XperfはWindows ADKの一部で、マイクロソフトの公式サイトからダウンロードが可能です。

コントローラーがプロバイダーを有効化する場合、EnableTraceExAPIを介してプロバイダーを有効にします。このAPIは、受信したいイベントのカテゴリを指定したり、プロセスIDやファイル名などでイベントに対する詳細なフィルタリングを行うことができます。

プロバイダー

プロバイダーはイベントを生成する前に、ETWに登録されている必要があります。 プロバイダー自体を登録した後、コントローラーはプロバイダーの有効状態を変化させることでログの記録を有効または無効にできます。一般に、プロバイダーが有効でない間に生成されたイベントは、バッファに記録されません。これにより、イベントログを常に記録することなく、アプリケーションにイベントトレースを追加できます。

プロバイダーには以下の4種類があります。Windows Vista以降のアプリケーションを作成する場合は、マニフェストベースプロバイダーまたはTraceLoggingプロバイダーの使用を推奨しています。

コントローラーで述べた通り、プロバイダーはEnableTraceExAPIを介してセッションで有効化されます。MOFプロバイダーとWPPプロバイダーは一度に1つのセッションでのみ有効にできますが、マニフェストベースプロバイダーとTraceLoggingプロバイダーは最大8つのセッションで有効にすることができます。

コンシューマー

コンシューマーは、イベントのソースとして1つ以上のイベントトレースセッションを選択するアプリケーションです。コンシューマーは、複数のセッションから同時にイベントを要求でき、それに対してシステムは時系列順にイベントを配信します。コンシューマーは、ログファイルや循環バッファに格納されているイベント、またはセッションからリアルタイムで配信されるイベントを受信し、それらを人の読める形に処理して出力します。イベントを処理する場合、コンシューマーは開始時刻と終了時刻を指定でき、指定された期間に発生したイベントのみを見ることができます。

コンシューマーの例として、TracepdbやTracefmt、tracerptなどのツールがあります。

イベント

ETWプロバイダーを登録した後、プロバイダーアプリケーションによってイベントが発行されます。発行方法はプロバイダーによって異なり、例えばマニフェストベースプロバイダーはEventWriteAPIを使用し、MOFやWPPプロバイダーはTraceEventAPIを使用します。

ETWでのイベントの処理は、Sechost.dllによって提供されるサービスを使用したコンシューマーアプリケーションによって、主にユーザーモードで実行されます。
コンシューマーアプリケーションはOpenTraceAPIを使用してevent trace log（etl）ファイルを開く、またはリアルタイムロガーへの接続を確立します。その後、ProcessTraceAPIを使用してイベントコールバック関数を指定します。

イベントトレース

ETWでイベントトレースを行う流れは以下の通りです。

1. プロバイダーを作成またはトレースしたい既存のプロバイダーを選ぶ
2. プロバイダーを登録する
3. コントローラーがセッションを作成し開始する
4. コントローラーがプロバイダーを有効化する
5. プロバイダーがイベントを発行する（イベントはetlファイルに記録される）
6. コントローラーがセッションを終了する
7. コンシューマーがログファイルを開きイベントを処理する

この手順は、プロバイダーが発行したイベントのデータを一旦ファイルに溜めておき、コンシューマーがセッション終了後にそれを処理して確認するので、リアルタイムの状態を確認する手段としては向いていません。

リアルタイムにログをトレースする流れは以下の通りです。

1. プロバイダーを作成またはトレースしたい既存のプロバイダーを選ぶ
2. プロバイダーを登録する
3. コントローラーがセッションを作成し開始する
4. コントローラーがプロバイダーを有効化する
5. コンシューマーがセッションを開く
6. プロバイダーがイベントを発行する
7. コンシューマーがイベントを処理する
8. コントローラーがセッションを終了する
9. コンシューマーがセッションを閉じる

ログを保存する方法は、アプリケーションの現在の状況を追うのに向いていない代わりに何度でもイベントを確認できるので、トラブルシューティングなどに向いています。一方、リアルタイムにログをトレースする方法は、同じイベントを一度しか処理できない代わりに、アプリケーションの現在の状況を追うのに向いており、アプリケーションの挙動を確認するのに適しています。

参考として、以下にそれぞれの手順で使用されるAPIを記載します。詳細はマイクロソフトの公式ドキュメントを参照してください。

実践

では実際に以下の手順でETWを操作してみます。

1. Windows上にある既存のプロバイダーのログを取得し確認
2. 自分でプロバイダーを作成し、イベントログを確認

この記事では、C++（Win32 API）を使用して紹介しますが、ETWはWin32 API以外でもログトレースを行うことができます。もし、C#（.NET）で使いたい場合は、EventSourceクラス ⧉を使うことでイベントの情報を取得したり、イベントを書き込んだりすることができます。

1. Windows上にある既存のプロバイダーのログを取得し確認

Windows 10 System Programming Part 2のサンプルコード ⧉を参考にし、実際に操作してみてどのような流れでプロバイダーのログを取得しているのか確認しました。そのうえでわかった、イベントトレースで触れていない、より細かい部分を解説します。

プロバイダー一覧の取得

プロバイダーの一覧を取得したい場合は、TdhEnumerateProvidersAPIを使用します。 TdhEnumerateProvidersAPIの引数は以下の通りです。

このAPIを使用することで、コンピューターに登録されているプロバイダーの登録名とGUIDを含んだ情報の配列を取得することができます。

コンシューマーのコールバック

イベントの処理はコンシューマーのコールバック関数で行われます。
コンシューマーのコールバック関数は、EVENT_TRACE_LOGFILE構造体のEventRecordCallbackメンバーに設定されます。この構造体にはログファイル名やロガー名などの情報も含まれ、これをOpenTraceAPIに渡すことでトレースセッションを開きます。開いたセッションでトレースイベントが発行されると、指定したコールバック関数が呼ばれ、イベントごとにログ出力やデータ処理などの処理が行われます。

コールバック関数の引数としてイベントに関する各種IDやタイムスタンプといったイベントの情報が格納されているPEVENT_RECORD構造体の情報が渡され、基本的なイベントの情報を処理することができます。また、TdhGetEventInformationAPIを使用することでイベントの詳細な情報を取得することができます。

実環境上でのプロバイダー一覧とログの取得

API利用でのコンシューマーの動作について説明しましたが、今回は既存のアプリケーションであるxperfを使い、プロバイダーの情報を取得します。

以下のコマンドを実行することで登録済みの既存のプロバイダー一覧を取得できます。

xperf -providers R

その中から適当なものを選び実行した結果、以下のように既存のプロバイダーのログを取得できました。

このようなログに任意の情報を加えてアプリケーションで出力できるように、次の項目で実際にプロバイダーの作成を行ってみます。

2. 自分でプロバイダーを作成し、イベントログを確認

プロバイダーでいくつかプロバイダーを紹介しましたが、その中でもTraceLoggingプロバイダーを使って実際にイベントを発行して確認してみます。

TraceLoggingは、Windows 10で導入されたETWの新しい拡張機能です。TraceLoggingプロバイダーはマニフェストを必要とせず、コード内で直接イベントの定義や変更ができるため、マニフェストベースプロバイダーと比べて簡単に作ることができ、柔軟に対応することができます。また、パフォーマンスも優れており高性能なロギングを行うことができます。TraceLoggingイベントには、各イベント内のイベント文字列が含まれているので、マニフェストベースと比較するとトレースファイルのサイズが大きくなります。

コード

全体像をわかりやすくするため、最低限の機能を持つプロバイダーコードを作成しました。
作成したプロバイダーのコードは以下になります。

#include <windows.h>
#include <winmeta.h>
#include <evntprov.h>
#include <TraceLoggingProvider.h>

// プロバイダーの定義
// プロバイダーのGUID : {EA345459-508F-435E-AD56-25EF8CB5FDC0}
TRACELOGGING_DEFINE_PROVIDER(g_LoggingProvider, "MyLoggingProvider", (0xea345459, 0x508f, 0x435e, 0xad, 0x56, 0x25, 0xef, 0x8c, 0xb5, 0xfd, 0xc0));

int main() {
	// プロバイダーを登録 
	ULONG result = TraceLoggingRegister(g_LoggingProvider);
	// イベントの発行
	TraceLoggingWrite(
		g_LoggingProvider,
		"MyEventName",
		TraceLoggingValue("ERROR!", "Message"),
		TraceLoggingKeyword(0x0002),
		TraceLoggingLevel(1),
		TraceLoggingOpcode(WINEVENT_OPCODE_REPLY),
		TraceLoggingEventTag(0x01));
    // プロバイダーの登録を解除
	TraceLoggingUnregister(g_LoggingProvider);
	return 0;
}

TraceLoggingでは、TRACELOGGING_DEFINE_PROVIDERマクロでプロバイダーを定義します。 TRACELOGGING_DEFINE_PROVIDERマクロの引数は以下の通りです。

プロバイダーを定義後、TraceLoggingRegisterマクロにプロバイダーのハンドル変数を渡すことでプロバイダーを登録します。同じハンドル変数を使って複数のプロバイダーを登録することはできません。
TraceLoggingRegisterマクロの中では、以下の処理が行われています。

1. EventRegisterを呼び出す。
2. EventRegisterが成功すると、TraceLoggingSetInformationを呼び出し、TraceLoggingサポート用のプロバイダーを構成する。

GUIDには固有の値を指定する必要があるため、VisualStudioのGUID作成ツールを使用して一意なGUID(EA345459-508F-435E-AD56-25EF8CB5FDC0)を生成し、プロバイダーを登録しました。
プロバイダーの登録状況はxperfで確認できます。

登録されたら、TraceLoggingWriteマクロでTraceLoggingイベントを生成します。 TraceLoggingWriteはWindows SDKに含まれるadvapi32.libに定義されています。

TraceLoggingWriteマクロの引数は以下の通りです。

任意の情報を追加で指定したい場合は__VA_ARGS__でパラメーターを追加します。今回はイベント構成マクロの内のいくつかとTraceLoggingValueを指定しました。TraceLoggingValueはトレースログラッパーマクロの一つになります。主なマクロについては以下に記載しています。ほかのパラメーターについてはトレースログラッパーマクロ ⧉を確認してください。

イベントを発行し終わった後は、TraceLoggingUnregisterマクロにhandleVariableを渡すことでプロバイダーの登録を解除します。

ログのトレース

上記のコードで自作したプロバイダーの動作を確認します。
今回はリアルタイムトレースではなく、etlファイルを出力し、内容の確認を行います。
以下の手順で、作成したプロバイダーからイベントを出力し、ログ取得を行うことができます。取得したデータの確認には、コントローラーとしてlogmanを、コンシューマーとしてtracerptを使用します。 まず、logmanを以下のコマンドで実行してETWセッションを開始します。

logman create trace [セッション名] -p [providerId または providerName] -o [ログファイル名] -ets

次に作成したプロバイダーアプリケーションを実行して開始されているセッションに対してイベントを発行し、以下のコマンドでセッションを停止させます。

logman stop trace_log -ets

最後にtracerptを以下のコマンドで使用することで、etlファイルを読み込み、人間の読める形式でXMLファイルを出力します。

tracerpt test.etl -o test.xml -lr

結果のXMLファイルを確認すると、System要素では作成したプロバイダーの名前とIDが確認でき、Level、Opcode、Keywordsが指定したものになっています。また、EventData要素では指定したメッセージが確認できます。以上で、任意のイベントの作成と取得が確認できました。

<Events>
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
	<System>
		<Provider Name="MyLoggingProvider" Guid="{ea345459-508f-435e-ad56-25ef8cb5fdc0}" />
		<EventID>0</EventID>
		<Version>0</Version>
		<Level>1</Level>
		<Task>0</Task>
		<Opcode>6</Opcode>
		<Keywords>0x2</Keywords>
		<TimeCreated SystemTime="2024-05-27T15:42:44.743613800+08:59" />
		<Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
		<Execution ProcessID="14672" ThreadID="9300" ProcessorID="1" KernelTime="0" UserTime="0" />
		<Channel />
		<Computer />
	</System>
	<EventData>
		<Data Name="Message">ERROR!</Data>
	</EventData>
	<RenderingInfo Culture="ja-JP">
		<Task>MyEventName</Task>
	</RenderingInfo>
</Event>
</Events>

ログ出力のパフォーマンス計測

TraceLoggingプロバイダーによるイベントの出力に成功したので、ほかのログ出力方法と実行時間のパフォーマンス比較を行います。

以下の方法を対象としました。

• コンソールに表示のみ(printf)
• テキストファイルへの出力(ofstream)
• Windowsイベントログ出力（ReportEventAPI）
• デバッガー出力(OutputDebugStringAPI)

計測結果

VisualStudioのパフォーマンスプロファイラーを使い、10万回ログを出力するのにかかる経過時間を計測しました。

それぞれ10回ずつ計測し平均秒数を算出した結果、以下のようになりました。

TraceLoggingプロバイダーがとびぬけて早く、次いでファイル出力、OutputDebugStringの順になっており、printfとEventLog出力は同程度のもので比較的遅いという結果になりました。 これにより、速度としては、比較したどのログ出力方法よりもパフォーマンスの面で優れているということがわかりました。

出力されたログを確認したところ、logmanでは受け取れていないイベントがあることがわかりました。しかし、実践時に使ったコードを動かして確認してみると、コールバック関数は試した回数分イベントを取得していました。また、パフォーマンス測定のために10万回イベントを出しましたが、実際の運用ではそこまで大量のイベントを一度に出すことはありませんので問題ありません。

まとめ

性能比較を行った結果、現状使用しているイベントログへの出力と比べても速度の差は明らかでした。 また、調べた中でETWはプロバイダーを有効化している間だけログを取得するということがわかりました。これにより、任意のタイミングでログを有効化することでログが肥大化しづらく、ピンポイントでログの収集を行うことができるため、ETWを使用すると解析がしやすくなり有用である言えます。

上記を踏まえて、パフォーマンスに問題なく運用中のシステムでログを取得して問題解析等に利用できることがわかりました。

この記事がログ出力方法の検討をしている方の助けとなれれば幸いです。

参考文献

• Ionescu, David A. Solomon （著）インサイドWindows第7版 下
• Pavel Yosifovich (著) Windows 10 System Programming,Part2
• マイクロソフト公式ドキュメント
  • Event Tracing for Windows (ETW) ⧉
  • TraceLogging ⧉