プロファイラを実装する方法 - Mosh 開発
そろそろ簡単なプロファイラが欲しくなったので実装します。
作るプロファイラは gprof などのプロファイラでは知ることのできない Scheme の世界のこと、例えば「どのScheme 手続きの実行に時間がかかっているか？」などを知るためのものです。
作ってみたら意外と簡単だったので情報をまとめておきます。
仕組み
世間で使われているプロファイラがどういう仕組みで動いていて、どのような限界があるか？については、omoさんのプロファイラのしくみを読むと良いでしょう。
必要な機能
gprof などのプロファイラを使っていると以下の2つの機能が必要そうだということが分かります。
- 手続きの呼ばれた回数とその名前の表示
- 手続きが費やした CPU 時間とその割合の表示
手続きの呼ばれた回数とその名前の表示
厳密なデータが欲しいので単純に VM の CALL 命令時に呼ばれた手続きを記録をします。
記録作業自体が大きな負荷になっては意味がないので、極力単純な仕組みにします。
以下擬似コードですが、こんな感じ。case 文は VM ループの中にあると思ってください。
case(CALL) { static int count = 0; samples[count++] = proc; // 今から call しようとしている手続きを配列に格納
samples はあらかじめ確保しておいた、記録用の配列です。
samples が溢れそうになったらどうしたらよいでしょうか。
結局記録したいのは (手続き 呼ばれた回数) のペアなので、その時点の samples を走査して結果を HashTable に記録し、samples を空にしてあげれば良いです。
一つ注意しなければいけないのは、この走査の作業中は後述のタイマーを一時的に OFF にすることです。そうでないとのの作業自体もプロファイリングの対象となってしまいます。
手続きが費やした CPU 時間とその割合の表示
この情報をとるには、定期的なサンプリングが有効そうです。
つまり一定間隔のタイマーで割り込んで、そのとき VM が何をしていたか？を調べるわけです。
より具体的にはタイマーで割り込んで、そのときの VM のレジスタやその他の情報から実行中の手続き情報を得ることになります。
ただし単純なタイマー割り込みを使うと、自分以外のプロセスがたくさん存在する場合に CPU 時間をどれほど費やしているかを正しく知ることはできません。
そのため SIGPROF というシグナルを利用します。
以下のような骨組みを持ったコードで情報を記録します。
記録場所や方法は、前述の samples 配列と同じような形になると思います。
#include <stdio.h> #include <signal.h> #include <stdlib.h> #include <sys/time.h> void signal_handler(int signo) { printf("%s\n", __func__); // ここで VM の各種レジスタ情報により実行中のクロージャなどを得て記録 } int main() { struct sigaction act; act.sa_handler = &signal_handler; // set signal_handler act.sa_flags = SA_RESTART; // restart system call after signal handler if (sigaction(SIGPROF, &act, NULL) != 0) { fprintf(stderr, "sigaction failed\n"); exit(1); } const int INTERVAL_USEC = 10 * 1000; struct itimerval tval, oval; tval.it_interval.tv_sec = 0; tval.it_interval.tv_usec = INTERVAL_USEC; tval.it_value.tv_sec = 0; tval.it_value.tv_usec = INTERVAL_USEC; setitimer(ITIMER_PROF, &tval, &oval); while (1) { // VM Loop } // 後始末 return 0; }
出力例
というわけで出来ました。
dekisugi% ./mosh -p match.scm time% msec calls name 8 50 906645 generic-assoc 3 20 9022 set-intersect 1 10 269 parse-lambda-vars 1 10 8113 pass1/sexp->iform 0 0 896744 eq? 0 0 108543 $map1 0 0 91196 foldr1 0 0 57297 memq 0 0 55949 append2 0 0 38445 apply 0 0 35247 append 0 0 32543 match:vector-structures 0 0 22018 set-union 0 0 21012 set-cons 0 0 10595 list 0 0 8959 pass1/expand 0 0 8869 equal? 0 0 8739 pass3 0 0 8604 find10 0 0 6832 caddr 0 0 6048 length 0 0 5396 map1 0 0 4496 pass3/symbol-lookup 0 0 4487 pass3/compile-refer 0 0 4457 cdddr 0 0 3636 pass2/optimize 0 0 3008 pass1/refer->iform 0 0 2824 pass3/compile-arg 0 0 2561 $label 0 0 2425 $local-ref 0 0 2327 car 0 0 2324 assq 0 0 2296 pass3/$local-ref 0 0 2284 acons ** 580 ** total
