time macro
前回、libmを弄んでいる時、gdbを使っていたんだけど、アプリの起動直後、目的の 関数に到達するまでに随分あちこちと引き回される事に気がついた。果たしてどれぐらい 余分に時間がかかっているか、知りたくなった。
ああ、C語にもタイムマクロが有ったらなあ。一発で測定出来るだろうに。ぐずっていても しょうがないので、flispに載ってたgettimeofdayを使って、マイクロ秒の単位で 求めてみよう。
下記のように、測定対象を現時間測定プログラムで挟んであげる。そして、その差分を 取れば、関数の実行時間が判明するはず。
st = time_now();
z = cexpl(x);
sp = time_now();
printf("time = %10.6f\n", sp - st);
st = time_now();
z = cexpl(x);
sp = time_now();
printf("time = %10.6f\n", sp - st);
これを、fedoraで実行してみた。vm.drop_caches=3は、メモリーキャッシュをクリア する命令。FreeBSDとかだとどうやるんだろう？memcontrol(8)とかは違うみたいだし。
[sakae@fedora z]$ sudo sysctl -w vm.drop_caches=3 vm.drop_caches = 3 [sakae@fedora z]$ ./a.out time = 0.000658 time = 0.000011 [sakae@fedora z]$ ./a.out time = 0.000115 time = 0.000010 [sakae@fedora z]$ ./a.out time = 0.000051 time = 0.000011 [sakae@fedora z]$ ./a.out time = 0.000051 time = 0.000010
やはり、初回だけ余分に時間がかかっている。
と、ここまではいいんだけど、測定対象をその都度上記のように時計で挟むのは、馬鹿 らしい。何とかlisp並みにタイムマクロを書いてみろ。
そういう時は、まず名前を決めよう。何が良いかな？ 余り頻出するような名前は却下 だぞ。英文で最も出現頻度が少ないQあたりが良いな。Qで始まる単語、、、クォーツ なんてのはどうだ。水晶って事で正確そう。それで出来たストップウォッチ。 超略して、QSP。これに決めよう。
ヘッダーファイル一つをincludeするだけで使えるようにする事。
[ob: z]$ cat qsp.h
// quartz stopwatch
#ifndef _STDIO_H
#include <stdio.h>
#endif
#include <sys/time.h>
double time_now() {
struct timeval now;
gettimeofday(&now, NULL);
return (double)now.tv_sec + (double)now.tv_usec/1.0e6;
}
double qsp_st, qsp_sp;
int qsp_i;
#define QSP(code) { \
qsp_st = time_now(); \
{ code; } \
qsp_sp = time_now(); \
printf("exec time = %10.6f\n", qsp_sp - qsp_st); \
}
#define QSPn(code, n) { \
qsp_st = time_now(); \
{ for (qsp_i=0; qsp_i<n; qsp_i++){ code; }} \
qsp_sp = time_now(); \
printf("exec time(%d) = %10.6f\n", n, qsp_sp - qsp_st); \
}
使い方は、下記のように上記をincludeしておいて、必要な関数をマクロで包むだけ。 一回だけの実行だと時間が極小になる場合、n回実行するようにした。
#include "qsp.h" QSP( z = cexpl(x) ); QSP( z = cexpl(x) ); QSPn( z = cexpl(x), 1000000 );
こうして、実験出来るようになると、emacsのベンチ内から出る事なくやりたくなる。 そこで、こんなMakefileを用意。C-c c で、コンパイル＆ゴー出来て便利。
cto: qsp.h
cc -g t.c -lm
./a.out
実行例
-*- mode: compilation; default-directory: "~/z/" -*- Compilation started at Sun May 1 10:51:04 make -k cc -g t.c -lm ./a.out exec time = 0.001480 exec time = 0.000017 exec time(1000000) = 2.058454 real=-1 imag=1.2246467991473532071737640294583966e-16 Compilation started at Sun May 1 10:51:07
ｎ回実行した時の、forのオーバーヘッドは如何ほど？ こういうのも億劫なく測定 出来る。（z = cexpl(x), の部分を ;, に置き換えただけ）
exec time(1000000) = 0.002457
と、ここまで、スラスラと開発出来たように涼しい顔をしてるけど、実はそうでは なかったのさ。Lispのマクロ開発にマクロ展開用のmacro-expandが有る。C語の場合は？
[ob: z]$ cc -E t.c
:
{ qsp_st = time_now(); { z = cexpl(x); } qsp_sp = time_now(); printf("exec ti
me = %10.6f\n", qsp_sp - qsp_st); };
{ qsp_st = time_now(); { z = cexpl(x); } qsp_sp = time_now(); printf("exec ti
me = %10.6f\n", qsp_sp - qsp_st); };
{ qsp_st = time_now(); { for (qsp_i=0; qsp_i<1000000; qsp_i++){ z = hoge(1+1*
1.0fi); }} qsp_sp = time_now(); printf("exec time(%d) = %10.6f\n", 1000000, qsp_
sp - qsp_st); };
printf("real=%g\timag=%38.36g\n", creal(z),cimag(z));
こんな風に、展開形を確認出来る。Lispのマクロでは、測定時間と共に与えた式の 結果も表示するようになっている。それも真似んかいというのは却下。C語は型が あるから、対応出来んのよ。こういう時は型も型無しであります。飽き足らない方は、 C++のラムダ式とマクロで経過時間を手軽に測定 を参照ね。
勢いで、マクロ名を QSP なんてしちゃったけど、これってよく考えたら無線界の Q符号じゃん。えーと、QSPって何だっけ？ 法令集を引きずりだしてみたら、 無線電信通信の略符号（第13条関係）別表第二号に出てた。
それによると、QSPって、そちらは...（名称又は呼出符号）へ中継してくれませんか、 ですって。そうか、システムからの応答をオイラーに中継してねって事だ。良い符号を 選んだな。まてまて、もっと良いのがあるぞ。QROしましょうかってやつ。送信出力を 増強しましょうか。増強して64Bitマシンになってくれ。＞ 女房殿。
Q符号ってのは、生活の知恵。混信とかフェージングが有る無線の世界で、普通の 文面には表れないQで始まり、かつ短い記号。間違いなく最短で相手に届く工夫。 デジタル通信（携帯電話）が当たり前の世界では考えられない事情だな。正に、 世界文化遺産だ事。
マクロを書く時の注意点
とまあ、C語のマクロを書いたけど、注意点を少々。
qsp.hでは、結果の表示にprintfを使ってる。これを使うには、stdio.hが必要。 だったら、qsp.h内でincludeしとけばいいんでないかい。それをそのままやっちゃうと、 観測対象のソースコード中でstdio.hをインクルードしてると、2重にインクルード する事になって、コンパイラーに怒られる。
冒頭付近のifndefで囲んでる部分は、その対策。(注: ifdefで使用している値は、OS依存)詳しくは、 2重インクルード防止を参照。
マクロは一行で書く事になっている。逆に言うと、複雑なものは書くな。そういう必要 が有ったら、Lispにスイッチしろって暗に勧めている訳ですよ。 その禁を破るのが、バックスラッシュに続く文字は無視するって逃げ道。バックスリャッシュ の後ろに置いてある改行を、C語のプロセッサーは無視してくれるので、目出度く、 一行になる。そのため、マクロ展開されたソースは見られたものじゃないけどね。 （見るものじゃありません）
qsp.h内で宣言してるtime_nowと変数名は、元のソース上からも見える。見えると 言う事は、名前の衝突の可能性が有ると言う事。これを防ぐ方法は無い。せいぜい、 へんてこりんな名前を使うしかないんだ。
また、コード部分を { } で囲ってるけど、これはガード戦法。コードが外に漏れ出さない ように、閉じ込めている。これは、セキュリティ的には失格だとか。 複数の文からなるマクロは do-while ループで包む ようにするのが、正しい方法だそうです。落とし穴だなあ。do{ .... }while(0) を使え なんて、初めて知ったぞ。
と、色々な注意が必要。ようするに、マクロなんて危ないものは使うなよって、言語 作者に逆らうから、いろいろな注意が必要になってくるんだ。
実例
#include "qsp.h"
int main(){
printf("bye C++\n");
QSPn(
printf("hello C\n");
printf("Hello Scheme\n");
, 2);
return 0;
}
元ソースは、おいらの好き嫌いが３行分書いてあった。ふと、好きを２回唱えると、 時間がかかるか調べたくなった。普通そんな発想しない。これは、例のための例です。 そこで、冒頭（範囲を分かりやすくする為）から始まる２行を追加。
bye C++ hello C Hello Scheme hello C Hello Scheme exec time(2) = 0.000014
IOを伴う処理って時間がかかると思ったら、OSに出力依頼するまでがアプリの 仕事らしく、あっと言う間に完了した。なんか、このマクロ、DSLっぽくないかい。
注: 上記のように複数行をまとめて１回だけ実行したい場合、ただのQSPではコンパイルエラーになる。 QSPn(code; ... code;, 1)で、代用する事。
まてまて、大量に出力する場合も有るだろう。そういう時は、出力を /dev/nullへ 棄てて、IOの影響を軽減する事があるな。この場合には、マクロからの出力も、棄てられて しまって、QSP できないじゃないですか。さあ、どうする。
こういう事もあろうかと、昔の人は、ちゃんと考えていたのさ。stderrっていう 出力端子は、特別な事をしない限り /dev/nullへは行かないよ。で、どうするんだい？
fprintf(stderr, "exec time = %10.6f\n", qsp_sp - qsp_st); \
こんな風に、qsp.h内の該当行を変更するんだ。そうすれば、
$ ./a.out bye C++ hello C Hello Scheme hello C Hello Scheme exec time(2) = 0.000014 $ ./a.out > /dev/null exec time(2) = 0.000002
これで、多い日も安心。ああ、IOは速いって言ってたけど、結構画面に見せるか 見せないかで差が有りそうだなあ。
: hello C Hello Scheme exec time(2000) = 2.025566 $ ./a.out > /dev/null exec time(2000) = 0.000533
口に出して唱える勤行は、それなりに時間がかかる。対して、心に秘しての勤行は、 あっと言う間ですよ。
まあ、これは、VMWAREの中でFreeBSDが動いていて、そこにPuTTYでssh接続してるから、 通信に膨大な時間がかかっているって事ですな。
何度か画面出力させてみると、exec time(2000) = 0.087034 ぐらいから上記の ように２秒近くまでばらつくなあ。これはきっと、早くWindows10にせいウィルスの 嫌がらせに違いない。
Makefile
上で挙げた Makefileは、必ずコンパイルしてから実行されてた。小さいファイルなら コンパイルが直ぐに終るから余り気にする必要は無いけど、大きなファイルだと イライラの元になる。
そこで、下記のように、ターゲットに最終バイナリーを指定した。これがコンパイルに的を 絞った、普通の書き方だ。
a.out: qsp.h t.c
cc -g t.c -lm
./a.out
で、a.outが無い状態から、実行してみると、
$ make cc -g t.c -lm ./a.out Hello Scheme exec time(1) = 0.001859 $ make `a.out' is up to date.
初回は、実行ターゲットが無いから、コンパイルして実行。でも、２回目は、 a.outが作成されているので、makeはそこで安心してしまって、やる事はございません と報告して、実行を打ち切った。
makefileの最初の行は、a.outってqsp.h若しくはt.cより後で出来上がっていたら、 コンパイルの必要無いからねって宣言。makeはまず、それを確かめる。満足してたら それで終了。してなかったら、しゃーない、後に続くコマンド行を順番に実行して くかってのを、自動的にやるのだった。
一度、バイナリーを実行したら、a.outを消しておけ。それじゃ、毎回コンパイル されてしまって、元の木阿弥。
で、解決策は無いかと探してみました。
$ cat makefile
run:
@make -f Makefile
./a.out
こんな風に makefileを別に用意します。普通はconfigure等で、Makefileが作られているはずです。 それとかぶらない、小文字のmakefileを用意した訳です。これが親になります。
ちょっと実行してみます。条件として、a.outは無いって所からスタートです。
$ make cc -g t.c -lm ./a.out hello C exec time(1) = 0.000730 $ make `a.out' is up to date. ./a.out hello C exec time(1) = 0.000784
一回目はa.outが無いから、コンパイルしてから実行されました。２回目は、a.outが 出来上がっているにも関わらず、実行してます。これで目的達成。
$ make
cc -g t.c -lm
t.c:6:19: warning: missing terminating '"' character [-Winvalid-pp-token]
printf(hello C\n");
^
:
1 warning and 2 errors generated.
*** Error code 1
Stop.
make[1]: stopped in /usr/home/sakae/z
*** Error code 1
Stop.
make: stopped in /usr/home/sakae/z
コンパイルエラーが発生すると、勿論、実行はされません。
どんな理屈で動くのか？ makefileとMakefileが有った場合、makefileの方が優先 されます。よって、普通にmakeって指定したのは、make -f makefile を実行 したのと同じ事になります。
makefileの中に、@make -f Makefile が書いてあります。頭の@は、このコマンド行の 表示を抑制しつつ実行してって意味。某Makefileみたいなcallを使って大事な表示を 隠しちゃう所業よりは悪質じゃないと思うぞ。単にちょっとしたトリックです。
ゆえに小供のmakeが起動され、a.outが無かったりソースの変更が有る場合、 コンパイルが実施されます。 コンパイルが失敗すれば、親のmakeはそこで実行を打ち切ります。よって、./a.outは 実行されません。
コンパイル済みで何もやる事が無い場合、@makeは成功したと みなされて続きの、./a.outが実行されるって仕掛けです。
最初、これと同様の事を シェルのエラーステータス $? を使って行おうと したけど、makefileは、shellスクリプトに有らずって事で、あえなく失敗。 しょうがないので、 5.4 コマンドのエラー をヒントに、裏技（って程でもないけど）を思いつきました。
makeの内部関数として、shellなんてのが有るそうな。これを使うとshellの実行結果を 取り込めるとか。ひょっとして便利ならいいじゃないののGNU makeだけの機能でしょうか？ BSD makeでも動く、makefileを書きたいものです。
実戦投入
そんじゃ、以前にやったfemtolispに、マクロを適用して内部の特定部分の実行時間を 測ってみますかね。
qsp.hをfemtolispのdir内にコピーします。次に親分になるmakefileをコピーします。 そしてちょっと変更。
sakae@uB:~/femtolisp$ cat makefile
run:
@make -k -f Makefile
./flisp &
@sleep 3
最初のmakeに -k が付いているのは、多少のエラーならmakeを実行してねって意味。 emacsからコンパイルを指定すると、make -k がデフォになってて、なるべく一度の コンパイルでエラーを叩き出し、修正してねって配慮されてます。勿論、リンクエラーとか fatalなエラーが発生した場合、そこでコンパイルは中止されます。
flispをバックグラウンドで起動してるのは、次のコマンド行を実行したいから。 emacsのコンパイル結果表示バッファーでは、会話型アプリと通信出来ませんから そこで立ち往生するのを防止（強制的にmakeの実行中止）するためです。
プローブを仕掛けるのは、flmain.cの中で、システムイメージを読み込んでいる所。 冒頭の方で、qsp.hをインクルードするのを忘れない事。
QSPn(
if (fl_load_system_image(f))
return 1;
, 1);
実行してみます。
sakae@uB:~/femtolisp$ make make[1]: Entering directory '/home/sakae/femtolisp' gcc -O2 -DNDEBUG -falign-functions -Wall -Wno-strict-aliasing -Illt -DUSE_COMPUTED_GOTO -c flmain.c -o flmain.o gcc -O2 -DNDEBUG -falign-functions -Wall -Wno-strict-aliasing -Illt -DUSE_COMPUTED_GOTO flisp.o builtins.o string.o equalhash.o table.o iostream.o flmain.o -o flisp llt/libllt.a -lm libflisp.a cd tests && ../flisp unittest.lsp exec time(1) = 0.005955 all tests pass make[1]: Leaving directory '/home/sakae/femtolisp' ./flisp & exec time(1) = 0.005669 ; _ ; |_ _ _ |_ _ | . _ _ ; | (-||||_(_)|__|_)|_) ;-------------------|---------------------------------------------------------- > sakae@uB:~/femtolisp$
flmain.cが再コンパイルされて、テストが走って、その時は5.9msでロードされた。 会話型のflispを起動した時は、5.6msだったとな。
同じ要領で、
QSP( fl_init(512*1024); );
イニシャライズの所は、exec time = 0.001066 でした。
自分で言うのもなんだけど、このマクロなかなか便利。
調子に乗ってgoshでもやってみた。仕掛けた所は、src/vm.cの中でScm_ReadしたS式を コンパイルしてる所。
1351ScmObj Scm_VMEval(ScmObj expr, ScmObj e)
1352{
1353 ScmObj v = SCM_NIL;
1354 int restore_module = SCM_MODULEP(e);
1355 ScmVM *vm = theVM;
1356
1357QSP( v = Scm_Compile(expr, e); );
1358 if (SCM_VM_COMPILER_FLAG_IS_SET(theVM, SCM_COMPILE_SHOWRESULT)) {
1359 Scm_CompiledCodeDump(SCM_COMPILED_CODE(v));
1360 }
結果は、
gosh> (define hoge (lambda(x)(* x x x x))) exec time = 0.000158 hoge gosh> (hoge 33) exec time = 0.000063 1185921