プロファイル測定

linux での代表的なプロファイル測定の実装を解説します。
関連して、マルチスレッドプログラムのプロファイル測定の注意点を述べます。

なお、gprof、oprofile の基本的な使い方は既知のものとし、本書では特に解説はいたしません。

測定ツールとその実装　- gprof

linux では gprof は glibc に付属するツールです。ここでは glibc-2.3.6 を使って説明します。

gprof によるプロファイル測定を行うには、 -pg コンパイルオプションをつけてプログラムをコンパイルします。
このことにより、プログラムに以下の処理が追加されます。

各関数の先頭からの mcount 関数の呼出し
プログラム起動時の setitimer() の実行
プログラム終了時の gmon.out の書き出し

各関数の先頭からの mcount 関数の呼出し

-pg オプションをつけてコンパイルすると、関数の先頭から mcount への呼出しが行われます。

例えば i386 アーキテクチャでは以下のようになります。

$ cat a.c
int
f(int a) {
	return a;
}
$ cc -pg -S a.c
$ cat a.s
    .file   "a.c"
    .text
.globl f
    .type   f, @function
f:
    pushl   %ebp
    movl    %esp, %ebp
    call    mcount
    movl    8(%ebp), %eax
    popl    %ebp
    ret
    .size   f, .-f
    .section        .note.GNU-stack,"",@progbits
    .ident  "GCC: (GNU) 3.3.5 (Debian 1:3.3.5-13)"

