uyota 匠の一手

printf 系のデバッグ方法は古典的だが、とても効果的だ。マクロを使ってもいいし、関数などを使ってもいい。最初に動作の確認をするときには、大抵必要になるものであり、どうせなら後々にも再び使えるように残しておいた方が、変更したときの二度手間も省ける。

一秒間に数千から数万のメッセージを処理するようなシステムだと、一筋縄ではいかない。DEBUG などのマクロでもいいし、大域変数により制御できる debug 関数でもいい。このようなシステムだと、一度これを有効にすると手に負えなくなる。

例えば、処理の仕方を効率良くするために少し手をいれたとしよう。何らかの、バグがあり期待どおりの動作をしない。そこで、デバッグを有効にする。大量にメッセージを処理する為、大量のデバッグ情報が溢れ出てくるのだ。一秒間に数千回も同じエラーを出力されても、人間は追い付けない。syslog などは、全く同じ出力が続いた場合は、何回続いたと報告するが、その程度のログの出力では有力な情報の出力を諦めざるをえない。また、二つのエラーが交互に発生したときには無力である。

大量のメッセージを処理するシステムでは、一つずつのログの出力を調整出来るようでないと、使い物にならない。 デバッグ情報も多ければ多い程よいわけではないのだ。例えば、十行目にある Log は全てを出力したいが、百行目では百回に一回だけ、二百行目にある Log では千回に一回だけ出力したいとなる。

もし、そのような事が出来る関数を書こうとしたら、ずいぶん大変だろう。少なくても、ファイル名または関数名と、行数を取らなくてはいけない。それらの情報を利用して、いつ出力すべきかの情報を保つ、リストなりハッシュテーブルなりが必要になるだろう。少なくても、個人的には書きたくないし、誰かが書いてくれたとしても、絶対に触りたくもない関数だ。

しかし、マクロをうまく使いこなせば、この複雑な処理がいとも簡単に出来てしまう。

% cat diagnostic.c 
#ifndef LIB
  #include 
#endif

#define DIAG(max, msg) \
  { static int count_ ## __LINE__; static int max_count_ ## __LINE__ = max; \
  if(max_count_ ## __LINE__ && \
    (++count_ ## __LINE__ <= max_count_ ## __LINE__ || \
    (count_ ## __LINE__ % max_count_ ## __LINE__) == 0)) printf msg; }

int main()
{
    int i ;

    DIAG(0, ("DIAG(%d)\n", 0));
    DIAG(1, ("DIAG(%d)\n", 1));
    for(i = 1; i <= 11; i++)
       DIAG(3, ("DIAG(%d), i = %d\n", 3, i));
}

この例では、DIAG と言うマクロ関数を作っている。DIAG は第一引数として最大表示回数を取り、二つ目にログの出力を取る。最大表示回数に届いた後は、最大表示回数で指定された数に対して、一回だけ出力するように移行する。

DIAG が表れるたびに新しい、ブロックを生成し、その中に static 変数を定義することによって、個々の行での出力を任意の制御を実現している。

__VA_ARGS__ を使ってもいいが、最初に書いたものでは __VA_ARGS__ は実装されていなかったので、この形にした。そのため、0 を最初に渡した場合は、ログを出力しない。1 を渡したときは、全てのログを出力する。そして、3 を渡した場合は、まず三回ログを表示した後に、3 の倍数回の時のみにログを出力する。

実行結果だ。

% make diagnostic
cc -O2 -fno-strict-aliasing -pipe   diagnostic.c  -o diagnostic
% ./diagnostic 
DIAG(1)
DIAG(3), i = 1
DIAG(3), i = 2
DIAG(3), i = 3
DIAG(3), i = 6
DIAG(3), i = 9

デバッガを使えば、実行中に表示回数を変化させることも出来る。

gcc のプリプロセッサを通した結果だ。

% gcc -E -DLIB diagnostic.c 
# 1 "diagnostic.c"
# 1 ""
# 1 ""
# 1 "diagnostic.c"
# 11 "diagnostic.c"
int main()
{
    int i ;

    { static int count___LINE__; static int max_count___LINE__ = 0;
 if(max_count___LINE__ && (++count___LINE__ <= max_count___LINE__ || (count___LINE__ % max_count___LINE__) == 0))
 printf ("DIAG(%d)\n", 0); };
    { static int count___LINE__; static int max_count___LINE__ = 1;
 if(max_count___LINE__ && (++count___LINE__ <= max_count___LINE__ || (count___LINE__ % max_count___LINE__) == 0))
 printf ("DIAG(%d)\n", 1); };
    for(i = 1; i <= 11; i++)
       { static int count___LINE__; static int max_count___LINE__ = 3;
 if(max_count___LINE__ && (++count___LINE__ <= max_count___LINE__ || (count___LINE__ % max_count___LINE__) == 0))
 printf ("DIAG(%d), i = %d\n", 3, i); };

実は、この出力はプリプロセッサ依存なのだ。gcc では ## が __LINE__ よりも先に処理されてしまう様だ。__LINE__ が先に展開される処理系だと、count_10 などの様になる。各ブロック内に static として新たに定義されている為、各行の出力回数が独立して保持されている。

大量の処理をしていると、問題が一度起きると、その後は雪崩の様に問題が起きるものだ。そして、それを全てログすると、それ自体がまた別の問題となる。システムのあちらこちらで、ログを大量に吐くため、状況が把握できないことが多々あった。このマクロを実装してから、大変楽になった。