JCLでお手軽に例外発生時のスタックトレースを取る

このアーティクルはDelphi Advent Calendar 2017の5日目の記事です(2年ぶり4回目)。またゆるふぁい#0のLTの内容を元にしています。なお以下の説明は基本的にVCLアプリケーションのお話になります。

Delphiで作成したプログラムを実行中にエラーが発生すると例外が送出されます。

procedure TForm1.Button1Click(Sender: TObject);
var
  P: PInteger;
begin
  P := nil;
  P^ := 42;  // EAccessViolation
end;

プログラム上で捕捉されなかった例外(unhandled exception)は、デフォルトの例外の処理としてApplicationオブジェクトで捕捉されてエラーメッセージを表示します。

このとき例外の原因になった処理のアドレスは詳細マップファイルを生成しておけばわかります(後述)。しかしエラーが発生した箇所までの実行経路(呼び出し経路)が複雑だったり、Systemユニットにあるような低レベルの関数のように、どこから呼ばれるのかの選択肢が非常に多い箇所でエラーが発生した場合は、単に例外が発生したアドレスがわかるだけでは不十分です。デバッガ上で動作させているのであればDelphiのIDEで例外発生時の呼び出し履歴を見ればよいのですが、客先環境でしか再現しないような場合などでスタックトレースを取ることができれば問題解決の大きな助けになります。そこで簡単にできる方法として、JCL(JEDI Code Library)のJCL Debugを使って例外送出箇所までのスタックトレースを取得してみます(もちろん商用製品のmadExceptやEurekaLogであればもっといろいろなことができるとは思います)。

JCL(JEDI Code Library)はJEDIプロジェクトによるライブラリ群です。ビジュアルコンポーネントのJVCL(JEDI VCL)とともにインストールされていることも多いのではないでしょうか。新たにインストールする場合は、Delphiの複数バージョンがインストールされている環境ではリポジトリ(JCL、JVCL)から取得してインストール、単一のバージョンのみならGetItパッケージマネージャからインストール、Starter SKUであればCC(JCL、JVCL)からバイナリインストーラをダウンロードしてインストール、ということになります(詳細な手順は省略します)。JCLがインストールされると、"メインメニュー"→"プロジェクト"の一番下あたりに"JCL Debug expert"というアイテムが追加されているはずです。

さて、ここまで来れば、必要な手順はたった4つです。プロジェクトを開いておいて、

ステップ1: "JCL Debug expert"の"Generate .jdbg files"を有効("Always enabled"または"Enabled for this project")にします。

ステップ2: "Insert JDBG data into the binary"を有効("Always enabled"または"Enabled for this project")にします。

ステップ3: "メインメニュー"→"プロジェクト"→"オプション"で"プロジェクトオプション"ダイアログを表示し、必要なターゲットを選択("すべての構成 - すべてのプラットフォーム"でいいと思います)して、"Delphiコンパイラ"→"リンク"の"マップファイル, 64ビット Windows, 32ビット Windows, OS X, iOS シミュレータ プラットフォームのみ"を"詳細"に変更します。

ステップ4: "メインメニュー"→"ファイル"→"新規作成"→"その他"で"新規作成"ダイアログを表示して、"Delphiプロジェクト"→"Delphiファイル"から"JCL Exception dialog for Delphi"を選択すると"New exception dialog..."ウィザードが表示されます。ここでPage 1 of 7の"Unit file name"に例外ダイアログのユニット名を入れ、Page 2 of 7の"Sizeable dialog"にチェックして(他の項目はとりあえずデフォルトのままでOK)、"Finish"ボタンをクリックすると例外ダイアログのユニットが作成されます。ただこのままだと表示フォントが英語環境向けなので、プロジェクトで使用しているフォントに合わせたほうがいいと思います(とりあえずフォームをテキスト表示にして"Font.*"の項目を全部削除すればデフォルトになります)。

これでプロジェクトをコンパイルすると確認ダイアログが表示されますが、これは詳細マップを作る設定に変更しますか？という確認なのでそのまま"OK"とします。これでコンパイルされたプログラムを実行すると例外ダイアログが表示されますが、ここで"Details"ボタンをクリックすると、スタックトレースが表示されます。

