Jaa

NDIS のトレース

  • Artikkeli

こんにちは、さなえすです。暑くなってきましたが、皆さまいかがお過ごしですか？「梅雨（つゆ）」の語源は諸説あるようですが、梅の実が熟す時期の雨という意味もあるそうです。今年は私も梅シロップと梅酒を漬けてみました。これで夏を乗り切りつつ、暑さがおさまる頃には美味しい梅酒が飲めるといいなぁーと、楽しみにしております♪

 

先日、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

Operation Status: 0L

 

Logger Name: myndistrace

Logger Id: 0x14

Logger Thread Id: 00000FC8

Guid:                    a93839ad-98b3-11e0-b2a1-0003ff2b4d63

Buffer Size: 8 Kb

Maximum Buffers: 24

Minimum Buffers: 2

Number of Buffers: 22

Free Buffers: 22

Buffers Written: 1356

Events Lost: 410935

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

 

トレース ログ (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

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

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

Break instruction exception - code 80000003 (first chance)

Remote operation finished with NTSTATUS 0x00000000

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}

Break instruction exception - code 80000003 (first chance)

Remote operation finished with NTSTATUS 0x00000000

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,  CheckUnbind 1

[2049]0004.0528::06/29/2011-15:30:23.396  [mp]<==ndisReferenceNextUnprocessedOpenEx: Miniport FFFFFA80068A01A0, Open  FFFFFA800752B010

　　　　　：

　　　  省略

　　　　　：

 

 

 

いかがでしたでしょうか？

「XP では Checked Build 使えばデバッグできたのに～」などとお困りの開発者の方へ、少しでもお役に立てば幸いです。

ではでは、しばらくは暑い日が続きそうですが、みなさまお元気で！