mcount の実体は glibc-2.3.6/gmon/mcount.c にあります。


														_MCOUNT_DECL(frompc, selfpc) /* _mcount; may be static, inline, etc */ {

ここで、_MCOUNT_DECL となっているのは、この関数には呼出し元とその親のプログラムカウンタ（それぞれ selfpc、frompc）が渡される必要があり、アーキテクチャ依存のコードが必要になるため、アーキテクチャ毎の違いを吸収するためにマクロになっています。

この関数は、frompc と selfpc の組に対応するカウンタをインクリメントするので、各関数が何回、どこから呼ばれたかがわかります。

プログラム起動時の setitimer() の実行

プログラム起動時に


														__monstartup ((u_long) TEXT_START, (u_long) &etext);

が実行されます。
__monstartup は gmon/gmon.c にあり、プロファイル測定用テーブルの初期化を行い、


														__profil((void *) p->kcount, p->kcountsize, p->lowpc, s_scale);

によって、一定実行時間毎にプログラムカウンタの位置に対応するカウンタがインクリメントされるようになります。
profil は BSD 系 UNIX などではシステムコールですが、linux ではタイマ割り込みとシグナルハンドラを用いて実装されています。
__profil の定義は sysdeps/posix/profil.c にあり、
__setitimer(ITIMER_PROF, …) を実行し、一定 CPU 実行時間毎に SIGPROF シグナルが発生するようになります。linux-2.6.11 以前では、この setitimer はスレッド毎なので、マルチスレッドプログラムでは、 gmon-helper.o（※1）などを使用して、スレッド毎に setitimer を実行する必要があります。

プログラム終了時の gmon.out の書き出し


														atexit (&_mcleanup);

が実行され、プロセス終了時に _mcleanup から呼ばれる write_gmon 関数から上記のカウンタの値がファイルに書き出されます。
デフォルトの出力ファイル名は gmon.out ですが、環境変数 GMON_OUT_PREFIX で変更することができます。
_mcleanup は atexit を利用して呼ばれるので、プロセスの異常終了時には gmon.out は生成されません。

上記の3つの処理によって、以下の情報を取得することができます。

各関数の実行回数
コールグラフ
各関数の実行時間

oprofileは主にカーネルで実装されたプロファイル測定ツールです。gprofでは一定間隔で呼ばれるSIGPROFのシグナルハンドラがプログラムカウンタの値をサンプリングしていましたが、oprofileではそれはカーネルによって行われています。
以下にlinux-2.6.22、oprofile-0.9.2、i386アーキテクチャでの実装を簡単に解説します。

oprofileの実装

oprofileの実装はカーネル内の以下の箇所にあります。
arch/*/oprofile/
drivers/oprofile/

arch/i386/oprofile/の下のコードは主に以下の処理を行います。

CPUのperformance(-monitoring)counterを設定し、一定時間ごとにNMIを発生させます。ただし、hlt命令でCPUが休止している時間はカウントされません。(※2)
register_die_notifier関数でoprofile用のNMIハンドラを登録します。

このnotifierから呼ばれる*_check_ctrs関数から、以下のように割り込み発生時点の実行箇所が記録されます。


														if (CTR_OVERFLOWED(low)) { oprofile_add_sample(regs, i);

local APICがない古いCPUなどでは、割り込みソースとして以上で説明したものではなくNMI timerが用いられますが、ここでは説明は省略します。
oprofile_add_sample関数以降の処理は、drivers/oprofile/cpu_buffer.cのコードが主であり、下記のような処理が行われます。また、これはNMIハンドラから呼ばれる処理なので、最小限のものとなっています。

add_sample関数でoprofile_add_sampleで渡されたアドレスをCPU毎のバッファに記録します。
backtrace
archの下のアーキテクチャ依存のコードがスタックを辿り、その結果をoprofile_add_trace関数に渡します。
スタックを辿るにはプログラムはフレームポインタを有効にしてコンパイルされている必要があります。

CPU毎のバッファの内容は、workqueueを利用して定期的に呼ばれるsync_buffer関数で、グローバルなイベントバッファにコピーされます。
その時に、ユーザーランドのアドレスは対応する実行ファイルとそのファイルオフセットに変換されます。
イベントバッファのデータは、ユーザーランドのoprofiledデーモンがread（2）して記録し、opreport（1）などはそれを参照してプロファイル結果を表示します。
oprofileではカーネル内のプロファイルも取得できますが、今回はそれは扱いません。

マルチスレッドプログラムでの注意事項

gprofの節で述べたように、linuxカーネルのバージョンによってはsetitimerの対処が必要となります。
また、mcountが使用するカウンタのデータはスレッド間で共有され、mcountはリストのポインタの操作を行うので複数スレッドからmcountが同時に呼ばれるとデータの破壊がおきることがあります。


														_MCOUNT_DECL(frompc, selfpc) /* _mcount; may be static, inline, etc */

 {

     register ARCINDEX *frompcindex;

     register struct tostruct *top, *prevtop; register struct gmonparam *p;

     register ARCINDEX toindex;

     int i;

     p = &_gmonparam; /* * check that we are profiling * and that we aren’t recursively invoked. */ 

     if (atomic_compare_and_exchange_bool_acq (&p->state, GMON_PROF_BUSY,GMON_PROF_ON)) return;

上記に示したようにmcountにそのような場合の対策となるコードがありますが、コンパイルオプションによっては atomic_compare_and_exchange_bool_acq が有効にならないことがあります。
興味のある読者は下記を見てみるとよいでしょう。


														glibc-2.3.6/include/atomic.h sysdeps/i386/i486/bits/atomic.h sysdeps/generic/bits/atomic.h

atomic_compare_and_exchange_bool_acqが意味のある排他処理となるには、i486以降で使える命令を使用する必要があり、全てのCPUで動くようにlibcがコンパイルされている場合は、sysdeps/generic/bits/atomic.hの排他の効果を持たないダミー実装が用いられます。
例えばDebian sargeでは、スレッドを使う場合はプロファイリングを無効にするという回避策がとられています。

測定例

本章に記載の内容は、以下の環境において測定した結果です。

Linux 2.6.10
Debian oldstable(sarge)

mcountのオーバーヘッド

mcountのオーバーヘッドは意外に大きいものです。例として、次に示すような関数の呼び出し回数が多いプログラムを使って調べてみます。

overhead.c

mcountの実行時間はgprofの出力では省略されますが、この例ではどういうわけかmcountで使われているはずの時間がfの実行時間として表示されています。
mcountで消費される時間は、例えばoprofileを使って調べることができます。


														$ sudo opcontrol –start –vmlinux=/usr/src/linux-2.6.10/vmlinux 

 $ sudo opcontrol –reset 

 $ ./overhead_p 

 $ sudo opcontrol –stop 

 $ opreport -l samples % app name symbol name 283942 84.6888 libc-2.3.2.so (no symbols) 19095 5.6953 overhead_p f

両者の比が、overheadとoverhead_pの実行時間比を見比べると似たような結果となっています。opreport -dを使うことで、実際にこのlibcの消費時間のほとんどがmcountによるものであることが確認できますが、似た手順を次の例で行うためその手順は省略します。

マルチスレッドプログラム

作為的ではありますが、以下のモンテカルロ法で円周率を計算するプログラムを例とします。

mt.c

#include <stdio.h>
#include <stdlib.h>
#include <pthread.h>
#include <inttypes.h>
void *f(void *);
int main(int argc, char **argv) {
    int i, nthreads = 1, ntries = 1000000, r = 0;
    pthread_t *threads;
    void *p;
    if (argc == 2) {
        nthreads = atoi(argv[1]);
        ntries /= nthreads;
    }
    if ((threads = malloc(sizeof(pthread_t) * nthreads)) == NULL)
        exit(1);
    for(i = 0; i < nthreads; i++)
        if (pthread_create(threads + i, NULL, f, (void *)(intptr_t)ntries) != 0)
            exit(1);
    for(i = 0; i < nthreads; i++)
        if (pthread_join(threads[i], &p) != 0)
            exit(1);
        else
            r += (intptr_t)p;
    printf("%fn", (r * 4.0) / (ntries * nthreads));
    exit(0);
}
void *f(void *arg) {
    int i, j, n = (intptr_t)arg;
    double x, y;
    j = 0;
    for(i = 0; i < n; i++) {
        x = ((double)random()) / RAND_MAX;
        y = ((double)random()) / RAND_MAX;
        if ((x * x + y * y) <= 1)
            j++;
    }
    return (void *)(intptr_t)j;
}

CPUが複数あるマシンでは、スレッド数を1より大きくすることで並列化によるスピード向上が得られるはずですが、そうはならないようです。


														$ cc -o mt -g -O -Wall mt.c -lpthread
$ time ./mt
    3.141664
    real    0m0.252s
    user    0m0.251s
    sys     0m0.001s
$ time ./mt 2
    3.143656
    real    0m0.868s
    user    0m0.960s
    sys     0m0.547s
$ time ./mt 4
    3.141632
    real    0m1.292s
    user    0m2.256s
    sys     0m2.210s
$ time ./mt 8
    3.143244
    real    0m1.356s
    user    0m2.124s
    sys     0m3.250s

Debian sargeでは、上述（マルチスレッドプログラムでの注意事項）の問題のため、gprofで測定するにはlibcの再コンパイルが必要になり、少し手間がかかります。
以下ではoprofileを使って調べます。oprofileのデータは前節と同様に以下のようにして収集しました。


														$ sudo opcontrol --start --vmlinux=/usr/src/linux-2.6.10/vmlinux
$ sudo opcontrol --reset
$ ./mt <引数>
$ sudo opcontrol --stop

opreport -l の出力（上位10）

このopreport -lの出力の3カラム目がvmlinuxとなっているものはカーネル内の関数であることを表しています。futexがロック関係の処理であることを知っていれば、この時点でロック競合だろうと見当はつきますが、今回のお題目はユーザーランドのプロファイリングなので、opreport -dを使ってlibcの中をみてみます。
スレッド数8の時に、opreport -dの出力から、libcの中で10%以上の時間を使っている命令を下に列挙します。スレッド数2、4の時も各命令の比率は若干変化しますが、ほぼ同様です。


														0002baee 6214     19.9884
0002bb1c 5570     17.9169
000e4266 4358     14.0183
000e4287 5494     17.6724

アドレスと関数の対応は、
$ objdump -T libc-2.3.2.so |sort
とすることで取得でき、前2者がrandomです。randomの実装をみてみると、下記のとおりとなっています。

long int
__random ()
{
      int32_t retval;
      __libc_lock_lock (lock);
      (void) __random_r (&unsafe_state, &retval);
      __libc_lock_unlock (lock);
      return retval;
}

これは予想通りの結果といえます。途中経過は割愛しますが、残りの2つの命令は、
nptl/sysdeps/unix/sysv/linux/i386/i486/lowlevellock.S
で定義された__lll_mutex_lock_waitであり、この__libc_lock_lockの実装の一部となります。

以上で、やや特殊なものではありますが性能分析例を含むlinuxにおける代表的なプロファイル測定ツールであるgprofとoprofileの実装解説を終了します。

※1　http://sam.zoy.org/writings/programming/gprof.htmlを参照してください。
※2　使うperformance counterを違うものに設定することで、一定時間ごとでないNMIを使うこともできますが、ここでは割愛します。

測定ツールとその実装

測定ツールとその実装 - gprof