------------------------------------------------------------------------------
Exception log with detailed tech info. Generated on 2017/11/09 19:39:30.
You may send it to the application vendor, helping him to understand what had happened.
Application title: Project1
Application file: (省略)\Win32\Debug\Project1.exe
------------------------------------------------------------------------------
Exception class: EAccessViolation
Exception message: モジュール 'Project1.exe' のアドレス 005D908C でアドレス 00000000 に対する書き込み違反がおきました。.
Exception address: 005D908C
------------------------------------------------------------------------------
Main thread ID = 2320
Exception thread ID = 2320
------------------------------------------------------------------------------
Exception stack
Stack list, generated 2017/11/09 19:39:30
[005D908C]{Project1.exe} Unit1.TForm1.Button1Click (Line 31, "Unit1.pas" + 2)
[00522143]{Project1.exe} Vcl.Controls.TControl.Click (Line 7442, "Vcl.Controls.pas" + 9)
[00526749]{Project1.exe} Vcl.Controls.TWinControl.WndProc (Line 10160, "Vcl.Controls.pas" + 158)
[0053B254]{Project1.exe} Vcl.StdCtrls.TButtonControl.WndProc (Line 5278, "Vcl.StdCtrls.pas" + 13)
[005268AF]{Project1.exe} Vcl.Controls.DoControlMsg (Line 10229, "Vcl.Controls.pas" + 12)
[00526749]{Project1.exe} Vcl.Controls.TWinControl.WndProc (Line 10160, "Vcl.Controls.pas" + 158)
[005C3E0D]{Project1.exe} Vcl.Forms.TCustomForm.WndProc (Line 4546, "Vcl.Forms.pas" + 209)
[00525D68]{Project1.exe} Vcl.Controls.TWinControl.MainWndProc (Line 9867, "Vcl.Controls.pas" + 3)
[004C590C]{Project1.exe} System.Classes.StdWndProc (Line 17364, "System.Classes.pas" + 8)
[0052685A]{Project1.exe} Vcl.Controls.TWinControl.DefaultHandler (Line 10201, "Vcl.Controls.pas" + 30)
[00526749]{Project1.exe} Vcl.Controls.TWinControl.WndProc (Line 10160, "Vcl.Controls.pas" + 158)
[0053B254]{Project1.exe} Vcl.StdCtrls.TButtonControl.WndProc (Line 5278, "Vcl.StdCtrls.pas" + 13)
[004C590C]{Project1.exe} System.Classes.StdWndProc (Line 17364, "System.Classes.pas" + 8)
------------------------------------------------------------------------------
Call stack for main thread
Stack list, generated 2017/11/09 19:39:30
[773A0C52]{ntdll.dll } ZwGetContextThread
(以下省略)
------------------------------------------------------------------------------

こんな感じで例外発生までの呼び出し履歴が表示されます。スタックトレースの表示項目はこの場合、左からアドレス、実行ファイル、メソッド、ソースコード内の当該行番号、ユニット名、メソッド先頭からの行オフセットとなっています(リンクされたユニットのデバッグ情報によって表示される項目が異なります)。

JCL Debugを有効にするとプロジェクトファイル(.dpr)の先頭に

// JCL_DEBUG_EXPERT_GENERATEJDBG ON
// JCL_DEBUG_EXPERT_INSERTJDBG ON

の2行が追加され、リンク時に.mapファイルから.jdbgファイルを生成して、これを実行ファイルに埋め込んでくれます。一方で例外ダイアログではこの.jdbgファイルの情報からスタックトレースに必要な情報を取り出して上記のような表示を行ってくれる、という仕組みです。

また例外ダイアログを使わずログなどに記録するような場合は、

unit DumpExceptionStack;

interface

uses
  Winapi.Windows,
  System.SysUtils,
  JclBase, JclDebug;

function DumpLastExceptStackInfoList(const Separator: String = '|'): String;


implementation

function GetStackInfoDescription(const Addr: Pointer): String;
var
  Info: TJclLocationInfo;
  StartProcInfo: TJclLocationInfo;
  OffsetStr: String;
  StartProcOffsetStr: String;
  FixedProcedureName: String;
  UnitNameWithoutUnitscope: String;
