プロセスの所要時間を計る（vDSPメモのおまけ）

こないだのvDSPのベンチマークで、計算の所要時間を測った。単に経過時間だけを測ると、他のプロセスに費やした時間も含まれてしまう。unixにはそのプロセス自身とそのプロセスの子プロセスの所要時間だけを測るシステムコールがある。

古いシステムコールで30年前からある骨董品（「えー、漫才の骨董品で」「ぽん」、おお懐かしや捨丸師匠）。times()という名前で

#include <sys/times.h>
clock_t	times(struct tms *tbuf);

昔はclock_tはlongだった。MacOS Xではunsigned longにtypedefされている。

引数の構造体はsys/times.hの中で

struct tms {
	clock_t	tms_utime;	/* [XSI] User CPU time */
	clock_t	tms_stime;	/* [XSI] System CPU time */
	clock_t	tms_cutime;	/* [XSI] Terminated children user CPU time */
	clock_t	tms_cstime;	/* [XSI] Terminated children System CPU time */
};

となっている。times()を呼ぶと引数の構造体に値が入って帰ってくる。 構造体のメンバの意味は、コメントにもちょこ、と書いてあるけど

tms_utime	そのプロセスがユーザレベルの実行に費やした時間
tms_stime	そのプロセスが発行したシステムコールで費やした時間
tms_cutime	子プロセス全部が費やしたユーザ時間の合計
tms_cstime	子プロセス全部が費やしたシステム時間の合計

となっている。つまり、他のプロセスは関係なく自分自身が消費した時間だけを知ることができる。また、times()自身はブートしてからの時間を返す。

時間の単位は、昔はヘッダに書いてあって適当なシンボルにdefineされていた。今、sys/times.hを見ても見当たらない。よくわからないけど僕が初めてこのシステムコールを使ったとき（System VのHP-UX）は1/100秒だった。

こないだのvDSPのベンチマークではこのシステムコールを使って所要時間を測るために、こんなのを書いた。

struct rtms {
    clock_t treal;
    struct tms  t;
};

void    tStart(struct rtms * tstart)
{
    tstart->treal = times(&(tstart->t));
}

struct rtms  tMeasure(struct rtms *tstart)
{
    struct rtms te;
    struct tms  tstop;
    te.treal = times(&tstop) - tstart->treal;
    te.t.tms_utime = tstop.tms_utime - tstart->t.tms_utime;
    te.t.tms_stime = tstop.tms_stime - tstart->t.tms_stime;
    te.t.tms_cutime = tstop.tms_cutime - tstart->t.tms_cutime;
    te.t.tms_cstime = tstop.tms_cstime - tstart->t.tms_cstime;
    return te;
}

ようするに2回測って差をとっているだけ。実時間も一緒に格納するために構造体を入れ子にしてある。 これで、測りたい作業の前後で挟んで

    struct  rtms  tstart, tperi;
    tStart(&tstart);
            //ここの所要時間を測る
    tperi = tMeasure(&tstart);

とすれば、実際に経過した時間と、プロセスに費やした時間がわかる。

試しにこないだのvDSPのベンチマークのmain()に

int main (int argc, const char * argv[]) {
    struct rtms tb, te;
    tStart(&tb);
    floatCompare();
    doubleCompare();
    te = tMeasure(&tb);
    fprintf(stderr, "real = %d\tuser = %d\tsystem = %d\n",
            te.treal, te.t.tms_utime, te.t.tms_stime);
    return 0;
}

として入れてみると、

real = 1690	user = 770	system = 55

だった。実際の経過時間が17秒で、そのうちこのプロセスが消費した時間が7.7秒、システムコールは0.5秒だった、ということ。なんでシステムコールに時間がかかってるんだ？なんにもしてないのに。context switchにこれだけ費やしてるということか。まあええけど。

昔のマシンは処理能力が低く、デバグのときだけでなく実際の実行時にもパフォーマンスを評価する必要がよくあった。そのとき単なる所要時間では相対的に重かったdaemonプロセスやシステムコールが含まれてしまうのでこういった測定法が必要だった。今ではできるだけ正確に所要時間を計りたいとか、いろんなプロセスが走っている中で評価したいとか以外では、もうあまり必要ないかも知れない。でも、まあこういう化石の発掘も面白かろ。