Time Travel Debugging (Preview) の Lab
ユーザーモードのプログラムで、クラッシュダンプでは原因がわからない問題を、問題が発生するまでの経緯をさかのぼって調べたいと思ったことはありませんか?それを実現してくれるのがTime Travel Debugging (TTD) です。TTD は、まだプレビューですが、WDK 1803 で TTD の使い方についてのLab が以下のドキュメントとして公開されました。
Time Travel Debugging - Sample App Walkthrough
< https://docs.microsoft.com/en-us/windows-hardware/drivers/debugger/time-travel-debugging-walkthrough >
そこで、今回は、このLab の手順をご案内します。これにより、読者の方のデバッグの作業効率が上がれば幸いです。
※ ただし、あくまでもプレビューですので、今後上記ドキュメントの内容は更新される可能性がある点にご注意ください。
※ メモリダンプがスナップショットであるのに対し、TTD で取得できるトレースログはその連続となるため、必要なメモリやディスクの容量が多くなります。そのため、再現手順が確立していない問題や再現までに時間がかかる問題に対してなど、長期間にわたる実行には向かない点にもご注意ください。
手順の概要
-
- 失敗するプログラムのTime Travel Trace をキャプチャします。
-
- dx (Display Debugger Object Model Expression) コマンドを使って、Time Travel Trace に記録された例外イベントを見つけます。
-
- !tt (time travel) コマンドを使って、そのトレースの中の例外イベントの位置まで移動(travel) します。
-
- トレースのその位置から、失敗したコードまでステップ実行でさかのぼります。
-
- 失敗したコードで、ローカル変数を確認し、誤った値を含む変数の仮説を立てます。
-
- 誤った値を持つ変数のメモリアドレスを確認します。
-
- 疑わしい変数のアドレスに、メモリアクセス時のブレークポイントをba (Break on Access) コマンドを使ってセットします。
-
- g- を使って、疑われる変数へのメモリアクセスの最後の位置までさかのぼります。
-
- その位置、またはそれ以前のいくつかの命令が、失敗したコードフローの場所であれば、完了です。もし誤った値がほかの変数からのものであれば、別の変数にメモリアクセス時のブレークポイントをセットします。
-
- g- を使って、疑われる変数へのメモリアクセスの最後の位置までさかのぼります。その位置、またはそれ以前のいくつかの命令が、失敗したコードフローの場所であれば、完了です。
-
- この手順を、エラーを引き起こした誤った値をセットするコードが見つかるまで繰り返します。
Lab が前提とする環境
Windows 10 が動作するラップトップまたはデスクトップ PC (ホスト)
WinDbg Preview (インストール手順は、WinDbg Preview – Installation をご参照ください。概要としては、Microsoft Store のアプリを開いて “WinDbg Preview” で検索するか、< https://www.microsoft.com/store/apps/9pgjgd53tn86 > のリンクから入手します。)
サンプルC++ コードをビルドできる Visual Studio
今回は、例として、WinDbg を動作させるホストPC では Windows 10 1803 x64 が動作しています。Visual Studio 2017 を使用します。
-
- サンプルコードのビルド
ここの手順では、Visual Studio を使って、サンプルコードをビルドします。
(1) Visual Studio で[ファイル] – [新規作成] – [プロジェクト] をクリックし、[Visual C++] をクリックします。[Windows コンソール アプリケーション] を選択します。プロジェクト名を “DisplayGreeting” として、[OK] をクリックします。
(2) DisplayGreeting プロジェクトを右クリックしてプロパティを開きます。[C/C++] をクリックし、[SDL チェック] を [いいえ(/sdl-)] に変更します。
(3) [OK] をクリックします。
(4) DisplayGreeting.cpp に以下のテキストを貼ります。
// DisplayGreeting.cpp : Defines the entry point for the console application. //
#include "stdafx.h" #include <array> #include <stdio.h> #include <string.h>
void GetCppConGreeting(wchar_t* buffer, size_t size) { wchar_t const* const message = L"HELLO FROM THE WINDBG TEAM. GOOD LUCK IN ALL OF YOUR TIME TRAVEL DEBUGGING!";
wcscpy_s(buffer, size, message); }
int main() { std::array <wchar_t, 50> greeting{}; GetCppConGreeting(greeting.data(), sizeof(greeting));
wprintf(L"%ls\n", greeting.data());
return 0; } |
(5) DisplayGreeting プロジェクトを右クリックしてプロパティを開きます。[C/C++] –[コード生成] をクリックし、[基本ランタイム チェック] を[既定]、[セキュリティ チェック] を[セキュリティ チェックを無効にします(/GS-)] に変更します。[OK] をクリックします。
※上記の設定は推奨されませんが、今回のLab のために、誰かがコーディングの簡略化や特定のテスト環境構築のために、そのような設定を行った、というシナリオを想定しているものとします。
(6) メニューの[ビルド] –[ソリューションのビルド] をクリックします。以下のように正常終了します。
1>------ ビルド開始: プロジェクト: DisplayGreeting, 構成: Debug Win32 ------ 1>cl : コマンド ラインwarning D9025: '/sdl-' より'/GS-' が優先されます。 1>stdafx.cpp 1>cl : コマンド ラインwarning D9025: '/sdl-' より'/GS-' が優先されます。 1>DisplayGreeting.cpp 1>DisplayGreeting.vcxproj -> C:\Blog\TTD\DisplayGreeting\Debug\DisplayGreeting.exe 1>プロジェクト"DisplayGreeting.vcxproj" のビルドが終了しました。 ========== ビルド: 1 正常終了、0 失敗、0 更新不要、0 スキップ ========== |
(7) ビルドされたサンプルアプリの場所を確認します。[ソリューション エクスプローラー] で、DisplayGreeting プロジェクトを右クリックして、[エクスプローラーでフォルダーを開く]
をクリックします。例えば、C:\Blog\TTD\DisplayGreeting\DisplayGreeting というフォルダが開くので、一階層上に上がり、Debug フォルダ(C:\Blog\TTD\DisplayGreeting\Debug)
を開くと、DisplayGreeting.exe と、そのシンボルファイルDisplayGreeting.pdb ファイルがあるのを確認できます。
(8) DisplayGreeting.exe をダブルクリックして、サンプルアプリを実行します。
少し経つとこのウィンドウが閉じますが、実は例外が発生しています。実際、イベントビューアーのアプリケーションログを見ると、以下のようなエラーになっています。
以降の手順では、サンプルアプリの実行を記録し、この例外がなぜ発生したのか見ていきます。
-
- “DisplayGreeting” サンプルのトレースの記録
ここの手順では、誤った動作を行うDisplayGreeting アプリの TTD トレースログを記録します。
サンプルアプリを起動し、TTD トレースを記録するには、以下の手順を行います。一般的な手順は、Time Travel Debugging - Record a trace のドキュメントをご参照ください。
(1) WinDbg Preview を管理者権限で実行し、Time Travel トレースが取得できるようにします。
(2) WinDbg Preview 上で、[ファイル] –[Start Debugging] –[Launch executable (advanced)] を選択します。
(3) [Executable:] に、記録したい、ユーザーモード実行ファイルへのパスを入力するか、もしくは、[Browse] ボタンで実行ファイルを選択します。[Start directory:] にそのexe のあるフォルダへのパスを入力します。WinDbg Preview の launch executable メニューの詳細は、WinDbg Preview - Start a user mode session のドキュメントをご参照ください。
(4) [Record process with Time Travel Debugging] のチェックボックスにチェックを入れ、実行ファイルの起動時にトレースを記録できるようにします。Output directory には、トレースを出力するフォルダへのパスを入力します。
(5) [OK] をクリックすると、実行ファイルが起動し、記録が開始されます。
(6) トレースが記録されることを示すダイアログが表示され、しばらく後に、アプリケーションがクラッシュします。
(7) トレース ファイルがディスクに書き込まれます。今回の場合、C:\Blog\TTD\DisplayGreeting01.run がトレース ファイルです。
(8) デバッガは自動的にトレースファイルを開き、インデックスを作成します。インデックスは、トレースファイルの効率的なデバッグのために行われます。トレースファイルが大きいほど、インデックスには時間がかかります。
0:000> !index Indexed 2/2 keyframes Successfully created the index in 86ms. |
Keyframe とは、インデックスに使われるトレース内の位置です。Keyframe は自動的に生成されます。大きなトレースファイルほど、多いKeyframe を含みます。
(9) この時点で、トレースファイルの最初にいることになります。時間を進めたり、さかのぼったりすることができます。
TTD トレースがあれば、トレースをリプレイしたり、トレースファイルを他の人と共有して協業することもできます。詳細は Time Travel Debugging - Working with Trace Files のドキュメントをご参照ください。
以降の手順では、トレースファイルを解析し、サンプルコードの問題を特定していきます。
-
- コードの問題特定のためのトレースファイルの解析
ここの手順では、コードの問題を特定するためにトレースファイルを解析します。
WinDbg 環境の設定
(1) サンプルアプリのシンボルの場所をシンボルパスに追加し、シンボルをリロードします。
|
(2) サンプルアプリのソースコードの場所をソースパスに追加します。
0:000> .srcpath+ C:\Blog\TTD\DisplayGreeting\DisplayGreeting Source search path is: C:\Blog\TTD\DisplayGreeting\DisplayGreeting
************* Path validation summary ************** Response Time (ms) Location OK C:\Blog\TTD\DisplayGreeting\DisplayGreeting |
(3) スタックやローカル変数の状態を表示できるようにするために、WinDbg Preview のリボンで、[View] タブの[Locals] と[Stack] をクリックします。ソースを表示する際に、これらのウィンドウの配置を調整して、ソースコードとCommand のウィンドウも同時に表示できるようにします。
(4) WinDbg Preview のリボンで、[Source] タブから[Open Source File] をクリックし、DisplayGreeting.cpp を開きます。
例外の確認
(1) トレースファイルがロードされると、発生した例外の情報が表示されます。
|
(2) dx コマンドを使って記録されたすべてのイベントをリストします。例外イベントが、それらのイベントの中にリストされます。
|
(3) その例外イベント(上記の例では[0xa] ) をクリックして、TTD イベントについての情報を表示します。
|
(4) Exception フィールドをクリックし、例外データの詳細をさらに確認します。
|
例外データは、これがCPU によってスローされたハードウェア フォールトであることを示しています。また、0xc0000005 の例外コードが、これはアクセスバイオレーションであることも示しています。これは、一般に、アクセスしてはいけないメモリへの書き込みを行おうとしたことを示します。
(5) 例外イベントの中の[Time Travel] のリンクをクリックして、トレース上のその位置に移動します。
|
レジスタの出力から、スタックとベースポインタが2つの全く異なるアドレスを指していることがわかります。
esp=007cfd74 ebp=00520055 |
これは、スタック破壊 - おそらく関数がリターンしてスタックが破壊されたように見受けられます。これを確認するために、CPU ステートが壊れる前までさかのぼり、スタック破壊が起きた時を見つけられるか見てみる必要があります。
ローカル変数の確認とブレークポイントのセット
トレース上の失敗のポイントでは、エラー処理コードの本当の原因よりも数ステップ後であることが一般的です。タイムトラベルで、命令をさかのぼり、本当の原因を調べます。
(1) Home リボンから、Step Into Back コマンドを使って、3 命令ステップバックします。この時、stack とmemory ウィンドウも確認します。Command ウィンドウがtime travel position
とレジスタを表示します。
|
上記コマンド出力の通り、UI メニューのオプション(Home リボンの、Step Into Back コマンド) の代わりに、コマンドライン(t-) を使うこともできます。
(2) トレースのこの場所で、スタックとベースポインタの値は、より意味のある値になっており、破壊が起こったコードに近づいていることがわかります。
esp=007cfcbc ebp=007cfd6c |
(3) さらに確認するために、memory ウィンドウを開き、ベースポインタのメモリアドレス 0x007cfd6c の近くの値を表示します
(4) Memory リボンから、[Text] を[ASCII] で表示するよう変更します。
(5) ベースポインタが命令を指す代わりに、メッセージテキストを指しています。何かが正しくないため、スタックを破壊した場所に近づいてきています。さらに調べるために、ブレークポイントをセットします。
なお、今回の例では、コードがとても小さなサンプルのため、コード上で問題を見つけるのは簡単ですが、何百行もあるコードや、何十ものサブルーチンがある場合、ここでの方法は、問題を見つけるのに時間を節約する役に立ちます。
TTD とブレークポイント
ブレークポイントを使うことは、興味のある何らかのイベントのコード実行で停止するための一般的な方法です。TTD は、記録されたトレースの中で、ブレークポイントをセットして、そのブレークポイントにヒットするまで時間をさかのぼらせることができます。
メモリアクセスのブレークポイント
あるメモリの場所にアクセスされたらブレークするブレークポイントをセットするには、ba (break on access) コマンドを以下のシンタックスで使用します。
ba <access> <size> <address> {options} |
Option |
説明 |
e |
execute (実行:CPU がそのアドレスから命令をフェッチした時) |
r |
read/write (CPU がそのアドレスをリードまたはライトした時) |
w |
write (CPUがそのアドレスに書き込んだ時) |
任意の時点で4 つのデータ ブレークポイントのみセットできる点にご留意ください。また、データが正しくアラインされていること(Word は2, Dword は4, Quadword は0 または8)。
ベースポインタへのメモリアクセスのブレークポイントのセット
(1) ベースポインタへの書き込みメモリアクセスにブレークポイントをセットします。ここでのebp は、0x007cfd6c です。
0:000> ba w4 0x007cfd6c |
(2) [View] の [Breakpoints] をクリックし、上記がセットされていることを確認します。
(3) [Home] の[Go Back] をクリックし、ブレークポイントがヒットするまでさかのぼります。
|
(4) [View] の[Locals] をクリックします。Locals ウィンドウで、source が全てのテキストを持っているのに対し、変数destination が、メッセージの一部のみを持っています。この情報が、スタックが破壊されたという考えの裏付けになります。
(5) ここでスタックがどのコードをアクティブにしているか見てみます。[View] の[Stack] をクリックします。
Microsoft が提供している wcscpy_s() 関数がこのようなコードバグを持っているとは考えにくいため、スタックをさらに見ていきます。スタックでは、DisplayGreeting!main が、DisplayGreeting!GetCppConGreeting を呼び出しています。今回のような小さなサンプルでは、コードを開いて誤りを見つけるのは非常に簡単です。しかし、より大きく複雑なプログラムで使えるように、さらに調べるための新たなブレークポイントをセットします。
GetCppConGreeting 関数へのアクセスのブレークポイントのセット
(1) Breakpoints ウィンドウで、既存のブレークポイントを右クリックして、Remove を選び、既存のブレークポイントを削除します。
(2) DisplayGreeting!GetCppConGreeting 関数のアドレスを確認するために、dx コマンドを使います。
|
(3) ba コマンドを使って、メモリアクセスのブレークポイントをセットします。実行のためにメモリから関数が読まれるので、r (read) のブレークポイントをセットします。
|
(4) Hardware Read のブレークポイントが Breakpoints ウィンドウでアクティブになっていることを確認します。
(5) greeting 文字列のサイズを確認するために、Watch ウィンドウで、sizeof(greeting) の値を表示します。View リボンで Watch を選択し、sizeof(greeting) を入力します。(この時点で表示されない場合は、main() 関数実行時の(8) で値が表示されます。)
(6) Time Travel メニューで、Time travel to start コマンドを使って、トレースの最初に移動します。
|
(7) Home メニューで、Go をクリックし、ブレークポイントがヒットするまでコードの処理を前に進めます。
|
(8) Home メニューで、Step Out Back で 1 ステップ戻ります。
|
(9) 原因が見つかったようです。greeting 配列は、50 文字の長さで宣言しましたが、sizeof(greeting) は 0x64 (100) でGetCppConGreeting に渡していました。
サイズをさらに見ると、message は75 文字で、終端文字を含めると76 文字あります。
HELLO FROM THE WINDBG TEAM. GOOD LUCK IN ALL OF YOUR TIME TRAVEL DEBUGGING! |
(10) コードを修正する一つの方法は、文字配列のサイズを100 にすることです。
std::array <wchar_t, 100> greeting{}; |
または、sizeof(greeting) をsize(greeting) に変更する必要があります。
GetCppConGreeting(greeting.data(), size(greeting)); |
(11) これらの修正を確認するには、コードを再コンパイルしてエラーなく実行できるかを確認します。
Source ウィンドウでのブレークポイントのセット
(1) この調査の別の方法として、コードの行をクリックすることでブレークポイントをセットすることがあります。例えば、Source ウィンドウの std:array の定義の行の左側をクリックすることで、ブレークポイントをセットできます。
(2) Time Travel メニューでTime travel to start コマンドを実行し、トレースの最初に戻ります。
|
(3) Home リボンで Go をクリックし、ブレークポイントにヒットするまで進めます。
|
変数 greeting へのアクセスのブレークポイントのセット
この調査を行う別の方法として、疑わしい変数にブレークポイントをセットして、どのコードがそれらを変更しているか確認する方法があります。例えば、GetCppConGreeting メソッドの変数greeting にブレークポイントをセットしてみます。ここでは、以前のセクションでセットしたブレークポイントがセットされたままとします。
(1) View のLocals をクリックします。Locals ウィンドウで、greeting が表示されており、そのメモリの場所を確認できます。
(2) dx コマンドで配列 greeting を確認します。
0:000> dx &greeting &greeting : 0x7cfd08 : { size=50 } [Type: std::array<wchar_t,50> *] [<Raw View>] [Type: std::array<wchar_t,50>] [0] : -18928 '또' [Type: wchar_t] ... |
このトレースでは、greeting は 0x7cfd08 のアドレスにあります。
(3) Breakpoints ウィンドウで、既存のブレークポイントを右クリックして、Remove をクリックし、削除します。
(4) ba コマンドで、書き込みアクセスを確認したいメモリアドレスにブレークポイントをセットします。
|
(5) Time Travel メニューで、Time travel to start コマンドを使って、トレースの最初に戻ります。
|
(6) Home メニューで、Go をクリックし、配列greeting への最初のメモリアクセスに移動します。
|
他にも、トレースの最後まで移動して、逆に戻ることで、メモリへ書き込んだ、トレース上の最後のポイントに移動することができます。
TTD.Memory オブジェクトでのメモリアクセスの表示
トレース内のメモリがどの時点でアクセスされたか確認するために、TTD.Memory オブジェクトと dx コマンドを使う方法があります。
(1) dx コマンドで配列 greeting を確認します。
0:000> dx &greeting &greeting : 0x7cfd08 : { size=50 } [Type: std::array<wchar_t,50> *] [<Raw View>] [Type: std::array<wchar_t,50>] [0] : -18928 '또' [Type: wchar_t] ... |
このトレースでは、0x7cfd08 にgreeting があります。
(2) dx コマンドで、そのアドレスから4 バイト分へのRead/Write アクセスを見てみます。
... |
(3) [0x*] のリンクをクリックして、メモリアクセスが発生した時の詳細情報を表示します。
|
(4) [Time Travel] のリンクをクリックして、トレース上のその場所に移動します。
|
(5) Read/Write アクセスがトレース上の最後に発生したところを見たい場合は、[0x*] のリストの最後をクリックするか、.Last() 関数をdx コマンドの最後につけます。
|
(6) [Time Travel] のリンクをクリックして、トレース上のその場所に移動し、その時点のコード実行を見ていきます。この部分は上述したとおりです。
上記の内容が、ユーザーモードのプログラムを開発される方のお役に立てば幸いです。
WDK サポートチーム 津田