こんにちは、さなえすです。暑くなってきましたが、皆さまいかがお過ごしですか？「梅雨（つゆ）」の語源は諸説あるようですが、梅の実が熟す時期の雨という意味もあるそうです。今年は私も梅シロップと梅酒を漬けてみました。これで夏を乗り切りつつ、暑さがおさまる頃には美味しい梅酒が飲めるといいなぁーと、楽しみにしております♪
先日、NDIS チームのブログで NDIS.sys の TMF (Trace Format) ファイルが公開されていました。実際の記事はこちら (→ ”TMF download page”) です。以前 K 里さんの投稿でも USB のイベントトレーシングについて書かれていましたが、NDIS.sys ドライバーも同様に ETW の機能を利用してトレースをとる事ができます。今日は TMF ファイルを使った NDIS の ETW トレース の出力・デコードの方法を皆さまにご紹介いたします。
※注意
なお、NDISチームのブログでも記載がありますが、”TMF download page” で公開されている TMF ファイルは、Windows 7 と Windows Server 2008 R2 においての以下のバージョンの NDIS のものです。全ての修正モジュールに対応しておりませんので、お使いの NDIS バージョンに該当しているかどうか、ご注意ください。
- RTM
- KB977927
- KB981765
- KB2471472
- KB2482122
- SP1
1．WDK に含まれる WMI トレース ツールや TMF ファイルを準備
◎トレース ツール
Tracefmt ：%BASEDIR%\tools\tracing\<Platform>\tracefmt.exe
Tracelog ：%BASEDIR%\tools\tracing\<Platform>\tracelog.exe
Traceview :%BASEDIR%\tools\tracing\<Platform>\traceview.exe
◎TMF ファイル
“TMF download page” から、TMF ファイル (ndistmf.zip) をローカル フォルダーへコピーし解凍
2. コマンド プロンプトを管理者権限で起動しトレースを開始
NDIS.sys のトレース プロバイダーと GUID は以下です。
”NDIS Tracing” {DD7A21E6-A651-46D4-B7C2-66543067B869}
以下の例では、-guid オプションへ、トレース プロバイダー (NDIS Tracing) の GUIDを直接指定しましたが、代わりにあらかじめ作成した GUID ファイルを指定することもできます。また、トレースレベルと、フラグについては ”TMF download page” のページに詳細がありますのでご参照ください。インストール時、スリープ復帰時など、トラブルシューティングしたいシナリオに合わせてトレースレベルやフラグを設定してください。
> tracelog -start <トレースセッションの任意の名前> -rt -guid <トレース プロバイダー> –flag <フラグ> -level <トレースレベル> -f <ログファイル名>
例：
C:\temp\ndistrace\tracetool>tracelog -start myndistrace -rt -guid #DD7A21E6-A651-46D4-B7C2-66543067B869 -flag 0x01FFFFFF -level 4 -f ndistrace.etl
Logger Started...
Enabling trace to logger 20
Enabling dd7a21e6-a651-46d4-b7c2-66543067b869 (Flags = 0x01ffffff Level = 4 ) t
o logger 20
Operation Status: 0L
Logger Name: myndistrace
Logger Id: 0x14
Logger Thread Id: 00000FC8
Guid: a93839ad-98b3-11e0-b2a1-0003ff2b4d63
Session Security: D:(A;;0x800;;;WD)(A;;0x120fff;;;SY)(A;;0x120fff;;;LS)(A;
;0x120fff;;;NS)(A;;0x120fff;;;BA)(A;;0xee5;;;LU)(A;;LC;;;MU)
Buffer Size: 8 Kb
Maximum Buffers: 24
Minimum Buffers: 2
Number of Buffers: 2
Free Buffers: 2
Buffers Written: 1
Events Lost: 0
Log Buffers Lost: 0
Real Time Buffers Lost: 0
AgeLimit: 0
Real Time Consumers: 0
ClockType: PerfCounter
Log Mode: Sequential
Real Time mode enabled
Maximum File Size: not set
Buffer Flush Timer: 1 secs
Log Filename: C:\temp\ndistrace\tracetool\ndistrace.etl
これでトレースが開始されました。
３．RealTime にログを表示する場合は、以下のコマンドを実行
この例の手順では、トレース レベル、フラグともに最大量が指定されていますので、ログが大量に出力されます。
> tracefmt -rt <トレースセッションの名前> -p <TMF ファイルへのパス> –display
C:\temp\ndistrace\tracetool>tracefmt -rt myndistrace -p C:\temp\ndistrace\tmf -display
Setting RealTime mode for myndistrace
Examining C:\temp\ndistrace\tracetool\default.tmf for message formats, none found, file not found
Searching for TMF files on path: C:\temp\ndistrace\tmf
[0]0BF8.0940::06/17/2011-18:12:51.853 [mp]==>ndisMQueueWorkItem: Miniport 84E5C0E0
[0]0BF8.0940::06/17/2011-18:12:51.853 [mp]<==ndisMQueueWorkItem: Miniport 84E5C0E0, Status 0
[0]0BF8.0940::06/17/2011-18:12:51.853 [mp]==>ndisMProcessDeferred Miniport 84E5C0E0
[0]0BF8.0940::06/17/2011-18:12:51.853 [mp]<==ndisMProcessDeferred Miniport 84E5C0E0
[0]0BF8.0BD8::06/17/2011-18:12:51.912 [mp]==>ndisMQueueWorkItem: Miniport 84E5C0E0
[0]0BF8.0BD8::06/17/2011-18:12:51.912 [mp]<==ndisMQueueWorkItem: Miniport 84E5C0E0, Status 0
[0]0BF8.0BD8::06/17/2011-18:12:51.912 [mp]==>ndisMProcessDeferred Miniport 84E5C0E0
[0]0BF8.0BD8::06/17/2011-18:12:51.912 [mp]<==ndisMProcessDeferred Miniport 84E5C0E0
[0]0C4C.0F48::06/17/2011-18:12:51.952 [mp]==>ndisMQueueWorkItem: Miniport 84E5C0E0
[0]0C4C.0F48::06/17/2011-18:12:51.952 [mp]<==ndisMQueueWorkItem: Miniport 84E5C0E0, Status 0
[0]0C4C.0F48::06/17/2011-18:12:51.952 [mp]==>ndisMProcessDeferred Miniport 84E5C0E0
[0]0C4C.0F48::06/17/2011-18:12:51.952 [mp]<==ndisMProcessDeferred Miniport 84E5C0E0
[0]0000.0000::06/17/2011-18:12:52.018 [mp]==>ndisMQueueWorkItem: Miniport 84E5C0E0
4. トレースを終了
調査対象の現象発生が確認できたら、トレースを終了します。
> tracelog -stop <トレースセッションの名前>
C:\temp\ndistrace\tracetool>tracelog -stop myndistrace
Number of Buffers: 22
Free Buffers: 22
Buffers Written: 1356
Events Lost: 410935
トレース ログ (ndistrace.etl) が作成できました。
５．採取した ETW トレースをデコード
手順4. で作成されたトレース ログをデコードします。ここでは 2 つ方法を紹介します。
> tracefmt <トレース ログファイル名>-p <TMF ファイルへのパス> –o <出力先のファイル名.txt>
C:\temp\ndistrace\tracetool>tracefmt ndistrace.etl -p C:\temp\ndistrace\tmf -o ndistrace.txt
Setting log file to: C:\temp\ndistrace\tracetool\ndistrace.etl
Logfile C:\temp\ndistrace\tracetool\ndistrace.etl:
OS version 6.1.7600 (Currently running on 6.1.7600)
Start Time 2011-06-17-18:12:51.814
End Time 2011-06-17-18:14:58.403
Timezone is @tzres.dll,-632 (Bias is -540mins)
BufferSize 8192 B
Maximum File Size 0 MB
Buffers Written 1356
Logger Mode Settings (0) Logfile Mode is not set
ProcessorCount 1
Processing completed Buffers: 1356, Events: 190361, EventsLost: 0 :: Format Errors: 0, Unknowns: 1
Event traces dumped to C:\temp\ndistrace\tracetool\ndistrace.txt
Event Summary dumped to C:\temp\ndistrace\tracetool\ndistrace.txt.sum
もしくは、Traceview.exe を使っても同様に ETWトレースをデコードできます。Traceview.exe を起動し、[File] → [Open Existing Log File] から、採取した ETW トレースと、TMF ファイルへのパスを指定すれば、上記同様にデコードが可能です。
６．おまけ
なお、Wmitrace.dll (デバッガーエクステンション) を使えば、カーネル デバッガーでも同様にトレース機能を使用することができます。ライブ デバッグ環境でもダンプ解析でも大丈夫です。デバッガーでの出力の方法の詳細については、同じく NDIS チームのブログの ”WPP and KD” で実際のやり方が紹介されていますのでそちらを参照いただければ幸いです。エクステンションに関しても、 MSDN ドキュメント、もしくは !wmitrace.help でヘルプが参照できます。
デバッガーでの出力例：
0: kd> .load wmitrace.dll
0: kd> !wmitrace.start ndis
Break instruction exception - code 80000003 (first chance)
Remote operation finished with NTSTATUS 0x00000000
0: kd> !wmitrace.enable ndis {DD7A21E6-A651-46D4-B7C2-66543067B869} -level 4 -flag 0x3033
1: kd> !wmitrace.searchpath F:\ndistrace\tmf
Trace Format search path is: 'F:\ndistrace\tmf'
---
1: kd> !wmitrace.disable ndis {DD7A21E6-A651-46D4-B7C2-66543067B869}
0: kd> !wmitrace.logdump ndis
(WmiTrace)LogDump for Logger Id 0x1a
Processing Global List: 4 Buffers
Total of 4 buffers found, now sorting entries
LOGGED MESSAGES (1303):
[2049]0004.0528::06/29/2011-15:30:23.395 [mp]==>ndisPnPDispatch: DeviceObject FFFFFA80068A0050, Irp FFFFFA800593C160
[2049]0004.0528::06/29/2011-15:30:23.395 [mp]ndisPnPDispatch: Miniport FFFFFA80068A01A0, MinorFunction: 7
[2049]0004.0528::06/29/2011-15:30:23.395 [mp]ndisPnPDispatch: Miniport FFFFFA80068A01A0, MinorFunction 0x7
[2049]0004.0528::06/29/2011-15:30:23.395 [mp]<==ndisPnPDispatch: Miniport FFFFFA80068A01A0, MinorFunction 7, Status c00000bb
[2049]0004.0528::06/29/2011-15:30:23.396 [mp]==>ndisPnPDispatch: DeviceObject FFFFFA80068A0050, Irp FFFFFA800593C160
[2049]0004.0528::06/29/2011-15:30:23.396 [mp]ndisPnPDispatch: Miniport FFFFFA80068A01A0, MinorFunction: 1
[2049]0004.0528::06/29/2011-15:30:23.396 [mp]==>ndisPnPQueryRemoveDevice: Miniport FFFFFA80068A01A0, UserModeOpenReferences 0
[2049]0004.0528::06/29/2011-15:30:23.396 [mp]==>ndisDevicePnPEventNotifyFiltersAndAllTransports: Miniport FFFFFA80068A01A0, NetEvent 2
[2049]0004.0528::06/29/2011-15:30:23.396 [mp]==>ndisIsMiniportStarted: Miniport FFFFFA80068A01A0
[2049]0004.0528::06/29/2011-15:30:23.396 [mp]<==ndisIsMiniportStarted: Miniport FFFFFA80068A01A0, Started 1
[2049]0004.0528::06/29/2011-15:30:23.396 [mp]==>NdisFNetPnPEvent: Miniport FFFFFA80068A01A0, Filter FFFFFA8006AE2010, NetEvent 2
[2049]0004.0528::06/29/2011-15:30:23.396 [mp]==>NdisFNetPnPEvent: Miniport FFFFFA80068A01A0, Filter FFFFFA8006AE3830, NetEvent 2
[2049]0004.0528::06/29/2011-15:30:23.396 [mp]==>ndisPnPNotifyAllTransports: Miniport FFFFFA80068A01A0, NetEvent 2
[2049]0004.0528::06/29/2011-15:30:23.396 [mp]==>ndisReferenceNextUnprocessedOpenEx: Miniport FFFFFA80068A01A0, CheckUnbind 1
[2049]0004.0528::06/29/2011-15:30:23.396 [mp]<==ndisReferenceNextUnprocessedOpenEx: Miniport FFFFFA80068A01A0, Open FFFFFA8007527010
[2049]0004.0528::06/29/2011-15:30:23.396 [mp]==>ndisPnPNotifyBinding: Open FFFFFA8007527010, NetEvent 2
[2049]0004.0528::06/29/2011-15:30:23.396 [mp]<==ndisPnPNotifyBinding: Open FFFFFA8007527010, NetEvent 2, Status 0
[2049]0004.0528::06/29/2011-15:30:23.396 [mp]<==ndisReferenceNextUnprocessedOpenEx: Miniport FFFFFA80068A01A0, Open FFFFFA800752B010
：
省略
いかがでしたでしょうか？
「XP では Checked Build 使えばデバッグできたのに～」などとお困りの開発者の方へ、少しでもお役に立てば幸いです。
ではでは、しばらくは暑い日が続きそうですが、みなさまお元気で！