ETW へのご招待
2008/07/14 追記： このサマリーについては、以下に Video 化しました
http://www.microsoft.com/japan/technet/community/events/dojo/online/self/11.mspx
こんにちは。
一昨日は、Visual Studio ラウンチイベントへのご参加、ありがとうございました。
いつものことで申し訳ありませんが、一昨日のデモでいくつかお見せできなかったもの (Service Trace Viewer のデモ、ETW との連携デモ、など) があり、またまた取りこぼしてしまいました。以下、先日のデモでお見せした内容も復習しつつ、新しく進化した ETW (= Event Tracing for Windows) と関連テクノロジーの概観をご説明します。
新しくなったETW
セミナーでご紹介したように、Vista, Windows Server 2008 では ETW が高度に改良されています。新しい ETW では、
Windows Server 2008 イベントログの活用
http://www.microsoft.com/japan/msdn/windows/windowsserver2008/tab/code/eventlog.aspx
でご紹介しているように、イベントマニフェストと呼ばれる XML ベースでのスキーマの管理と拡張が可能です。XML なので、例えば、自身で管理する項目を増やしたり、スタイルを使って独自のビューを提供したり、PowerShell を使って独自の集計処理をおこなうといったこともやりやすくなっています。また、この ETW では、セミナーでご説明したように WMI のトレースも統合されています。
WCF を使った ETW トレースを使ってその例を見てみましょう。
尚、手前ミソのビデオで恐縮ですが、以下の全体をご理解いただく準備として、まずは上記のビデオのデモを見て頂くことをお奨め致します。
ダウンロードサンプルの説明
WCF を使った ETW トレースの概要とサンプルについては、以下からリンクされている「ダウンロードサンプル」より入手してください。
http://msdn2.microsoft.com/ja-jp/library/ms751538.aspx
このサンプル一式の中に、「ETWTracing」というプロジェクトがありますが、これが該当のサンプルです。
このサンプルで実施している内容について簡単に記載します。
まず、このサンプルでは前述の通り WMI のトレースを使っています。ETW や WMIのトレースでは、プロバイダ (Provider) という大切な概念があります。プロバイダーはトレースそのものを提供する論理オブジェクトです。プロバイダをわけることによって、そのトレース固有に異なるデータなどを扱うことができます。
上記のサンプルで RegisterProvoder.bat を実行することで、mofcomp (mofコンパイラ) のコマンドが実行され、サンプルでは「XmlStringProvider」という名前のトレースプロバイダが専用のデータベースに登録されます。以下のコマンドを使うと、この WMI のプロバイダを含む ETW のすべてのプロバイダが一覧表示されますので確認してみましょう。
logman quey providers
[出力結果]
....(中略)
XmlStringProvider {411A0819-C24B-428C-83E2-26B41091702E}
....(中略)
さて、トレースに際しては、トレースリスナーというオブジェクトが上記のプロバイダにトレースの出力 (Write) を要求しています。上記のサンプルプロジェクトをコンパイルすると、TraceListner クラスを継承してカスタムで構築されているトレースリスナー(ETWTraceLister クラス)がコンパイルされます。上記のサンプルコードのカスタムのリスナークラス(ETWTraceListner.cs)の中のサンプル内で、
provider = new EtwTraceProvider(ProviderGuid);
というコードがありますが、この行でプロバイダを作成し(ProviderGuid 変数には上記で登録したプロバイダの GUID が入っています)、provider.Trace と記載されているコードの箇所でETWトレースを出力しています。
そして、セミナーでご説明したように、web.config に以下の通り指定をすることで、アプリケーションではこのトレースリスナーを使用するようになります。
<system.diagnostics>
<sources>
<source name="System.ServiceModel" switchValue="Information, ActivityTracing"
propagateActivity="true">
<listeners>
<add name="ETW" />
</listeners>
</source>
</sources>
<sharedListeners>
<add type="Microsoft.ServiceModel.Samples.EtwTraceListener, ETWTraceListener"
name="ETW" traceOutputOptions="Timestamp" />
</sharedListeners>
<trace autoflush="true" />
</system.diagnostics>
セミナーでお伝えしたように、sharedListners の add で上記のカスタムリスナーを ETW という名前で定義し、listners の add でこのリスナーを使うように指定しています。ですから、例えば、カスタムリスナーのクラスをコンパイルした dll を WCF とは別に構築しておけば、必要になった際に bin フォルダ (IIS では bin の下の dll にパスが通っています) に配置して web.config を書き換えることで、再コンパイルすることなくトレースをおこなう仕組みを自由に組み込むこともできます。
リスナー (Trace Listner) とソース (Trace Source) についてはこの後でもう少しちゃんと触れましょう。
さて、イベントを収集するには、例えば、logman コマンドを使います。デモでお見せしたように、例えば以下のコマンドを実行してみます。
logman create trace MyTrace -pf mytrace.dat -o c:\tmp\MyTrace.etl
logman start MyTrace
尚、mytrace.dat には、以下のように記載しておきます。
{DD5EF90A-6398-47A4-AD34-4DCECDEF795F} 0x00000000 0 Microsoft-Windows-HttpService
{411A0819-C24B-428C-83E2-26B41091702E} 0x00000000 0 XmlStringProvider
これで、HTTP Services と上記の WCF (プロバイダは XmlStringProvider) の双方のトレースが MyTrace.etl というバイナリファイルとして保存されます。これをあとは、tracerpt コマンドで XML などに変換し、PowerShell のコマンドを使って分析するといったことが可能になるのです。
ログの操作をつかさどるコントローラ
先ほど logman コマンドというものを使用しましたが、ETW にはコントローラ (controller) というもう１つの概念上のオブジェクトがあります。イベントを処理する場合には、発生したイベントをキャプチャして所定のログファイルなどに出力する必要がありますが、こうした動きをつかさどるオブジェクトになります。
つまり、コントローラを何も指定しないと、いくらログを出力してもいかなる処理もおこなわれません。コントローラを複数設定してログ出力をおこなうように設定しておくと、ETW に通知されたトレースの情報は、(該当のプロバイダから通知されたトレースのみ)すべてのコントローラに対して通知され、ファイルなどの形でログに出力されます。
上述の logman.exe はこのコントローラの１つですが、Windows 標準のイベントビューア(eventvwr.exe)で処理する際もやはりその裏でまたコントローラが存在しています。そして、そのコントローラにイベントの情報の登録などをおこなう必要があります。この登録や有効化/無効化等の制御をおこなうコマンドが、上述の「Windows Server 2008 イベントログの活用」のビデオでご紹介している wevtutil.exe コマンドです。
また、logman.exe 同様の処理を UI からおこなうこともできるようになっています。「信頼性とパフォーマンスモニタ」(perfmon.exe) の [データコレクタセット] - [イベントとレースセッション] で、カスタムのコレクタを作成してみてください。logman.exe 同様、トレースセッションの名前を付けて、どのプロバイダからデータを収集するか指定することができます。例えば、この中で、ASP.NET Event と上述 XmlStringProvider (サンプルのプロバイダ) を指定すると、双方のトレースを .etl ファイルに出力できます。(ASP.NET Event のトレースでは、[編集] ボタンを押してプロパティをすべて設定しておきましょう。)
logman コマンドに代表されるように、コントローラは、ETW に登録されているプロバイダの一覧を検索したり、そのログ出力を要求したりと、さまざまな管理をおこなうことができます。コントローラは、その名の通り、ETW に通知されたトレースをコントロールする役目を担っています。
上記の logman start コマンドで開始したトレース出力のセッションのことを「イベントトレースセッション」(Event Trace Session) と呼びます。イベントビューアでこのセッションを開始にするには、イベントビューア (eventvwr.exe) の UI 上から [ログを有効にする] をチェックするか、wevtutil.exe コマンドを使って開始することができます。
この辺りの概念をより深く知りたい方は、以下が役に立ちます。
ETW によりデバッグおよびパフォーマンス調整を改善する
http://msdn.microsoft.com/msdnmag/issues/07/04/ETW/default.aspx?loc=jp
尚、先ほど ETW と WMI が統合されていると記載しましたが、上述の通り、WMI ログファイルを使用せずに専用の .etl の形式でイベントをキャプチャすることができます。イベントビューアもコントローラが使用されていますので、内部的には logman.exe と同じ .etl のバイナリ情報を扱っています。ですので、上述で出力した .etl ファイルをイベントビューアで表示することもできます。(イベントビューア上のツリーを右クリックして、[保存されたログを開く] を選んで .etl ファイルを開けば、内容を表示できます。)
svctraceviewer
さて、上記サンプルで収集したトレースをさまざまなコントローラとコンシューマを使って見て頂くとわかりますが、実はWCF トレースの主要な情報は残念ながら 1 つのデータの中にすべて埋まってしまっていますので、tracerpt で csv などに変換してもあまりきれいに表示させることはできません。この WCF 固有のトレースデータをきれいに表示できるのが svctraceviewer.exe です。
このツールを使うと、.etl ファイルそのものや、XmlWriterTraceListner という XML テキスト出力用のリスナーを使って出力したログも含め、WCF のトレースデータの内容を UI 上でビジュアルに表示できます。
例えば、現実の開発では複数の WCF サービスを呼び出して使用することが多いでしょう。こうした場合でも SvcTraceViewer 上で [File] - [Add ...] メニューを使って複数のサービスから出力された情報を重ねて見ていくことができるようになっています。
また、上記で記載した .config のように switchValue 属性として ActivityTracing を指定しておくと、コンポーネント間での転送関係をグラフで表示することもできます。(カンマ (,) で区切って複数の switchValue を指定可能です。switchValue で指定できる値については、以下が参考になります。)
Windows Communication Foundation : トレースの構成
http://msdn2.microsoft.com/ja-jp/library/ms733025.aspx
ユーザコードのログとトレース
以上ご説明してきましたが、トレースリスナーに出力を要求している実体はどこにあるのでしょうか。１つの方法としては、System.Diagnostics.Trace オブジェクトというものを使ってここにリスナーを登録するという方法もありますが、トレースソース (Trace Source) というオブジェクトを使用することができます。
上述の .config では、<source name="System.ServiceModel" ... と指定しています。ここで、"System.ServiceModel" という名前のトレースソースを指定しています。このように .config に記述しておくと、この名前のトレースソースが出力したトレースが、そこと関連しているリスナーに渡されて処理されるというモデルです。つまり WCF のトレースでは、この名前のトレースソースのクラスが内部で使用されています。(主に System.ServiceModel.Diagnostics のクラスが担当しています。) ですから、ユーザコードの中でもこのトレースソースをそのまま使うことで、皆さんが作成したユーザコードでここにトレース出力をさせることができます。
しかし、WCF と皆さんが作成したコードという、性質の異なる 2 つのアプリケーションコンポーネントで同じトレースソースを使うというのはモデル上きれいではありません。もしかしたら、皆さんが開発するコードでは、独自のデータをイベントスキーマに含めて後で集計処理などをかけたくなるかもしれません。switchValue も独自のものが必要になる可能性があります。また逆に、同じトレースソースで出力すると、皆さんの開発コードの中で WCF でしか使わない余計なデータも考えてトレース出力する必要が生じるかもしれません。
こうした場合、トレースソースについても、リスナー同様、カスタムに構築することができます。
無論、ASP.NET の開発など、組み込みの Trace オブジェクトなどをバンバン使って頂いて構いません。汎用性のある製品開発ように、非常に高いモジュール性や完結性が要求とされるようなものの場合はこのようにカスタムトレースソースを作って組めるということです。
カスタムのトレースソースを使えば、開発者の皆さんが構築するコードについてもロジックの再ビルドをすることなくさまざまなレベルでトレースを .config に (実行中に) 設定することができるわけです。この簡単なサンプルについては、WCF を使ったサンプルではありませんが、以下が参考になるでしょう。(サンプルコードも付属していますので是非参考にしてみてください。)
CLR Inside out (Extending System.Diagnostics)
http://msdn.microsoft.com/msdnmag/issues/06/04/CLRInsideOut/default.aspx
「ログ」という観点では、エラーログのように、アプリケーション側で発生した例外 (Exception) を統一的に (どこか一箇所で) キャプチャしたいという場合があるでしょう。その場合には、以前このブログで投稿した以下の方式と組み合わせることも可能です。(このサンプルでは、カスタムリスナーやカスタムソースは使わず、そのままイベントビューアに渡すサンプルになっています。)
[IT Pro 道場補足] WCF サービスからイベントログ (Event Log) を出力する
http://blogs.msdn.com/tsmatsuz/archive/2007/11/21/it-pro-wcf-event-log.aspx
[IT Pro 道場補足] WorkflowServiceHost からイベントログ (Event Log) を出力する
http://blogs.msdn.com/tsmatsuz/archive/2007/11/21/it-pro-workflowservicehost-event-log.aspx
あとは、.config の上で、どのソース (System.ServiceModel, System.ServiceModel.MessageLogging, System.ServiceModel.Activation, ユーザのカスタムソース, etc) をどのスイッチで、どのリスナーを使ってトレースするかを列挙して記述するだけです。実行中の都合（例：障害発生により特定の情報を追跡したい、など）でこの構成を変えることもできます。
特にリスナーの出力先を ETW とし、新しいイベントマニフェストを使った方式(上述の「Windows Server 2008 イベントログの活用」のビデオを参考にしてください)で ETW のプロバイダーを登録しておけば、以前このブログでもご紹介したように Windows Server 2008 のサブスクリプションの機能 (下記) を使って複数のマシンで発生したイベントを 1 台のマシンで集約管理したり、イベントタスクを登録してイベント発生時のメール送信やバッチ実行を仕掛けたりといったことが容易になります。
[IT Pro 道場補足] そして、Windows Server 2008 イベンティングシステム
http://blogs.msdn.com/tsmatsuz/archive/2007/11/21/it-pro-windows-server-2008.aspx
周辺技術をみてみましょう
ご存知の方も多いかと思いますが、IIS7 の管理ツールを使うと、ASP.NET やマネージモジュールなどのトレースを上記同様の XML 形式で出力され、これらを串刺しにしてスタイルを使って美しくトレース情報をビューイングすることができるようになっています。
How to Capture ASP.NET Page Trace Events in IIS7 Tracing
http://www.iis.net/articles/view.aspx/IIS7/Hosting-Web-Applications/ASP-NET/How-to-Capture-ASP-NET-Page-Trace-Events-in-IIS7-T?Page=1
How to Add Tracing to IIS7 Managed Modules
http://www.iis.net/articles/view.aspx/IIS7/Extending-IIS7/Developing-a-Module-using--NET/How-to-Add-Tracing-to-IIS7-Managed-Modules?Page=1
ここでも上述の ETW が大活躍しているわけです。IIS 7 のこの仕組みでも基本的仕組みは同じですので、上記を理解しておくといろいろと動きが理解でき応用 (例： IIS 7 ではなく logman を使ってコマンドで設定する、など) できることでしょう。
IIS7でちょっと違う点は、web.config に上述の方法でリスナーを設定するのではなく、IIS 7 の大元のコンフィグ (%SystemDrive%\Windows\system32\inetsrv\config\applicationHost.config) で一括で構成しているという点です。この applicationHost.config の <traceProviderDefinitions> の中をみてみてください。やはり ETW のプロバイダに名前をつけて設定しているのがわかります。(試しに logman query providers コマンドで同じ Guid のプロバイダーを検索してみてください。) IIS7 では、独自のコントローラ (logman の IIS7 版だと思ってください) とコンシューマ (.etl から .xml への変換プログラム) を使って、このプロバイダーからやはり ETW の仕組みでトレースログを出力していると考えれば理解しやすいでしょう。
日本の市場では著名な運用管理ツールが数多く提供されています。今後 この統一的な ETW という仕組みに、こうした優れた製品群と連携するカスタムのコントローラやリスナーなどを組み合わせた仕組みが出てくると、さらに機能性の優れた運用追跡の仕組みをこうした市販ツールなどと統合していくことが可能になるかもしれません。
