トレースで動作を探る

前回に続き、他人が作ったプログラムの改訂作業です。

贅肉を落とす

ただでさえすごい量なので、 必要のないところはばっさばっさと切り落としていきます。 ざっと眺めてみると、

#if 0 〜 #endif で囲まれた部分

が結構ありました。バグ修正前のコードを念のために保存しておいたり、 実験的に作ってみたけど使えないのでとりやめた機能の部分だったりします。 こういうのは潔く削除したほうが悔いを残さないものです。 特に、かなり長い部分を #if 0 で無効にしている場合、有効な部分と間違えて、

「いくら修正しても動作が変わらない」

と悩んだりするのもばからしいでしょう。 500行にもわたって無効になっているところもありました。

「いや、もうしばらくは削除しないでおきたい」という場合には、

#if        0
/*
*/
#endif  /* 0 */

みたいな感じに全部の行に印をつけておけば、grepで1行だけ取り出したときでも すぐにここは無効なコードだとわかるので便利です。 私はエディターに、「行頭に ** をつける」だけのマクロを定義していて、 一気に無効の印をつけられるようにしています。

/* 〜 */ の形式の註釈は、入れ子にできないのが欠点。 無効の印をつける前のコードに註釈がついていれば、閉じの */ を消さなければ なりません。もっともこの場合は #if 0 がついているので、 コンパイル・エラーになることはありませんから、このままでもいいことにしちゃいます。

だったら // を行頭につければいい? ごもっとも。 これを使わないのは、まあ私の個人的な趣味ですね。 それと、今回は元の作者が // を多用していたので、自分がつけた註釈と 区別がつく、という効用もありました。

動かして様子を見る

ある程度整理がついたらコンパイルしてみます。 Win32になって廃止された函数でいくつかエラーが出ましたが、 幸いにも付録の機能の部分だったので、その付近のコードを単純に註釈にして、 とにかくコンパイルできるようにしました。 VC++1.5よりも詳しくチェックしているようで、警告も山のように出ます。

例として貰っておいたファイルを入力として指定し、いざ実行。 なぜか途中でエラーメッセージが出て処理が中断してしまう。 実はあとになって、本当にこの入力ファイルに構文上の誤りがあったことが 判明したのですが、この時は、一部のデータファイルがないなど 実際の動作環境と違っているせいだと思い込んでいました。

トレース機能を組み込む

さて、プログラムの構成や動きを把握するにはいろいろ方法がありまして、

など、臨機応変に使い分けて調べていく訳です。

上に書いた「動的解析」も有効なんですが、調べたいプログラムによっては、

ブレークポイントで何度もプログラムを止めて変数値をメモする

という作業の繰り返しが必要になってしまいます。 これが実にかったるいし、量が増えると間違いも多い。 という訳で、こういう情報をプログラム自身に生成させようというのが、 トレース機能です。

ctraceというツールがありました。 これは、Cのプログラムを変換して、トレース出力用のコードを埋め込むものでした。 変換したプログラムをコンパイルして実行すると、 実行した文と行番号、そこに現れる変数の値をすべてファイルに出力します。 実行後、ゆっくりと処理の流れを調べることができます。

確かに便利なんですが、なんでもかんでも出力するので、すぐに巨大な ファイルができてしまいます。もう少し使いやすいものを、ということで、 トレース用の函数・マクロ群を用意してみました。 これは、

使い方ですが、下準備としてList 1のような函数を 用意しておきます。テキストをファイルに書き出すだけの単純なものです。 そして、プログラムの最初と最後に、List 2のように書きます。 InitInstance() と ExitInstance() に置くのが便利でしょう。 MFC 以外の場合でも考え方は同じで、要はトレース出力の準備と後始末を しているのです。

List 3List 4 はトレース出力の実体です。

トレースしたい函数の入り口点(先頭)には、

TRACE_IN("HogeClass::MunyaFunc()");

出口点(return の直前)には

TRACE_OUT("HogeClass::MunyaFunc()");

のように書きます。これを手がかりとしてトレース出力に字下げがつくので、 函数の呼び出し関係を把握しやすくなります。 TRACE_IN() や TRACE_OUT() に渡す文字列は何でも構わないので、 return が複数ある場合にどこから戻ったか区別できるようにするなど、 工夫できます。

ある文に処理が到達したことを示したり、そのときの変数値を表示したりするには、

TRACE_LOG(("Statement A: val1 = %d, val2 = %s", val1, val2));

のように書きます。括弧が二重になっていることに註意。

なお、List 4 で使われている _vsnprintf() は、使えない処理系もあるかも知れません。 vsprintf() と同様の処理なのですが、buf の領域をはみ出て書きこんでしまう ことのないよう制限できるものなので、安全のため使っています。

独自のトレース機能はいろいろ細工ができて便利

MFCの機能にもTRACEというのがあるのですが、ちょっと面倒でも独自の トレース機能を用意すると、いろいろ細工ができて便利です。 その例をひとつ紹介しましょう。

例えば、

        for (int i = 0; i < 100; i++) {
                Sub1();
        }