begin

  OffsetStr := '';

  if GetLocationInfo(Addr, Info) = True then
  begin
    with Info do
    begin
      FixedProcedureName := ProcedureName;
      if Pos(UnitName + '.', FixedProcedureName) = 1 then
      begin
        FixedProcedureName := Copy(FixedProcedureName,
                                   Length(UnitName) + 2,
                                   Length(FixedProcedureName) - Length(UnitName) - 1);
      end
      else if Pos('.', UnitName) > 1 then
      begin
        UnitNameWithoutUnitscope := UnitName;
        Delete(UnitNameWithoutUnitscope, 1, Pos('.', UnitNameWithoutUnitscope));
        if Pos(UnitNameWithoutUnitscope + '.', FixedProcedureName) = 1 then
        begin
          FixedProcedureName := Copy(FixedProcedureName, Length(UnitNameWithoutUnitscope) + 2, Length(FixedProcedureName) - Length(UnitNameWithoutUnitscope) - 1);
        end;
      end;

      if LineNumber > 0 then
      begin
        if (GetLocationInfo(Pointer(TJclAddr(Info.Address) - Cardinal(Info.OffsetFromProcName)), StartProcInfo) = True) and
           (StartProcInfo.LineNumber > 0) then
        begin
          StartProcOffsetStr := Format(' + %d', [LineNumber - StartProcInfo.LineNumber]);
        end
        else
        begin
          StartProcOffsetStr := '';
        end;

        if OffsetFromLineNumber >= 0 then
        begin
          OffsetStr := Format(' +0x%x', [OffsetFromLineNumber]);
        end
        else
        begin
          OffsetStr := Format(' -0x%x', [-OffsetFromLineNumber]);
        end;

        Result := Format('[0x%p] %s.%s (Line %u, "%s"%s)%s',
                         [Addr, UnitName, FixedProcedureName, LineNumber, SourceName, StartProcOffsetStr, OffsetStr]);
      end
      else
      begin
        OffsetStr := Format(' +0x%x', [OffsetFromProcName]);
        if UnitName <> '' then
        begin
          Result := Format('[0x%p] %s.%s%s', [Addr, UnitName, FixedProcedureName, OffsetStr]);
        end
        else
        begin
          Result := Format('[0x%p] %s%s', [Addr, FixedProcedureName, OffsetStr]);
        end;
      end;
    end;
  end
  else
  begin
    Result := Format('[0x%p]', [Addr]);
  end;

end;

function DumpLastExceptStackInfoList(const Separator: String = '|'): String;
var
  I: Integer;
begin

  Result := '';

  with JclLastExceptStackList do
  begin
    ForceStackTracing;
    for I := 0 to Count - 1 do
    begin
      Result := Result + GetStackInfoDescription(Items[I].CallerAddr) + Separator;
    end;
  end;

  if Result <> '' then
  begin
    Delete(Result,Length(Result) - Length(Separator) + 1,Length(Separator));
  end;

end;

initialization
//  Include(JclStackTrackingOptions, stRawMode);
  Include(JclStackTrackingOptions, stStaticModuleList);
  JclStartExceptionTracking;

finalization
  JclStopExceptionTracking;

end.

このようなユニットをプロジェクトファイルのなるべく先頭のほうでusesしておき、TApplicationEventsコンポーネントのOnExceptionイベントで

procedure TForm1.ApplicationEvents1Exception(Sender: TObject; E: Exception);
begin
  Memo1.Lines.Add(DumpLastExceptStackInfoList(sLineBreak));
end;

というように処理させることもできます。

JCL Debugのいいところとしては、無料であること、またJCL/JVCLを入れてあればそれだけで使えることがあげられます。一方でいまいちなところとしては、メインスレッド以外のスレッドを扱うときはTThreadからではなくTJclDebugThreadから派生していないとスタックトレースがとれないこと、リソースDLLで言語切り替えをするプロジェクトでは、言語リソースDLLのコンパイルでいちいちエラーになってJCLの例外ダイアログが表示されること、それ以外にもJCL Debugを有効にしているとIDEでJCLの例外ダイアログが頻繁に表示されること、などがあります。

ところで例外時の(通常の)アドレス表示からソースコードの場所を特定するには、マップファイルを参照します(こちらも詳細がお勧めです)。表示されたアドレスから、マップファイルの先頭にある

Start Length Name Class
0001:00401000 001D3B24H .text CODE
0002:005D5000 0000155CH .itext ICODE
...

のCODEの値、通常は0x00401000を引きます。この値がマップファイル上のアドレス表示の"0001:XXXXXXXX"のXXXXXXXXに相当します。次にマップファイルの"Publics by Value"のリストの"0001:"の部分を上から順に、このアドレスと同じか、より小さく最も近い行を探します。見つかった行が例外を発生させたメソッドになります。さらに詳細マップであれば"Line numbers for"でこのアドレスを探していき、見つかったらそこに書かれているのがユニット(ソースコード)の名前と、行番号になります。

→JclDebugでスタックトレースを取得する(Gist)