Exception Monitor のログの分析
Geoff Gray
Microsoft Internet Server Support Engineer
Updated August 2000
日本語版編集注: この資料で解説しているダウンロード モジュール Exception Monitor の提供は終了しております。この資料をご利用いただくにあたって、現在この Exception Monitor を 入手いただけないことをご了承ください。最新情報については米国サイトの原文記事での確認をお勧めします。
https://msdn.microsoft.com/workshop/server/iis/readlogs.asp
概要: この記事では、Exception Monitor Log File Analyzer を使用して IIS の問題を診断する方法について説明します。また、一般的なデバッグの概念を述べ、ReadLogs 出力を見直す際のポイントも説明します。
目次
はじめに
背景
ReadLogs のインストールと実行
ログ分析のウォークスルー
メイン情報ウィンドウの使用
メイン出力ウィンドウの使用
スタック リストの表示
スレッドの移動
DLL の表示
エラーの表示
ロックについて
レポート機能の使用
クラッシュ前のアクティビティの表示
システム情報の表示
レポートおよび警告パラメータの構成
その他の機能の使用
Windows NT および Windows NT デバッガについて
プロセス、スレッド、およびその他の内部要素
メモリ
DLL について
メモリの操作
スタックの詳細
ヒープとスタックの破壊
Exception Monitor によって使用される CDB コマンド
より一般的な分析情報
デバッグ ファイルの作成
まとめ
はじめに
この記事では、Exception Monitor Log File Analyzer (ReadLogs.exe) を使用して Microsoft® Internet Information Server (IIS) の問題を診断する方法について説明します。また、一般的なデバッグの概念を述べ、ReadLogs 出力を見直す際のポイントも説明します。
Log File Analyzer を Exception Monitor と組み合わせて使用することによって、IIS のクラッシュやその他の問題の原因を特定することができます。Exception Monitor の詳細については、「Exception Monitor によるトラブルシューティング」を参照してください。
背景
Exception Monitor を実行すると、IIS サーバーの問題をトラブルシューティングするためのログが生成されます。 Log File Analyzer ツール (ReadLogs.exe) は、Exception Monitor ログをさらに分解して、分析を容易にします。ReadLogs では次のようなコンポーネントをすばやく表示して、IIS 問題の根底にある潜在的な原因を特定することができます。ReadLogs によって以下のことができます。
プロセスのどのスレッドが障害を引き起こしたかを調べる。
実行中のモジュールとそれらが障害発生時に行っていた処理の一覧を示す "障害スタック" を表示する。
(実行していたスレッドには関係なく) ロードされたすべてのモジュールの一覧を収集し、これらのモジュールに関して入手可能なバージョン情報を表示する。
シンボルに関するエラーまたは警告を探して表示する。
発生したが、アナライザをトリップするほど重大ではなかった例外エラーを探す。
その他の種類の例外に関する情報を探して表示する。
トラブルシューティング プロセス中に実行していたコマンドの出力をすばやく表示する。
さまざまな構成可能データ オプションを含んだ、例外に関するカスタマイズ可能なレポートを生成する。
この資料では、これらとその他の機能について詳しく説明します。
ReadLogs は分析を容易にしますが、このツールだけでは問題を診断できない場合もあります。ReadLogs も含め、Exception Monitor ツール スイートは、ユーザーに正しい方向を指し示すことを目的として設計されています。しかし、状況を完全に診断するには、追加のステップが必要な場合もあります。
注 ReadLogs バージョン 7 は以前のバージョンの Exception Monitor のログ ファイルも読み取れるように設計されていますが、以前のバージョンのログ ファイルのすべてが正しく解析されるわけではありません。Exception Monitor バージョン 6.1 で生成されたログ ファイルを開こうとすると、CPU 使用率が高くなり、 ReadLogs ダイアログ ボックスが表示されないことがあります。この場合は、タスク マネージャを使用して readlogs プロセスを終了した後、メモ帳でログ ファイルを開いてください。Microsoft はこの問題の救済策を開発中ですが、まだリリースされていません。
ReadLogs のインストールと実行
ReadLogs は、Exception Monitor をインストールすると自動的にインストールされます。このツールは Exception Monitor から直接実行するか、次のように [Exception Monitor] プログラム グループからスタンドアロンのアプリケーションとして実行することができます。
- [スタート] メニューの [プログラム] をポイントし、[Debugging Tools] をポイントし、[Exception Monitor] をポイントし、[ReadLogs] をクリックします。
注 ** ログを生成する方法や出力の解釈の詳細については、「Windows NT および Windows NT デバッガについて」を参照してください。
ログ分析のウォークスルー
初めて ReadLogs を起動すると、 Log File Analyzer メイン ウィンドウ (図 1) が表示されて、ログ ファイルのさまざまな面が示されます。
.gif "Log File Analyzer main window")
図 1. Log File Analyzer メイン ウィンドウ
メイン情報ウィンドウとメイン出力ウィンドウに、分析中のログに関する情報が表示されます。また、ウィンドウの左上隅には以下の情報が表示されます。
障害のタイプ (この例では、デバッガは手動トリップされました)。
ログの生成に使用された Exception Monitor のバージョン。
ログがカスタム コマンド セットを使用したか、標準コマンド セットを使用したか。
ログ ファイルの開始時刻と終了時刻。
メイン情報ウィンドウの使用
初めてログを解析するときや、プログラムの機能を選択すると、メイン情報ウィンドウにメッセージが挿入されます。メッセージにはデータが表示されたり (ほかのセクションで述べます)、ユーザーがとったアクションやそのアクションの結果の簡単な説明が表示されます。ReadLogs は、ユーザーがとったアクションとログの解析結果の両方に基づく動的メッセージングを使用します。動的メッセージの例をいくつか示します。
初めてログを解析するときには、ReadLogs は、ログが手動でトリップされたか、古いデバッガを使用していたかどうか、未解決のダイナミック リンク ライブラリ (DLL) 呼び出しがあったかどうかなどを調べます。この情報がメイン情報ウィンドウに自動的に表示されます。
メイン出力ウィンドウにスタックまたはモジュール情報が表示された後、その中の行をクリックすると、選択されたモジュールに関するバージョン情報がメイン情報ウィンドウに表示されます。
[Fault Stack] をクリックすると、障害スタックについてプロセッサのレジスタ ダンプと拡張スタック情報がメイン情報ウィンドウに表示されます。
メイン出力ウィンドウの使用
メイン出力ウィンドウのスタイルも、表示している情報に応じて変化します。該当する関数ヘルプ ページに、出力の例と説明が示されています。この動的出力の例をいくつか示します。
スタック リスト出力
ロードされた DLL のリスト
ロックとロックを所有しているスレッド ID のリスト
ログで検出されたエラー
スタック リストの表示
Log File Analyzer メイン ウィンドウの [Stack List] をクリックすると、スレッド スタック ウィンドウが表示されます (図 2)。
.gif "Thread Stacks window")
図 2. スレッド スタック ウィンドウ
スレッド スタック ウィンドウの情報は、自動デバッグの (あるいは、どんなデバッグでも) おそらく最も重要な部分を示しています。スレッド スタックは、クラッシュの時点で実行されていたコードを示します。このスレッド スタック情報は、どの DLL が実行されていたか、DLL 内のどの関数が実行されていたかを理解するのに役立ちます。最後の行の DLL と関数がその上の行の DLL と関数を呼び出し、それらがその上の行の DLL と関数を呼び出す、というように続いているので、スタックは下から順に読んでください。これらのスタックを読むときには、以下の点を考慮してください。
[Function] 列は、呼び出された DLL 名と DLL 内の関数名を示しています。DLL 名と関数名は感嘆符 (!) で区切られています。関数名の後にプラス記号 (+) と数字が付いている場合もあります。これは、インプリメントされていた実際のコードが関数の始まりから何バイト目かを示すオフセットです。
DLL および関数名に関する情報は、DLL のシンボル ファイルから抽出されます。シンボル ファイルを正しく読み取れない場合は、 Image@ という関数呼び出しの後にアドレスとオフセットが表示されます (図 2 を参照)。アドレスは、呼び出された DLL 内の関数呼び出しのメモリ位置を表します。ReadLogs はロードされた DLL のリストを検索して、そのメモリ位置がそれらの DLL の開始アドレスと終了アドレスの間にあるかどうかを調べることによって、[Name Resolution] 列で解決を試みます。上の図の例では、ReadLogs はこのアドレスを Taxcalc.dll で見つけました。
特定の DLL のシンボルがない場合には、[Function] 列にはメモリ アドレス (0x0230ffd0 など) とオフセットだけが表示されます。やはり、ReadLogs は、これの解決を試みて、[Name Resolution] 列に名前を表示します。このような DLL があった場合は、その DLL のシンボル ファイルを入手して、さらにデバッグすることを考慮してください。
デバッガはスタックの一番上のコマンドによって引き起こされた障害によってトリップされましたが、一番上の DLL に原因があるとは限りません。多くの場合、スタックの一番上には Microsoft® Windows NT® コア ファイル (Ntdll.dll など) が表示されます。通常、これは何かほかの関数が問題の原因となった不正なパラメータを渡したことを示しています。
左端の列のアドレスをクリックすると、DLL 出力からバージョン情報を得ることができます。同様に、スレッド スタック ウィンドウ内の DLL の ChildEBP アドレスを取得して、バージョン情報を表示することができます (入手可能な場合)。
デフォルトでは、新しいログを解析するときには、メイン出力ウィンドウに障害スタックが表示されます。ReadLogs はログ内のデバッグ コマンド プロンプトを読み取ることによって、障害の原因となったスレッド スタックを判断します。Exception Monitor は、トリップされたときには常に、自分自身をトリップを引き起こしたスレッドに設定します。また、 x:yyy> というように、トリップを引き起こしたスレッドを反映したプロンプトを表示します。x は、スレッドが実行中だったプロセッサの番号を示し、 yyy は、スレッドの番号を示します。
スレッドの移動
障害スレッドの周辺のほかのスレッドを表示したい場合があります。ReadLogs には、スレッドを移動するためのさまざまな手段が用意されています。たとえば、Log File Analyzer メイン ウィンドウの [Fault Stack] とそれに関連するコントロールを使用することができます (図 3 を参照)。
.gif "Fault Stack and its associated controls")
図 3. [Fault Stack] と関連コントロール
[Fault Stack] と関連コントロールを使用してスレッドを移動するには、次のようにします。
アナライザのコマンドに従って、[Fault Stack] をクリックすると、障害スレッド スタックに戻ります。
[<<] をクリックすると、前のスタックに移動します。
[>>] をクリックすると、次のスタックに移動します。
現在表示されているスタックの番号を示すエディット ボックスをクリックして、キーボードの上向き矢印キーと下向き矢印キーを使用すると、リスト内を移動することができます。
ドロップダウン リストから特定のスレッド スタックを選択すると、特定のスタックにジャンプします。
ほかのスレッドを調べると、CPU 使用率 100 パーセント問題のトラブルシューティングに役立つことがあります。CPU 使用率 100 パーセント問題とは、プロセッサが 100 パーセントで実行して、コンピュータの応答が非常に遅くなったり、応答しなくなったように見えることをいいます。クラッシュの時点で特定のスレッドが CPU サイクルのすべてを使用していたことがわかっている場合は、ドロップダウン リストからそのスレッドを選択して、その時点で何が行われていたか調べてください。クラッシュしたときにシステムが他に何をしていたか興味がある場合は、いくつかのスレッドを移動してみてください。
DLL の表示
Log File Analyzer メイン ウィンドウの [DLLs] をクリックすると、メイン出力ウィンドウに、現在ロードされているすべての DLL の一覧が表示されます。一覧は DLL の開始アドレスの順に表示されます。一覧には、DLL の開始アドレス (ベース アドレスともいいます)、終了アドレス、および名前 (パスも含む) が示されます。DLL が一覧に示されているということは、IIS の実行中に少なくとも一度は、そのファイルが呼び出されたことを意味します。Exception Monitor は !inetdbg.mod コマンドを使用して、ロードされた DLL の一覧を取得します。
[Hide Microsoft Files] チェック ボックスを選択した場合、ReadLogs は DLL のバージョン情報を調べて、Company Name フィールドの値が "Microsoft" に等しくない DLL、またはバージョン情報のない DLL だけを一覧表示します。障害発生時にロードされていたサードパーティ DLL をすばやく表示したいときには、このオプションを使用してください。
ログ ファイルには、すべての DLL のバージョン情報が含まれています (入手可能な場合)。DLL の開始アドレスをクリックすると、入手可能なバージョン情報がメイン情報ウィンドウに表示されます。Exception Monitor がバージョン情報を入手できない場合は、メイン情報ウィンドウに "no version information was available" というメッセージが表示されます。Exception Monitor は !inetdbg.ver コマンドを使用して、ロードされた DLL のバージョン情報を入手します。
エラーの表示
Log File Analyzer メイン ウィンドウの [Errors] をクリックすると、ログ内で検出されたすべてのエラーの一覧がメイン出力ウィンドウに表示されます。この一覧には、警告 (シンボルの不一致など)、エラー (ロードできなかったシンボルなど)、および NTSD エラーが含まれます。詳細については、「ロックについて」を参照してください。
注 Exception Monitor は、エラーをトラップするために明示的なコマンドは使用しません。代わりに、これらのエラーはログ全体に表示されます。
NTSD エラー
ログに "NTSD: Exception Number xxxxxxxx " という形式のエラーが含まれていることがあります。これらは、Windows NT、IIS、またはアプリケーション固有のエラー コードです。通常、これらのエラーはセッションをトリップするほど重大なエラーではありません。何かが失敗したが、サーバーはクラッシュしなかったことを示しています。これらのエラーが実際の問題を示唆している場合もありますが、ほとんどの場合は、サーバーが安定すれば解決されるマイナーな問題を示しているに過ぎません。
ReadLogs が NTSD エラーを検出したときには、その解決を試みて、対応する情報を表示します。ReadLogs は組み込みの Windows NT アプリケーション プログラミング インターフェイス (API) 呼び出しを使用して、これらのエラーを解決します。ReadLogs が 8 桁のエラー コードを Microsoft Win32® API の FormatMessage() 関数に渡すと、この関数が Windows NT 内部エラー リストでそのコードを検索します。コードが見つかると、エラーの解釈を返します。これらのエラーは、Winerror.h という名前の Windows C ヘッダー ファイルのコピーで表示することもできます。ReadLogs がエラーを解決できない場合は、通常、アプリケーション固有のエラー コード (IIS のこともあります) が発生したために、ReadLogs がエラー コードにアクセスできないことを示しています。
ロックについて
まず、ロックの定義と重要性について述べましょう。ロックは、スレッド (実行中のコードの一部) が排他的にコードにアクセスする必要があるときに発生します。スレッドがロックを要求し、可能な場合は、システムはスレッドにロックを与えます。この時点で、システム内のほかのスレッドは、ロックされたコードにアクセスできなくなります。これは、スレッドがファイルに情報を書き込むとき、ほかのスレッドがそのファイルに同時に書き込むことがないようにしたいときに便利です。書き込みを終了すると、スレッドはロックを解除します。これは常時行われていることであり、効率的に作成されているマルチスレッド アプリケーションの正常な一部です。注意しなければならないのは、特定のロックを所有できるのは一度に 1 つのスレッドだけですが、1 つのスレッドが複数のロックを所有することは可能だということです。
ここまでは問題ありません。問題になるのは、2 つ以上のスレッドがロックを所有していて、それぞれがもう一方のスレッドの作業終了を待っている場合です。この場合、テキサス州の実際の法律と似た問題が生じます。この法律では、2 台の列車が鉄道踏切で出会ったとき、2 台とも完全に停止して、どちらかが通過するまでは通過してはならないことになっています。このような状態を デッドロック といいます。
この状況は、セッションを手動でトリップしなければならない数少ない状況の 1 つです。デッドロックに陥ると、サーバーはハングしたように見えます。手動トリップすると、この問題の解決に必要な情報がダンプされます。手動トリップしたログがあり、問題がデッドロックであると思われる場合は、[Locks] をクリックすると、この情報が表示されます。ロック ウィンドウに何も表示されない場合は、適切なシンボルをロードしていないか ( !locks コマンドは Ntdll.dll のシンボルが正しくなければ機能しません)、デッドロックが問題の原因ではないということです。
[Locks] をクリックすると、ログ内で検出されたすべてのロックが、ロックの所有スレッドの ID とロック カウントとともにメイン出力ウィンドウに一覧表示されます。所有スレッド ID をクリックすると、ロックを所有しているスレッドのスタックがメイン情報ウィンドウに表示されます。この情報と下記のサンプル シナリオを使用して、デッドロック問題があるかどうかを判断できます。Exception Monitor は !locks コマンドを使用してロック情報を取得します。このシナリオのサンプル出力を以下に示します。
CritSec ftpsvc2!g_csServiceEntryLock+0 at 6833dd68
LockCount 0
RecursionCount 1
OwningThread a7
EntryCount 0
ContentionCount 0
*** Locked
CritSec isatq!AtqActiveContextList+a8 at 68629100
LockCount 2
RecursionCount 1
OwningThread a3
EntryCount 2
ContentionCount 2
*** Locked
CritSec +24e750 at 24e750
LockCount 6
RecursionCount 1
OwningThread a9
EntryCount 6
ContentionCount 6
*** Locked
上の例の 2 番目のロックを見てください。所有スレッドは、スレッド a3 です。 ~*kb コマンドの出力を見ると、出力の中からこのスレッドを見つけることができます。この例では、スレッド 4 です。
4 id: 97.a3 Suspend: 0 Teb 7ffd9000 Unfrozen
ChildEBP RetAddr Args to Child
014cfe64 77f6cc7b 00000460 00000000 00000000 ntdll!NtWaitForSingleObject+0xb
014cfed8 77f67456 0024e750 6833adb8 0024e750 ntdll!RtlpWaitForCriticalSection+0xaa
014cfee0 6833adb8 0024e750 80000000 01f21cb8 ntdll!RtlEnterCriticalSection+0x46
014cfef4 6833ad8f 01f21cb8 000a41f0 014cff20 ftpsvc2!DereferenceUserDataAndKill+0x24
014cff04 6833324a 01f21cb8 00000000 00000079 ftpsvc2!ProcessUserAsyncIoCompletion+0x2a
014cff20 68627260 01f21e0c 00000000 00000079 ftpsvc2!ProcessAtqCompletion+0x32
014cff40 686249a5 000a41f0 00000001 686290e8 isatq!I_TimeOutContext+0x87
014cff5c 68621ea7 00000000 00000001 0000001e isatq!AtqProcessTimeoutOfRequests_33+0x4f
014cff70 68621e66 68629148 000ad1b8 686230c0 isatq!I_AtqTimeOutWorker+0x30
014cff7c 686230c0 00000000 00000001 000c000a isatq!I_AtqTimeoutCompletion+0x38
014cffb8 77f04f2c 00000000 00000001 000c000a isatq!SchedulerThread_297+0x2f
00000001 000003e6 00000000 00000001 000c000a kernel32!BaseThreadStart+0x51
スレッドが見つかったら、それが WaitForCriticalSection 関数を呼び出していることがわかります。これは、このスレッドがロックを持っているだけでなく、ほかのスレッドによってロックされているオブジェクトを待っていることを意味します。 WaitForCriticalSection 呼び出しの最初のパラメータを見ると、そのオブジェクトをロックしているスレッドが何かわかります。この例では、24e750 を待っています。そこで、 !locks コマンドの出力に戻って、3 番目の Critical Section を見ます。
CritSec +24e750 at 24e750
LockCount 6
RecursionCount 1
OwningThread a9
EntryCount 6
ContentionCount 6
*** Locked
これで、スレッド 4 (2 番目のロックを所有している) が 3 番目のロックを待っていることがわかりました。これが解除されたら処理を続行できるので、ここまでは問題ありません。では、3 番目のロックを分析しましょう。このスレッドは a9 です。 ~*kb 出力を使用して探してみると、次のような部分が見つかります。
6 id: 97.a9 Suspend: 0 Teb 7ffd7000 Unfrozen
ChildEBP RetAddr Args to Child
0155fe38 77f6cc7b 00000414 00000000 00000000 ntdll!NtWaitForSingleObject+0xb
0155feac 77f67456 68629100 6862142e 68629100 ntdll!RtlpWaitForCriticalSection+0xaa
0155feb4 6862142e 68629100 0009f238 686222e1 ntdll!RtlEnterCriticalSection+0x46
0155fec0 686222e1 0009f25c 00000001 0009f238 isatq!ATQ_CONTEXT_LISTHEAD__RemoveFromList+0xb
0155fed0 68621412 0009f238 686213d1 0009f238 isatq!ATQ_CONTEXT__CleanupAndRelease+0x30
0155fed8 686213d1 0009f238 00000001 01f26bcc isatq!AtqpReuseOrFreeContext+0x3f
0155fee8 683331f7 0009f238 00000001 01f26bf0 isatq!AtqFreeContext+0x36
0155fefc 6833984b ffffffff 00000000 00000000 ftpsvc2!ASYNC_IO_CONNECTION__SetNewSocket+0x26
0155ff18 6833adcd 77f05154 01f26a58 00000000 ftpsvc2!USER_DATA__Cleanup+0x47
0155ff28 6833ad8f 01f26a58 000a3410 0155ff54 ftpsvc2!DereferenceUserDataAndKill+0x39
0155ff38 6833324a 01f26a58 00000000 00000040 ftpsvc2!ProcessUserAsyncIoCompletion+0x2a
0155ff54 686211eb 01f26bac 00000000 00000040 ftpsvc2!ProcessAtqCompletion+0x32
0155ff88 68622676 000a3464 00000000 000a3414 isatq!AtqpProcessContext+0xa7
0155ffb8 77f04f2c abcdef01 ffffffff 000ad1b0 isatq!AtqPoolThread+0x32
0155ffec 00000000 68622644 abcdef01 00000000 kernel32!BaseThreadStart+0x51
このスレッドもロックされた項目が解放されるのを待っていることがわかります。ここまでも問題ありません。では、どのロックを待っているのかを見てみましょう。先程と同じように、アドレスは WaitForCriticalSection() 関数の最初の引数として上記にリストされています。これをロック リストで探しましょう。
CritSec isatq!AtqActiveContextList+a8 at 68629100
LockCount 2
RecursionCount 1
OwningThread a3
EntryCount 2
ContentionCount 2
*** Locked
これにはロック番号 2 と示されています。これで問題がわかりました。ロック 2 はスレッド 4 によって所有され、スレッド 4 はロック 3 を待っています。ロック 3 はスレッド 6 によって所有され、スレッド 6 はロック 2 を待っています。これはデッドロックです。何が起きているのかを知るためには、スレッド 4 とスレッド 6 を分析して、これらのスレッドが何をしていたかを調べる必要があります。そうすれば、デッドロックのそもそもの原因を突き止めることができます。
レポート機能の使用
[Report] ボタンをクリックすると、ReadLogs はレポートを生成して、メイン出力ウィンドウに表示します。デフォルトでは、レポートの内容はクリップボードにもコピーされるので、ほかのアプリケーションに貼り付けることができます。レポートに含まれる情報をカスタマイズするには、「 レポートおよび警告パラメータの構成」を参照してください。
クラッシュ前のアクティビティの表示
Log File Analyzer メイン ウィンドウの [P.T.C.] (Prior To Crash: クラッシュ前) ボタンをクリックすると、ReadLogs はクラッシュ前のログの最後の 20 行を表示します。この機能を使用すると、IIS がクラッシュする直前に何が起きていたかがわかります。レジストリの以下のキーを設定することによって、表示行数を構成することができます。
HKEY_CURRENT_USER\Software\ReadLogs\READLOGS\Settings\LinesForPTC
システム情報の表示
Log File Analyzer メイン ウィンドウの [Sys Info] ボタンをクリックすると、[System Info] ダイアログ ボックスが表示されます(図 4 を参照)。
.gif "System Information dialog box")
図 4. [System Info] ダイアログ ボックス
このダイアログ ボックスには、各種のシステム設定とバージョンがツリー表示されます。この情報は、デバッグ中のマシンに関する情報を確認するのに役立ちます。
注 [System Info] ダイアログ ボックスは、Exception Monitor バージョン 6.1 以上で生成されたログでのみ使用可能です。Exception Monitor は !emdbg.sysinfo コマンドを使用して、この情報を取得します。emdbg デバッグ拡張は、Exception Monitor チームが作成した Exception Monitor のアドオンです。
レポートおよび警告パラメータの構成
Log File Analyzer メイン ウィンドウの [Config] ボタンをクリックすると、[ReadLogs Configuration] ダイアログ ボックスが表示されます (図 5 を参照)。
.gif "ReadLogs Configuration dialog box")
図 5. [ReadLogs Configuration] ダイアログ ボックス
このダイアログ ボックスで、ReadLogs が使用する設定をカスタマイズすることができます。左側のチェック ボックスは、レポート生成に関する設定です。右側のチェック ボックスは、特定のログについての警告の設定です。変更された設定は、次回に ReadLogs を起動したときに有効になります。
注 [Wizard] ボタンとその機能については、この資料では説明しません。
レポート パラメータ オプションには、以下のものがあります。
| レポート パラメータ | 説明 |
|---|---|
| Copy Report to Clipboard | レポートの内容をクリップボードにコピーします。 |
| Show Processed Stack Information | !inetdbg.ds -v esp コマンドからのレポート出力をレポートに追加します。これは基本的には拡張スタック ポインタ (Extended Stack Pointer: ESP) のダンプであり、障害スタックの詳細ダンプを提供します。ただし、このコマンドはスタックをスキャンして、DLL 内の値をダンプするだけなので、常に正確な情報が得られるわけではありません。情報には、コマンドが含まれていたり、前の呼び出しによって渡されたパラメータが含まれていることがあります。 |
| Show Version Information for the Selected DLLs | それぞれの DLL のバージョン情報をレポートに表示します。レポートに含まれる DLL は、このダイアログ ボックス内のほかの設定によって決まります。 |
| Show Microsoft DLLs in the Report | バージョン情報に "Microsoft" を含んでいる DLL をレポートに含めます。 |
| Show a List of Errors from the Log | ログのエラーをレポートに含めます。 |
| Show Non-Microsoft DLLs and Files with No Version Information | バージョン情報に "Microsoft" と記載されていない DLL と、バージョン情報がない DLL をレポートに含めます。 |
| Show Verbose Instructions and Explanation in the Report | レポートを読むための追加説明をレポート全体に表示します。 |
警告パラメータ オプションには、以下のものがあります。
| 警告パラメータ | 説明 |
|---|---|
| Show Warning Dialog on Manual Trip | ReadLogs がシステムの手動トリップを検出したときに警告を表示します。警告メッセージは、状態に関係なく、メイン情報ウィンドウに表示されます。 |
| Show Warning Dialog on "Not in Memory" | DLL がないメモリ内の位置に対して呼び出しが行われたことを ReadLogs が検出したときに警告を表示します。警告メッセージは、状態に関係なく、メイン情報ウィンドウに表示されます。 |
| Show Warning Dialog on a Bad Log File | ReadLogs が、ログ ファイルが古いデバッガによるものである、または情報を含んでいないと判断したときに警告を表示します。警告メッセージは、状態に関係なく、メイン情報ウィンドウに表示されます。 |
| Show Warning Dialog on a "Shut Down" | 分析中のプロセスのシャットダウン時にログが生成されたことを ReadLogs が検出したときに警告を表示します。現時点では、ReadLogs は "Suspend: -2" が設定されている実行中スレッドを探すことによって、プロセスのシャットダウンを検出します。これはシャットダウンを示す唯一の証拠ではありませんが、現時点では ReadLogs がシャットダウンを検出する唯一の手段です。 |
| Hide Locks with a Lock Count of 0 | Log File Analyzer メイン ウィンドウの [Locks] をクリックしたときに、カウントが 0 より大きいロックだけを表示します。 |
その他の機能の使用
Log File Analyzer メイン ウィンドウには、その他にも次のような機能を持つボタンがあります。
Notepad - ログ ファイルをメモ帳で開きます。
Help - Microsoft Web サイトにリンクして、この資料を開きます。
New - 新しいログ ファイルを開きます。
Windows NT および Windows NT デバッガについて
Exception Monitor は、Cdb.exe という名前の Windows NT デバッガに基づいています。Exception Monitor はユーザーレベル デバッガなので、ユーザーモード プロセスをデバッグすることはできますが、カーネルモード プロセスをデバッグすることはできません。CDB は、何らかの種類のアクセス違反を探すことによって機能します。アクセス違反が発生すると、Windows NT は、デバッガを起動し、デバッガがアタッチされているプロセスを停止するフラグをレイズします。プロセスが停止するので、システムはプロセスのメモリ領域全体を違反の時点での状態のままに保ちます。この機能により、CDB からコマンドを実行して、このメモリからログへ特定の情報をダンプすることができます。
.gif "CDB process")
これは、CDB がアタッチして、何らかの種類の障害の発生を監視しているプロセスです。障害が発生すると、CDB は NT へのパイプを切断して、プロセスを凍結するので、デバッグが可能になります。
図 6. CDB プロセス
プロセス、スレッド、およびその他の内部要素
この資料では、プロセス、スレッド、およびスタックについて言及しているので、これらのトピックについて簡単に説明しておいた方がよいでしょう。また、これらのトピックについての詳しい説明は、以下の書籍を参照してください。
Programming Applications for Window, Fourth Edition by Jeffrey Richter (Microsoft Press).
Inside Windows NT, Second Edition by David Solomon (Microsoft Press).
プロセス とは、基本的には "実行中のプログラムのインスタンス" です。スレッドとは、"プロセス内の実行経路" です。Windows NT の動作は、これらの単純な用語で説明することができます。プロセスが起動すると、タスク マネージャに表示されるプロセス リストが作成されます。このプロセスの内部には、アプリケーションを形成しているコードのすべてを実行する 1 つ以上のスレッドがあります。実際の処理を行い、メモリにアクセスし、プログラムの出力を生成するのは、これらのスレッドです。Windows NT はマルチタスキングかつマルチスレッドのオペレーティング システムです。したがって、同時に複数のアプリケーションを実行することができ、これらのアプリケーションのそれぞれが同時に複数のタスクを処理することができます。Windows NT は、CPU の時間をアクティブなスレッドのすべてに分割して、それぞれのスレッドに "タイム スライス" を与えることによって、これを達成しています。この事実を考えると、ある特定の時点で特定のプロセッサ上で実行するのは 1 つのスレッドだけであることが理解できると思います。タイム スライスは非常に短時間なので、複数のスレッドが同時に実行されているように見えますが、実際はそうではありません。このことがデバッグを容易にします。問題が発生した場合、現時点でアクティブなスレッドがそれを生成したことがわかるからです。これをさらに突き詰めていくと、"障害を起こした" スレッドが犯人とは限らないことがわかります。実際には別のスレッドの犠牲者かもしれないのです (「ヒープとスタックの破壊」を参照してください)。
この資料では Windows NT がスレッドの実行をどのように管理しているかについては述べませんが (詳細については、上記の書籍を参照してください)、別のスレッドやユーザーからの情報を待っているなど、さまざまな理由から、スレッドが自分の持ち時間の一部を自発的に放棄する場合があるということは理解できると思います。このような場合、スタックに次のような呼び出しが見られます。
WaitForSingleObject
WaitForMultipleObject
WaitForCriticalSection
Sleep
SleepEx
これらの呼び出しは、この呼び出しを行ったスレッドが自分の作業を続行する前に、一休みして、何らかのイベントが発生するのを待っているということを意味するに過ぎません。Windows NT は、処理を続行できるようになると、スレッドを "wake up" します (目覚めさせます)。
メモリ
このセクションでは、プロセスでのメモリの基本的な使用について述べます。ご存じのように、Windows NT では、それぞれのプロセスが 4GB の仮想アドレス可能メモリを取得しますが、そのうちの 2GB はシステム メモリです。システム メモリは共有されます (1 つしかないメモリをすべてのプロセスで共有します)。次の表は、Windows NT 4.0 でのユーザーモード プロセスのメモリ領域のマップを示しています。
注 このマップは、Windows NT Enterprise Edition には適用されません。Windows NT Enterprise では、3 GB のユーザー メモリと 1 GB のシステム メモリを取得することができます。
| 範囲 (16 進) | サイズ | 機能 |
|---|---|---|
| 0 ～ FFFF | 64 KB | 非アクセス領域 |
| 10000 ～ 7FFEFFFF | 2 GB ～ 192 KB | プライベート プロセス アドレス空間 |
| 7FFDE000 ～ 7FFFFFFF | 136 KB | Windows NT の各種の機能のための予約領域 |
| 80000000 ～ FFFFFFFF | 2 GB | システム メモリ |
仮想アドレス可能メモリ
すでに述べたように、Windows NT はそれぞれのプロセスに 4GB のメモリを割り当てます。しかし、Windows NT を実行しているシステムの実メモリが 64MB (またはそれ以下) しかないときには、どのようにしてこれが可能なのでしょうか。プロセスは 4GB の仮想アドレス空間を持ちますが、必ずしも 4GB すべてを使用するわけではありません。Windows NT がなぜこのようにしているのかを理解するために、プログラミングの基本概念を見てみましょう。
古い DOS プログラムでは、プログラムが実行するメモリ領域の量が頭痛の種でした。また、マシンのサイズに応じて、1 つのプログラムのさまざまな "バージョン" を作成しなければなりませんでした。その他にも、プログラムが拡張メモリや増設メモリを使用するかどうかという問題や、十分な増設メモリがあるかどうかといった問題がありました。Windows NT では 4GB の "仮想アドレス空間" を設定できるようになったため、すべてのプログラムが フラットなメモリ モデル で実行するようになりました。プログラムのコンパイル方法を気にする必要はなくなりました。呼び出しを仮想アドレスから物理アドレスに変換するのは、Windows NT に任せておけばよいのです。
ユーザーモード アプリケーションをデバッグするときには、変換を気にする必要はありません。デバッガはすべてのメモリをプログラムが見たとおりに、すなわち仮想アドレス空間で見たとおりに表示するからです。このことを念頭に置いて、Windows NT メモリのレイアウトの非常に単純な例を見てみましょう。
メモリ領域のレイアウト
Windows NT 上でプロセスが開始すると、システムはメモリ領域を構築して、この領域内にメモリをレイアウトします。Windows NT がメモリをレイアウトする方法はアプリケーションによって異なりますが、同じ一般原則がすべてのプロセスに適用されます。プロセスのメモリには 4 つの部分があります。
.gif "Memory space layout")
図 7. メモリ領域のレイアウト
メモリのデータ (緑色) 部分は、 アプリケーションによって使用されるデータまたは変数を含みます。プログラムが malloc などのコマンドを実行すると常に、Windows NT はヒープ内の領域をアプリケーションに与え、アプリケーションがこの領域を独自の目的に使用できるようにします。アプリケーションは、メモリから読み取り、メモリに書き込み、作業が終わるとヒープに返します (これをメモリの解放といいます)。詳細については、「仮想メモリとヒープ」を参照してください。
メモリのコード (青色) 部分は、アプリケーションの実際のコマンドと命令を含みます。Windows NT は、プログラムのロード時にこのメモリを割り当てます。プログラムの整合性を保護するために、Windows NT はこのメモリを読み取り/実行専用としてマークします。コードのロードとデバッグへの影響については、「DLL について」を参照してください。
メモリのスタック (黄色) 部分は、コードの実行経路の "ロードマップ" を含みます。プログラムは複数のコンポーネント (またはモジュール) から成り、これらのモジュールは複数の関数から成ります。関数は入力 (引数またはパラメータと呼ばれます) を受け取って、結果 (戻り値と呼ばれます) を返します。アプリケーションが自分の場所 (どの関数が何を呼び出したか) と渡された値を追跡できるように、プロセスはスタックという後入れ先出し (Last In, First Out: LIFO) リストを使用します。スタックとその読み方については、「スタックの詳細」を参照してください。
メモリの未使用 (灰色) 部分は、上の 3 つのカテゴリのいずれにも属しません。Windows NT は動的にメモリを使用するので、メモリのこの部分は、プロセスによるメモリの使用と解放につれて増減します。
仮想メモリとヒープ
Windows NT は、プログラムがデータを格納し使用できるようにするために、ヒープと仮想割り当てメモリという 2 種類の方法を使用しています (3 番目の方法であるメモリマップ ファイルは、この資料の範囲を超えています)。ヒープとは、Windows NT がアプリケーションのために確保して、ユーザーがアクセスできるようにしたメモリを指します。ヒープは通常、多数の小さなデータに使用されます。一方、仮想割り当てメモリは、プログラムが自分のために確保したメモリであり、通常、大きなデータを格納するために使用されます。この 2 種類のメモリ割り当てには、ほかにも次のような違いがあります。
仮想割り当てメモリはプロセス間で共有できるので、メモリをデータ共有の手段として使用することができます。ヒープ メモリは共有できません。
パフォーマンス モニタの "private bytes" カウンタは共有メモリを示さないので、現在使用中の実際のメモリ サイズを示さないことがあります。
Windows NT は 1MB のデフォルト ヒープを生成します。Windows NT はヒープのサイズを必要に応じて自動的に調整します。仮想割り当てメモリの増加はアプリケーションが行います。
プロセス メモリのレイアウトを表示するには、Windows NT リソース キットの PViewer.exe ユーティリティを使用して、詳細分析を入手してください。
DLL について
DLL は、現在の Windows のパワーとスピードの源泉です。DLL の使用の概念は、非常に単純です。ライブラリは、プログラムが使用する可能性があるルーチンのセットであり、通常、ライブラリは、いくつかのプログラムが使用する可能性がある共通のルーチンから成ります。使用する必要があるたびにルーチンを書き直すのではなく、ライブラリを作成して、それをプログラムに含めます。ライブラリのルーチンを使用するには、それがプログラムに "リンク" されていなければならず、これは通常、開発時に行われます。この方法の欠点は、すべてのプログラムにライブラリのコピーが必要なため、メモリとディスク領域を急速に消費することです。Windows は DLL を使用して、実行時に (アプリケーションが実行するときに) ライブラリをアプリケーションに "リンク" できるようにすることによって、この問題を解決します。多くの異なるアプリケーションが同じ DLL を共有できるので、Windows はさらに効率を高めることができます。5 つのアプリケーションが DLL を使用する場合でも、メモリにロードされる DLL のコピーは 1 つだけです。
DLL には、メモリに留まる必要がないという利点もあります。10 個の DLL があり、それぞれが一度しか使用されないとします。使い終わった DLL はアンロードできるので、より重要なほかのタスクにメモリを使用することができます。ただし、プログラムにとって重要な DLL は、ロードされた後、プログラムが実行されている間はメモリに残されるので、必要に応じて使用することができます。
デバッグ出力を見ていると、別の DLL との衝突による DLL の再配置に気付くことがあります。これは、Windows 環境では正常なことです。DLL の構築時に、Windows は実行時に優先的にロードするアドレスを割り当てます。しかし、ロードしようとしたときに、別の DLL がそのメモリを占めていた場合は衝突が起こるので、Windows NT はそれを別の位置に移動してからロードします。Windows NT は、この DLL に対する呼び出しのすべてをこの新しいメモリ位置に変換します。DLL の優先ロード アドレスを表示するには、DLL を右クリックして、[クイック ビューア] を選択します (Windows NT 4.0 でのみ使用可能)。DLL に関するヘッダー情報が表示されます。"Image Base" エントリが優先ロード アドレスを示しています。
メモリの操作
すでに述べたように、コード メモリは読み取り専用です。デバッガがプロセスにアタッチして、ブレークポイントの追加など、コードの変更を試みるときには、Windows NT はメモリを読み取り専用から書き込み時コピーに変更します。これによって、事実上、コードのコピーが作成され、デバッガはコピーを変更できるようになります。その場合、Windows NT は、プロセスの流れを新しいコードを指すように変更します。このようにして、Windows NT は、ほかのプロセスに影響を与えずに、共有コードの変更を可能にします。
スタックの詳細
注 このセクションでは、スタックに関する一般的な概念について述べます。スタックの詳細は、CPU プラットフォームのタイプ、プログラムの生成に使用されたコンパイラ、およびコードの作成方法によって異なります。
以下は、『Assembler Inside and Out』(McGraw Hill Press) からの抜粋です。
スタックは、情報を一時的に保持するためのものです。これは、プロシージャを扱うときに特に重要です。
中規模および大規模なプログラムのほとんどは、プロシージャと呼ばれる独立のモジュールに分かれています (高水準言語では、これらのモジュールは、しばしば関数またはサブルーチンと呼ばれます)。プロシージャが別のプロシージャを起動することを、最初のプロシージャが 2 番目のプロシージャを呼び出すと言います。2 番目のプロシージャが終了すると、プログラムは最初のプロシージャに戻ります。
呼び出し命令の実行の一部として、プロセッサは、2 番目のプロシージャが終了したときに実行を再開する最初のプロシージャ内の位置を保存しなければなりません。この位置をリターン アドレスといいます。
プロセッサは、リターン アドレスをスタックに入れることによって保存します。2 番目のプロシージャが戻ると、プロセッサはリターン アドレスをスタックから取り出して、その位置から実行を再開します。スタックは後入れ先出しで項目を取り出すので、プロシージャがほかのプロシージャを呼び出し、そのプロシージャがまた別のプロシージャを呼び出したとしても、すべてのプロシージャが正しい位置に戻ります。
スタックのもう 1 つの重要な用途は、プロシージャの開始時のレジスタの内容を保存することです。プロシージャが戻る前に、スタックから元の値を取り出すことによって、レジスタを復元することができます。このため、それぞれのプロシージャがレジスタを必要に応じて自由に使用することができます。しかし、それぞれの呼び出し側プロシージャから見ると、レジスタは元のままに見えます。
スタックは、プロシージャから別のプロシージャへ情報を渡すために使用することもできます。プロシージャはデータをスタックに入れて、2 番目のプロシージャを呼び出し、呼び出されたプロシージャがデータにアクセスします。必要な場合には、2 番目のプロシージャもスタックを使用して、最初のプロシージャにデータを渡すことができます。
スタックの最後の用途は、複雑な操作の間に発生する一時的な結果を保持することです。一時的な値は、(CPU 上の) 汎用レジスタに格納されることもありますし、スタックに入れられることもあります。どちらの方法を選ぶかは、特定のプログラムのロジックによって決まります。
スタックとマルチスレッド アプリケーション
前のメモリの図 (図 6) では、1 つのメモリ領域だけがスタックと関係があるように示されています。しかし、それぞれのスレッドが自分の履歴を認識している必要があるので、それぞれのスレッドが専用のスタックを持ち、それはプロセス内のほかのスレッドから完全に独立しています。
スタックは (上位メモリ アドレスから下位メモリ アドレスへと) 常に大きくなり続け、値を入れることによって大きくなります。次の値に割り当てられる位置は、ESP レジスタの値によって決まります。値が入れられると、プロセッサは自動的に ESP をデクリメントして、次の情報を入れる位置を指すようにします。
次のサンプルは、実行中のスレッドを示しています。3 つの関数があり、最初の関数が次の関数を呼び出し、それが 3 番目の関数を呼び出します。呼び出しのたびに、スタックにフレームを追加します。フレームは情報を格納して、プロセスのリターンと情報の受け渡しを可能にします。
.gif "Stack diagram")
図 8. スタック図
スタック フレームについて
図 8 は、 call または jnz ステートメントなどのジャンプを検出したときに、プログラム実行ラインがどのように変化するかを示しています。ジャンプは、実行を続行するためにコードの別のセクションに移動するので、プロセスが終了したときに戻ることができるように、この位置をスタックに保存する必要があります。スタックに保存するデータは、小さいかもしれないし、大きいかもしれません。サイズに関係なく、この時点で保存されるデータはすべて、フレームと呼ばれます。したがって、上の例では、実際に 2 つのフレームをスタックに追加しています。最初の関数が 2 番目の関数を呼び出すときに 1 つと、2 番目の関数が 3 番目の関数を呼び出すときに 1 つです。3 番目の関数が戻ると、2 番目の関数が復元され、スタック フレームを復元することによって実行を続行します。
スタック情報は、本質的に、プログラムが行うことの "ロードマップ" となります。Exception Monitor によって生成されたログを分析するとき、このロードマップを見て、障害発生時にアプリケーションが何をしていたかを知ることができます。スタック上のそれぞれのフレームは、最初に ReadLogs または障害スタックを起動したときの Readlogs のメイン出力ウィンドウに表示される行に対応します。
ヒープとスタックの破壊
まず、ヒープ破壊です。wh@@@@@@ I waMARY HAD A LITTLE LAMBn this subject を見てみましょう。
待ってください。もう一度やってみましょう。明らかに、上の文は壊れています。上のスペースをプログラムが使用するメモリと考えると、この文はプログラムに必要なデータ (またはコード) と考えることができます。プログラムがこの情報を使用するのは難しいだろうということがわかります。これが、ヒープ破壊の 1 つの形です。ヒープ は、プログラムが後で取り出す必要がある情報を格納するためのメモリ部分です。アプリケーションのスレッド 1 が何か (この例ではヒープ破壊) を論じることに決め、アプリケーションのスレッド 2 は歌を歌うことにしたと仮定しましょう。スレッド 1 は、モノローグを格納するためにヒープから若干のメモリを与えられ、このメモリにモノローグを書き込みました。
スレッド 2 にも若干のメモリが与えられましたが、スレッド 2 は歌うのに夢中で、そのメモリがどこにあったかを忘れてしまったので、適当なところから始めました。そして、スレッド 1 のモノローグに上書きしてしまいました。さて、スレッド 1 はモノローグを読み返してみようと思いましたが、できません。そこで、オペレーティング システムを呼び出して、「もうこれ以上我慢できません!!!」と言って死んでしまいます。これで、例外が発生します。あいにく、スレッド 2 は歌い終えて、カーテン コールに応え、週末を過ごすために家に帰ってしまったので、オペレーティング システムはスレッド 2 が例外の原因だとは思い付きません。
これは、あなたがヒープ破壊について聞いたことがある最も技術的な、あるいは最も正確な説明ではないでしょうが、大体の概念はおわかりいただけたと思います。基本的に、スレッドが自分が所有していないメモリに書き込むときには常に、別のスレッドが所有しているデータまたはコードに上書きする危険性を犯していることになります。最大の問題は、上書きされたメモリがしばらくの間使われないままかもしれないということです。そして、ついに呼び出されて、爆発したとき、それに上書きしたコードはすでに実行されていないかもしれず、そうすると、実際にメモリを破壊してクラッシュを引き起こしたのが何なのかわからなくなります。
同じことがスタック破壊についても言えますが、スタック破壊の場合は、スタック上のポインタ (メモリ アドレスともいいます) が間違った場所を指します。CPU は、このポインタを見て、「なるほど、ここへ行けば次に実行するコマンドが見つかるのだな」と思います。しかし、ポインタが空のメモリを指していたら？ ドカーン、爆発です。これは通常、コードがスタック内の次の関数へ正しくないポインタを渡したことによって起こります。スタック トレースを前にたどっていくと、リストにいくつかのスタック フレームがあります。このポインタは、実際に使用される前に何度か受け渡されたかもしれません。
これらは、スタックの一番上の関数が常に犯人だとは言えない 2 つの理由です。下から不正ポインタを受け取ったのかもしれないし (この場合、スタック上のほかの関数が問題の原因だということになります)、すでに破壊されていたメモリにアクセスしたときに問題に出会ったのかもしれません (この場合は、犯人は近くにいないかもしれません)。障害スタックに RtlCoalesceFreeBlocks などの呼び出しがあることから、ヒープ破壊を検出できるときもあります。また、strcat、strcpy、memcpy などの文字列操作関数を探してください。これらは、使い方を誤ると、頻繁にヒープ破壊を起こします。スタック破壊の兆候はさまざまであり、この資料の範囲を越えているので、ここでは詳しく述べません。
Exception Monitor によって使用される CDB コマンド
Exception Monitor が使用するコマンドの中には、デバッグの際に役立つものがいくつかあります。以下に、これらのコマンドとその出力を示します。
kv コマンド
Exception Monitor が最初に実行するコマンドは、kv です。このコマンドは、トリップの時点でアクティブであったスレッドの関数コールバック スタックを明らかにします。このスタックは、下から上へ読みます。すなわち、一番上の関数は、このスレッドで最後に呼び出された関数であり、一番下の関数は最初に呼び出された関数です。
サンプル出力 (x86 プラットフォーム):
ChildEBP RetAddr Args to Child
00f8fdf8 53d0f7f3 003070ac 00307078 00306d48 0x1000113c [Stdcall: 0]
00f8fe5c 53d0ad45 00306ee4 00f8ff0c 00f8ff4c w3svc!AddFilterResponseHeaders+0x26
00f8ff20 53d01ce6 00f8ff4c 00f8ff68 003154b0 w3svc!HTTP_REQUEST__DoDirList+0x2f7
00f8ff50 53d01f56 00f8ff68 00315478 00315460 w3svc!&127;ole32_NULL_THUNK_DATA+0x96e
00f8ff6c 53d04adb 00000166 00000000 00000001 w3svc!&127;ole32_NULL_THUNK_DATA+0xbde
00f8ff88 539895d0 00315460 00000166 00000000 w3svc!HTTP_REQ_BASE__`vftable'+0x1fd3
00f8ffb8 77f04f2c abcdef01 776a2254 00000028 infocomm!AtqPoolThread+0x1c8
00f8ffec 00000000 53989408 abcdef01 00000000 kernel32!BaseThreadStart+0x51
サンプル出力 (Alpha プラットフォーム):
Callee-SP Return-RA Call Site
0815ffc0 77e6f5b8 : ntdll!DbgBreakPoint+0x4
0815ffc0 77e6cc48 : KERNEL32!DebugBreak+0x8
0815ffd0 00000000 : KERNEL32!BaseThreadStart+0x60
関数コールバック スタックは、特定のスレッドでアクティブであったすべての関数をリストします。これは、関数 1 が関数 2 を呼び出し、関数 2 が関数 3 を呼び出し、というように続くことを意味します。最後に呼び出された関数が処理を終了すると、"巻き戻されます"。すなわち、その関数を呼び出した関数に戻ります。その関数も終了すると、それを呼び出した関数に戻ります。コールバック スタックは、どの関数が何を呼び出したかをリストして、コードが正常に実行したときに、どのように戻るかを示します。このスタックは障害スタックなので、スタックの最初にリストされている関数でアクセス違反が発生したことがわかります。しかし、必ずしも、この関数が実際の問題を引き起こしたとは限りません。スタック上の別の関数が不正ポインタを渡したことが問題の原因かもしれませんし、あるいはまったく別のスレッドが原因かもしれません。詳しくは、「ヒープとスタックの破壊」を参照してください。
スタックの最初のコマンドには呼び出し側コマンドがリストされていないことに注目してください。これは、このファイルのシンボルがロードされていないことを意味します。このスタックが ReadLogs にロードされるときには、ロードされたモジュールのリストを使用して、この関数呼び出しをフレンドリー名に解決する試みが行われます。まず、呼び出しが行われたメモリ アドレス (0x1000113c) を取得して、このメモリ位置を所有しているロード済み DLL を探します。
!inetdbg.mod
IIS デバッガが CDB に追加する拡張の 1 つが、Inetdbg.dll ファイル です。このファイルが Windows NT ディレクトリ (またはローカル デバッグ ディレクトリ) に存在する場合は、これらのコマンドを CDB から使用することができます。拡張コマンドの前に '!' 記号を付けると、CDB は DLL を探して、コマンドを拡張に渡します。この例では、Inetdbg 拡張を呼び出して、mod コマンドを渡します。このコマンドは、Inetinfo メモリ領域にロードされているすべてのモジュールのリストをダンプして、次のような情報を返します (このリストは省略されています)。
サンプル出力:
Start End Entry Path
01000000 01006000 01001122 C:\WINNT\System32\inetsrv\inetinfo.exe
77f60000 77fbc000 00000000 C:\WINNT\System32\ntdll.dll
78000000 78047000 7800546d C:\WINNT\system32\MSVCRT.dll
77f00000 77f5e000 77f01000 C:\WINNT\system32\KERNEL32.dll
77dc0000 77dfe000 77dc1000 C:\WINNT\system32\ADVAPI32.dll
77e70000 77ec1000 77e7a2a2 C:\WINNT\system32\USER32.dll
77ed0000 77efc000 00000000 C:\WINNT\system32\GDI32.dll
10000000 10024000 10001650 C:\InetPub\scripts\selfdestruct.dll
この情報は、Inetinfo のメモリ領域で実際にどんなコードが実行されているかを調べる上で役立ちます。上の kv コマンドの例では、未解決の関数がありました。これを解決するには、メモリ アドレス 0x1000113c に注目すると、これが Selfdestruct.dll の開始アドレスと終了アドレスの範囲内であることがわかります。
!inetdbg.ver
Inetdbg によって与えられたもう 1 つの拡張は、 ver コマンドです。これは、ロードされた DLL から抽出できるバージョン情報をリストします。ほとんどの DLL は、実際のファイルのヘッダー ブロックにバージョン情報があります。この拡張は、ここから情報の取得を試みます。
サンプル出力:
Module @ 0x01000000 = inetinfo.exe
dwFileFlags = 0x00000000 (FREE)
CompanyName = Microsoft Corporation
FileDescription = Internet Information Services Application v 1.0
FileVersion = 4.00
InternalName = INETINFO.EXE
LegalCopyright = Copyright (C) Microsoft Corp. 1981-1996
OriginalFilename = INETINFO.EXE
ProductName = Microsoft(R) Windows NT(TM) Operating System
ProductVersion = 4.00
Module @ 0x77f60000 = ntdll.dll
dwFileFlags = 0x00000000 (FREE)
CompanyName = Microsoft Corporation
FileDescription = NT Layer DLL
FileVersion = 4.00
InternalName = ntdll.dll
LegalCopyright = Copyright (C) Microsoft Corp. 1981-1996
OriginalFilename = ntdll.dll
ProductName = Microsoft(R) Windows NT(TM) Operating System
ProductVersion = 4.00
この例では、問題の DLL (Selfdestruct.dll) に関する情報がリストされないことに注目してください。Inetdbg.mod は、バージョン情報を取得できない DLL の情報は表示しません。ReadLogs は、ver コマンドからのそれぞれのエントリのファイル名とこれらのエントリを比較して、リストにある DLL のそれぞれに、取得できたバージョン情報を追加します。利用できるバージョン情報がない場合は、ReadLogs は "There is no version information available for this DLL" というメッセージだけを追加します。ReadLogs がバージョン情報の表示に使用するのは、このコマンドの出力です。この情報は、特定の DLL の適切なバージョンを実行しているかどうかを調べる際に非常に役立ちます。
注 Windows NT Service Pack (SP) 4 を実行している一部のマシンでは、 ver コマンドは完全には実行しません。コマンドを 2 回実行すると、適切なバージョン情報を入手できる場合があります。ReadLogs は、エラーを含んでいない出力のバージョンを探して、このセットを使用してバージョン情報を表示します。どちらのコピーも正常に実行できない場合は、ReadLogs はバージョン情報を表示できません。
~*kb
~*kb コマンドは、メモリ領域内のすべてのスレッドについて、(kv と同様の)スタックのコピーをダンプするようにデバッガに指示します (~ コマンドは "スレッドを選択" という意味であり、* コマンドは "すべてのスレッド" を意味します。その後に、すべてのスレッドに対して実行したいコマンド (この例では kb) を追加します)。 このコマンドを使用すると、クラッシュの時点でほかに何が起きていたかを調べることができます。この情報は、CPU 使用率 100 パーセント問題やデッドロックをトラブルシューティングする場合にも使用できます。それぞれのスタックが kv スタックと同じように分析されます。
この情報を CPU 使用率 100 パーセント問題のトラブルシューティングに利用するには、デバッガのほかにパフォーマンス モニタも実行して、スレッド カウンタをキャプチャします。CPU 使用率 100 パーセント問題が発生したら、デバッガを手動でトリップしてから、パフォーマンス モニタ ログを停止します。パフォーマンス モニタ ログを分析することによって、CPU を利用していたスレッドの番号がわかります。次に、ReadLogs を使用して (またはデバッグ ログ ファイルを手動で検査して)、 ~*kb コマンドでリストされたスレッドのうち、同じ番号のスレッドを探します。これで、そのスレッドが何をしていたかがわかり、犯人がわかります。
注 スレッドの出力をキャプチャするには、パフォーマンス モニタのロギング機能を使用する必要があり、また、使用率が 100 パーセントになるまで待ってからログを開始する必要があります。グラフ表示でスレッドを監視しているだけでは、スレッド番号を誤認するおそれがあります。
u eip-50 eip+20 (x86 プラットフォームのみ)
u コマンドは、指定されたアドレス範囲にあるアセンブリ コードを表示するようにデバッガに指示します。この例では、拡張命令ポインタ (EIP) レジスタが指すアドレスの 50 バイト前から EIP の 20 バイト後までのコードを表示するように指示しています。EIP レジスタは常に、次に実行されるコード行を指します。これを表示することによって、クラッシュの時点でどんなコードが実行しようとしていたかがわかります。
サンプル出力 (短縮されています):
ntdll!RtlpWaitForCriticalSection+0x45:
77f6cc16 0000 add [eax],al
77f6cc18 008b0d805afa add [ebx+0xfa5a800d],cl
77f6cc1e 7739 ja ntdll!RtlpWaitForCriticalSection+0x88 (77f6cc59)
77f6cc20 48 dec eax
77f6cc21 2475 and al,0x75
77f6cc23 2333 and esi,[ebx]
77f6cc25 c0894604894608 ror byte ptr [ecx+0x46890446],0x8
77f6cc2c 89460c mov [esi+0xc],eax
77f6cc2f 894610 mov [esi+0x10],eax
!locks
!locks コマンドは、現在実行中のコードのうち、クリティカル セクションとしてマークされているセクションに関する情報を表示します。クリティカル セクションについては、「ロックについて」を参照してください。
サンプル出力:
CritSec w3svc!MDIDMappingTable+100 at 68c2b1b0
LockCount 0
RecursionCount 1
OwningThread 156
EntryCount 0
ContentionCount 0
*** Locked
!inetdbg.atq -g
atq コマンドは、IIS 非同期スレッド キュー (Asynchronous Thread Queue) に関連する情報を表示します。このスレッド キューは、IIS に固有の機能です。新しい要求が IIS に着信すると、スレッドの処理が必要になります。スレッドの作成は、時間と CPU 使用率の点でコストがかかる操作なので、IIS は着信した要求をすぐに処理できるように、ワーカー スレッドのセットを保持しています。IIS は、このスレッドのプールを管理します。 atq コマンドは、プール内のスレッド数や、現在未使用の (すなわち使用可能な) スレッド数などの情報を表示します。このコマンドは、IIS 以外のアプリケーションをデバッグするときには効果がありません。
サンプル出力:
Atq Globals:
isatq!g_cConcurrency = 0 (0x 0)
isatq!g_cThreads = 9 (0x 9)
isatq!g_cAvailableThreads = 9 (0x 9)
isatq!g_cMaxThreads = 15 (0x f)
isatq!g_fUseAcceptEx = 1 (0x 1)
isatq!g_cbXmitBufferSize = 4096 (0x 1000)
isatq!g_cbMinKbSec = 1000 (0x 3e8)
isatq!g_cCPU = 1 (0x 1)
isatq!g_fShutdown = 0 (0x 0)
isatq!g_msThreadTimeout = 43200000 (0x 2932e00)
isatq!g_dwTimeoutCookie = 2 (0x 2)
isatq!g_cListenBacklog = 25 (0x 19)
isatq!AtqGlobalContextCount = 347 (0x 15b)
sizeof(ATQ_CONTEXT) = 212
!inetdbg.asp -g
asp コマンドは、IIS Active Server Pages (ASP) 処理に関連する情報を表示します。このコマンドは、セッション、アプリケーション、および要求情報を表示し、IIS 以外のアプリケーションをデバッグするときには効果がありません。
サンプル出力:
Asp Globals:
asp!g_nSessions = 0 (0x 0)
asp!g_nApplications = 2 (0x 2)
asp!g_nApplicationsRestarting = 0 (0x 0)
asp!g_nBrowserRequests = 0 (0x 0)
asp!g_nSessionCleanupRequests = 0 (0x 0)
asp!g_nApplnCleanupRequests = 0 (0x 0)
asp!g_fShutDownInProgress = 0 (0x 0)
!inetdbg.ds -v esp (x86 プラットフォームのみ)
ds コマンドは、現在のスレッドのスタックに関する情報を表示します。パラメータに -v esp を渡すと、ds コマンドは ESP で開始するスタックを表示し、呼び出された関数の名前だけを表示します。スタック フレームの他の情報は表示しません。このコマンドの出力は、スタックをかなり前までさかのぼって示すので、スレッドが何をしていたかという長い "ロードマップ" が得られます。
サンプル出力:
0a1a2ab0 : 7800fb30 : Image@78000000!wcscmp
0a1a2ab4 : 7800fa59 : Image@78000000!wcslen+0x19
0a1a2ac4 : 65345ed6 : oleaut32!VariantChangeTypeEx+0x586
0a1a2ad8 : 7800fab0 : Image@78000000!wcsncpy
0a1a2ae4 : 7800fab0 : Image@78000000!wcsncpy
0a1a2ae8 : 60502760 : MscsCore+0x2760
0a1a2b04 : 7800fab0 : Image@78000000!wcsncpy
0a1a2b10 : 77f67456 : ntdll!RtlEnterCriticalSection+0x46
0a1a2b14 : 0911b3a0 : Image@09110000+0xb3a0
0a1a2b18 : 091123d5 : Image@09110000+0x23d5
0a1a2b1c : 0911b3a0 : Image@09110000+0xb3a0
0a1a2b24 : 7800fb30 : Image@78000000!wcscmp
0a1a2b28 : 7800fa59 : Image@78000000!wcslen+0x19
0a1a2b2c : 09111256 : Image@09110000+0x1256
0a1a2b34 : 7800fa59 : Image@78000000!wcslen+0x19
0a1a2b3c : 091179d0 : Image@09110000+0x79d0
!inetdbg.ds
引数のない ds コマンドは、スタックの現在のトップに基づいて、スタックの生の出力を表示します。kv、kb、および ds -v コマンドと違って、これは (すべてのパラメータを示す) 正確なスタックとローカル ストレージのダンプです。読みにくく、書式化されていませんが、スタックの正確な内容を示します。
サンプル出力:
0a1a2aac : 0a1a2c85
0a1a2ab0 : 7800fb30 : Image@78000000!wcscmp
0a1a2ab4 : 7800fa59 : Image@78000000!wcslen+0x19
0a1a2ab8 : 0a1a2b3c
0a1a2abc : 80020005
0a1a2ac0 : 00000400
0a1a2ac4 : 65345ed6 : oleaut32!VariantChangeTypeEx+0x586
0a1a2ac8 : 0a1a2af8
0a1a2acc : 00000002
0a1a2ad0 : 37dc29f4
0a1a2ad4 : 00000000
0a1a2ad8 : 7800fab0 : Image@78000000!wcsncpy
0a1a2adc : 37dc29f4
0a1a2ae0 : 8002000b
0a1a2ae4 : 7800fab0 : Image@78000000!wcsncpy
0a1a2ae8 : 60502760 : MscsCore+0x2760
0a1a2aec : 00000000
0a1a2af0 : 00000008
0a1a2af4 : 11d045fd
0a1a2af8 : a0000000
0a1a2afc : 00000030
0a1a2b00 : 37dc29f0
dc esp-200 esp+200 および dc poi(eax)-200 poi(eax)+200 (x86 プラットフォームのみ)
dc コマンドは、渡された引数が指すメモリを表示します。表示は、生のメモリ (DWORD のグループとして表示されます) と、表示中のメモリ アドレスを示す最初の列、およびメモリ値に等しい ASCII 文字を示す最後の列から成ります。これによって、メモリに格納された文字列を見ることができます。このコマンドを何度も呼び出して、プロセッサのレジスタに基づいて値を渡します。これは一種の "ショットガン(手当たり次第の)" アプローチであり、実際に関連情報が表示される場合もありますし、表示されない場合もあります。上にリストされた最初のコマンドは、ESP レジスタが指しているメモリを表示するようにデバッガに指示しています。2 番目のコマンドは、 eax が指すメモリによって示されているメモリを表示するようにデバッガに指示しています (プログラマにとって、これはポインタのポインタです)。
サンプル出力:
02a7d97c 00000000 4e4c5153 28205445 294e534f ....SQLNET (OSN)
02a7d98c 00000000 33393931 00000000 00534e54 ....1993....TNS.
02a7d99c 716e736f 00006769 72746e65 00000a79 osnqig..entry...
02a7d9ac 00000000 00534e54 5754454e 004b524f ....TNS.NETWORK.
dc ra-40 ra+40 (Alpha プラットフォームのみ)
Alpha システムはレジスタが異なるので、アルファ システムのレジスタを反映するように、 dc コマンドに渡す引数を変更します。推論と分析は、上の段落の Intel プラットフォームでの dc とまったく同じです。
サンプル出力:
77e6f57c 23de01b0 6bfa8001 00000000 00000000 ...#...k........
77e6f58c 00000000 000000ab a0000030 a4000000 ........0.......
77e6f59c 480050c0 6bfa8001 00000000 00000000 .P.H...k........
77e6f5ac 00000000 23defff0 b75e0000 d3415619 .......#..^..VA.
77e6f5bc a75e0000 23de0010 6bfa8001 00000000 ..^....#...k....
77e6f5cc 00000000 243f77e6 23deffe0 a0012008 .....w?$...#. ..
77e6f5dc 47f00411 b53e0000 b75e0008 221e0018 ...G..>...^...."
77e6f5ec 6b404000 241f77e6 221e0010 a0002044 .@@k.w.$..."D ..
77e6f5fc 223e0018 ..>"
より一般的な分析情報
このセクションでは、ログ ファイルに示される可能性があるさまざまな出力について説明し、アプリケーションをデバッグして、アプリケーションを堅牢にするための方法について述べます。
IIS デバッガによって生成された生のログを見ると、アクセス違反の前に、ログに数行の情報があることに気付くかもしれません。これは、デバッガが常時、情報を取得して表示しているためです。以下に、この情報とその意味について説明します。
-----
NTSD ModLoad: 77720000 77731000 C:\WINNT\system32\mpr.dll
-----
LDR: Automatic DLL Relocation in inetinfo.exe
LDR: Dll scod32.dll base 10000000 relocated due to collision with
C:\Program Files\Common Files\System\ADO\msader15.dll
NTSD ModLoad: 04800000 0489f000 C:\WINNT\SYSTEM32\scod32.dll
-----
NTSD: C++ EH Exception
-----
NTSD: exception number c000008f
-----
上の例の最初の出力、NTSD ModLoad は、Inetinfo が特定のモジュール (または DLL) 内のコードに対する要求を受け取って、DLL をメモリにロードしていることを意味しているにすぎません。一部の DLL は、一度ロードされると、セッションの期間中、メモリに留まります。その他の DLL は、呼び出し側の処理が終了するとすぐに、アンロードされます。再び必要になると、DLL は再ロードされます。詳細については、Jeffrey Richter 著『 Programming Applications for Microsoft Windows, Fourth Edition 』(Microsoft Press) の第 19 章を参照してください。
上の出力の 2 番目のセットは、LDR から NTSD までです。LDR は、DLL の再配置が行われていることを示しています。2 行目に、その理由が示されています。この例では、すでにメモリ内にあった別の DLL との衝突がありました。3 行目の NTSD は、DLL が新しいアドレスに正常にロードされたことを示しています。一見、このステートメントのセットは恐ろしく見えるかもしれませんが、これは Windows の動作にとって不可欠なことです。
上の出力の 2 番目のセットで実際には何が起きているのか、詳しく見てみましょう。コンパイラが DLL を構築するとき、デフォルトのベース アドレスを割り当てます。可能な場合には、DLL はこのアドレスにロードされます。ここにロードすることによって、DLL 内の公開関数のすべての位置についての情報を変換する必要がなくなるので、呼び出しが高速になります。しかし、同じメモリ領域に別の DLL があると、衝突が起こります。ローダーは DLL をロードする別の場所を見つけて、DLL の関数を呼び出すために必要な変換を行います。
次に、NTSD C++ 例外があります。これはエラーですが、デバッガをトリップしなかったエラーです。C++ 例外は、"ファースト チャンス例外" と呼ばれています。これは、(日常的な表現で言うと) 例外が発生したときに、Windows NT がコードを所有している DLL に問題を自分で修正するチャンスを与えたことを意味します (プログラミング用語では "例外処理" といいます)。これは通常、C では try/except ラッパーを使用することによって、また C++ では try/catch ラッパーを使用することによって行われます。ラッパー (wrapper) とは、コードのセクションを "包んで (wrap して)"、そのセクションを隔離するコードです。try/catch ラッパーの場合、 try 部分のコードで例外が発生すると、問題を処理するために、catch/except コードが呼び出されます。問題を処理できた場合は、上記のエラーはシステムのクラッシュにはつながりません。
最後のエントリは C++ 例外に似ていますが、この例外はオペレーティング システムによって処理されています。例外の番号を意味のあるテキストに変換できる場合があります。ReadLogs は、取得した例外番号のすべてに対して自動的にこの変換を試みます。ReadLogs がどのようにこれを行うかについては、「エラーの表示」を参照してください。
正直なところ、今までの説明は、実際に起こっていることの表面をなでた過ぎません。Jeffrey Richter は、彼の著書『 Programming Applications for Microsoft Windows, Fourth Edition 』(Microsoft Press) の一節をこのトピックに割いています。
デバッグ ファイルの作成
このセクションでは、アプリケーションのデバッグ バージョンを構築する方法と、出力を強化する方法について述べます。どちらの説明も、Microsoft Visual C++®バージョン 5 および 6 に基づいていますが、その他の C コンパイラ、Java、および Visual Basic®でも同様の機能を使用することができます。
まず、デバッグしたいカスタム コードのデバッグ バージョンを構築しましょう。このためには、プロジェクトを Microsoft Developer Studio® にロードします。次に、以下の手順を実行します。
[ビルド] メニューの [アクティブな構成の設定] をクリックします。
ダイアログ ボックスからデバッグ構成を選択して、[OK] をクリックします。
[プロジェクト] メニューの [設定] をクリックして、[リンク] タブをクリックします。
[カテゴリ] ドロップダウン ボックスの [デバッグ] をクリックします。[デバッグ情報] セクションで、[両方のフォーマット] を選択します。
COFF (Common Object File Format) と Microsoft 情報の両方の PDB デバッグ ファイルが生成されます。CDB は COFF シンボル ファイルを使用するので、このステップによって CDB がシンボルを読み取れるようになります。
プロジェクトをリビルドします。次に、デバッグ ディレクトリから DLL および対応する PDB ファイルの両方を Web サーバー上の適切な場所にコピーします。
注 PDB は DLL と同じディレクトリにコピーする必要があります。これで、CDB が使用できるシンボルができました。
もっと楽しむために、出力文字列を追加することができます。デバッガがトリップする前にログにあった情報をすべて覚えていますか？ コードに手を加えて、情報を出力するようにすることもできます。たとえば、データベースに接続する DLL があり、本当に接続しているかどうか調べたいとします。DLL がデバッガに接続ステータスを書き込むようにしたり、変数の値をプリントアウトするようにできます。あるいは、本当にそうしたければ、「ハイ、ママ!!」と言わせることもできます。必要なのは、 OutputDebugString() という API を使用することだけです。この関数は、アタッチされたデバッガに文字列を書き出すようになっています。wsprintf() を使用して、目的のプログラムに関する情報を含んだ文字列を書式化し、その文字列を OutputDebugString に渡すことができます。そして、そのコードが実行されると、文字列がデバッグ ウィンドウに表示されます。デバッガがアタッチされていない場合は、Windows NT はコマンドを無視して、プログラムは通常どおりに実行します。
これが役に立ちそうな実世界での場面を見てみましょう。常に何らかの種類のスタック破壊を引き起こしているらしい DLL があるのですが、DLL 内のどの関数が問題の原因かわからないとします。すべての関数の始めと終わりに、"Entering < 関数名 >" と "Exiting < 関数名 >" というような OutputDebugString を入れれば、ログを見て、最後に呼び出された関数を調べることができます。この関数が犯人とは限りませんが、捜査の出発点にはなります。また、OutputDebugString を使用して、DLL 内の変数などを監視することもできます。
まとめ
Microsoft Technical Support は、Exception Monitor を使用して多くの問題を解決しています。ReadLogs とともに、 Exception Monitor は、サーバー上に発生した例外を診断するためのパワフルなツール スイートとなります。このツール セットですべての例外を解決できるわけではありませんが、サーバーのロギング メカニズムよりも多くの、障害の状態に関する情報を提供します。