というプログラムで、Sub1() の中ではいろいろ複雑なことをやっていて トレース出力も膨大になるとします。でも実際には、i == 0 や i == 99 の 場合のみ詳しく調べればデバッグには充分なことが多いのです。

このトレース機能は、プログラムの途中でも、

DebugSetLogFunc(NULL);

とすればトレース出力を無効にすることができるようになっています。 そこで、

        for (int i = 0; i < 100; i++) {
#if     defined(_DEBUG)
                if ((i == 0) || (i == 99)) {
                        DebugSetLogFunc(WriteDebugLog);
                }
                else {
                        DebugSetLogFunc(NULL);
                }
#endif  /* defined(_DEBUG) */
                Sub1();
        }

のようにすれば、必要な部分のみトレース出力できます。

ほかにも、TraceLog.c を適宜書き替えれば、特定の文の実行回数を数えるなど デバッグのための情報を収集できます。


List 1

#if     defined(_DEBUG)
CStdioFile *    DebugFp = NULL;
static  void    CloseDebugLog(void)
{
        delete DebugFp;
        DebugFp = NULL;
}
static  void    OpenDebugLog(void)
{
        UINT    mode = CFile::modeCreate | CFile::modeWrite | CFile::typeText;
        DebugFp = new CStdioFile("Trace.txt", mode);
}
int     WriteDebugLog(char * text)
{
        if (DebugFp == NULL) {
                OpenDebugLog();
        }
        DebugFp->WriteString(text);
        DebugFp->WriteString("\n");
        return 0;
}
#endif  /* defined(_DEBUG) */

List 2

/* InitInstance() */
#if     defined(_DEBUG)
        DebugSetLogFunc(WriteDebugLog);
#endif  /* defined(_DEBUG) */
/* ExitInstance() */
#if     defined(_DEBUG)
        CloseDebugLog();
#endif  /* defined(_DEBUG) */

List 3

/* TraceLog.h */
#if     ! defined(D_TRACELOG_H)
#define D_TRACELOG_H    1
#define TYPEEXPO(type)  __declspec(dllexport)   type
typedef TYPEEXPO(int)   UDF_TRACELOG(char *);
#if     defined(__cplusplus)
extern  "C" {
#endif  /* defined(__cplusplus) */
extern  void    DebugSetLogFunc(UDF_TRACELOG * udfLogOutFunc);
extern  void    DebugTraceIn(char * name);
extern  void    DebugTraceOut(char * name);
extern  int     DebugTraceLog(char *fmt, ...);
#if     defined(__cplusplus)
}
#endif  /* defined(__cplusplus) */
#if     defined(_DEBUG)
#define TRACE_IN(x)     DebugTraceIn(x)
#define TRACE_LOG(x)    (DebugTraceLog x)
#define TRACE_OUT(x)    DebugTraceOut(x)
#else   /* defined(_DEBUG) */
#define TRACE_IN(x)
#define TRACE_LOG(x)
#define TRACE_OUT(x)
#endif  /* defined(_DEBUG) */
#endif  /* ! defined(D_TRACELOG_H) */

List 4

/* TraceLog.c */
/*
*/
#include        "TraceLog.h"
#include        <stdarg.h>
#if     defined(_DEBUG)
#include        <stdio.h>
#if     ! defined(BUFSIZ)
#define         BUFSIZ          1024
#endif  /* ! defined(BUFSIZ) */
#endif  /* defined(_DEBUG) */
/*.....................................................................
*/
static  UDF_TRACELOG *  UdfLogOutFunc = NULL;
static  long            TraceLevel = 0;
/*=====================================================================
*/
void
DebugSetLogFunc(
        UDF_TRACELOG *  udfLogOutFunc)
{
        UdfLogOutFunc = udfLogOutFunc;
}
/*---------------------------------------------------------------------
*/
void
DebugTraceIn(char * name)
{
        DebugTraceLog(">>> %s", name);
        TraceLevel ++;
}
/*---------------------------------------------------------------------
*/
void
DebugTraceOut(char * name)
{
        TraceLevel --;
        DebugTraceLog("<<< %s", name);
}
/*---------------------------------------------------------------------
*/
int
DebugTraceLog(char *fmt, ...)
{
        int             n = 0;
#if     defined(_DEBUG)
        char            buf[BUFSIZ];
        va_list         argptr;
        int             i;
        int             indent = 2;
        if (0 < TraceLevel) {
                indent = TraceLevel * 4 + 2;
        }
        for (i = 0; i < indent; i++) {
                buf[i] = ' ';
        }               /* 念のため memset() は避ける */
        buf[0] = ':';
        va_start(argptr, fmt);
        n = _vsnprintf(&buf[indent], BUFSIZ - indent, fmt, argptr);
        va_end(argptr);
        if (UdfLogOutFunc != NULL) {
                if (n < 0) {
                        (*UdfLogOutFunc)("[FATAL] (DebugTraceLog) Too long message.");
                        buf[BUFSIZ - 1] = '\0';
                }
                (*UdfLogOutFunc)(buf);
        }
#endif  /* defined(_DEBUG) */
        return n;
}