setitimer システムコールを使って簡単なプロファイラを作る

2006年3月 5日

setitimer システムコールを使って簡単なプロファイラを作る

setitimer システムコールを使うと一定時間間隔でシグナルを発生させることができます。頻繁にシグナルを発生させて、「シグナルが呼ばれたときにどこにいたか」を記録していけばサンプリング方式のプロファイラを作ることができます。

以下のコードは x86 の Linux を対象とした簡単なプロファイラです。prof_start() では setitimer() を使ってプロファイルをとるための下準備をしています。シグナルハンドラ prof_handler() ではシグナルが呼ばれた時点のコンテキストの情報からプログラムカウンタを取り出し、fwrite() でファイルに書きこんでいます。

LD_PRELOAD するだけで使えるよう、 prof_start() と prof_end() にそれぞれ constructor と destructor を指定しています (main() の前に関数を呼ぶを参照)。

#include <assert.h>
#include <stdio.h>
#include <sys/time.h>
#include <signal.h>
#include <asm/ucontext.h>

static const int FREQ = 100; // samples per sec
static FILE *prof_fp;

static void
prof_handler(int signal, siginfo_t *siginfo, void *ucontext) {
    struct ucontext *uc = (struct ucontext *)ucontext;
    unsigned long int pc = uc->uc_mcontext.eip;
    fwrite(&pc, sizeof(pc), 1, prof_fp);
}

static void __attribute__((constructor))
prof_start() {
    prof_fp = fopen("prof.out", "w");
    assert(prof_fp != NULL);

    struct sigaction sa = {
        .sa_sigaction = prof_handler,
        .sa_flags = SA_RESTART | SA_SIGINFO,
    };
    sigemptyset(&sa.sa_mask);
    assert(sigaction(SIGPROF, &sa, NULL) == 0);

    struct itimerval itimer = {};
    itimer.it_interval.tv_sec = 0;
    itimer.it_interval.tv_usec = 1000000 / FREQ;
    itimer.it_value = itimer.it_interval;
    assert(setitimer(ITIMER_PROF, &itimer, 0) == 0);
}

static void __attribute__((destructor))
prof_end() {
    fclose(prof_fp);
}

上のプログラムを prof.so としてビルドします。

% gcc  -fPIC -shared -o prof.so prof.c

prof.so を使ってプロファイルを取るには LD_PRELOAD=prof.so を指定してプログラムを実行します。

% cat test.c
void f() {
    for (volatile long long i = 0; i < 1000000000; ++i);
}

void g() {
    for (volatile long long i = 0; i < 1000000000; ++i);
}

void h() {
    for (volatile long long i = 0; i < 1000000000; ++i);
}

int main() {
    f();
    g();
    h();
    return 0;
}
% gcc -std=c99 test.c
% time LD_PRELOAD=./prof.so ./a.out
17.30s total : 17.29s user 0.00s system 99% cpu

プロファイルデータは prof.out に記録されています。prof.out にはプログラムカウンタのアドレスが書き込まれています。下のシェルスクリプトではアドレスを addr2line を用いて関数名に変換して、それぞれの関数内でシグナルが発生した回数を数えています。

% cat prof.sh
#! /bin/sh
#! /bin/sh
BINARY=${1:-a.out}
PROF=${2:-prof.out}
cat $PROF |\
ruby -e 'puts ARGF.read.unpack("L*").map {|x| x.to_s(16) }'|\
addr2line -f -e $BINARY  | perl -nle 'print if $. % 2 == 1' |\
sort |uniq -c |sort -nr

% sh prof.sh
    577 h
    576 g
    575 f

関数 f(), g(), h() は同じ処理を行っているため、頻度はそれぞれ 575, 576, 577 とほぼ同じ数字になっています。サンプリングの頻度は 100 hz なので、各関数は約 5.76 秒かかっていることがわかります。

ちなみに、 gcc -pg + gprof でも時間の計測は profil(2) または setitimer(2) を使ってサンプリングベースで行っているようです (参考: GNU gprof - Implementation と Binutils の gprof/hist.c)。

問題点

上のプロファイラには次のような問題があります。

関数がどこから呼ばれてきたか (コールグラフ) をまったく考慮していない
アドレスから関数名への変換を addr2line に頼っているが、addr2line は共有ライブラリ内の関数のシンボルは見つけられない
システムコール内の処理はプロファイリングできない
サンプリング頻度が100 hz と低いため、実行時間の短いプログラムでは意味のあるプロファイルを取れない

最初の問題は、コールグラフをスタックトレースから取得すれば解決できます (C でバックトレース表示を参照)。

2番目の問題は、ldd の出力を元に共有ライブラリに対しても addr2line で探しに行けば解決できます。ただし、addr2line に渡すアドレスを相対アドレスに戻すなどの工夫が必要になります。また、dlopen した共有ライブラリには対応できません。

3番目と4番目の問題は setitimer を使う限りおそらく解決できません。サンプリング数の 100 hz (1秒に100回) は、手元の環境の Linuxカーネルの割り込み頻度 100 hz に合わせています。より高い精度のサンプルを取るには Sysprofや OProfile などのようにカーネルスペース内で処理を行う必要があると思われます。

なお、Linux の割り込み頻度は長らく 100 だったものの、カーネル 2.6 で 1,000 hz に変更され、さらに 2.6.13 から 250 hz になったそうです。参考: Linux Kernel Watch 8月版　割り込み頻度変更で消費電力は低下するか？

まとめ

setitimer システムコールを使ってサンプリング方式の簡単なプロファイラを作る方法を紹介しました。setitimer は他にもいろいろおもしろいことに使えるのではないかと思います。

p.s.
更新履歴兼雑記: いろいろなプロファイラに触発されて書きました。

bkブログ

2006年3月 5日

setitimer システムコールを使って簡単なプロファイラを作る

問題点

まとめ