技術情報

技術情報

プロファイル測定

2007年11月30日

技術文書トップへ

測定ツールとその実装

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

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

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

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

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

ページトップ

各関数の先頭からの 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

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
#include 
int f(int);
int main(int argc, char **argv) {
int i;
for(i = 0; i < 10000; i++)
f(7);
exit(0);
}
int f(int depth) {
int d, i;
d = depth - 1;
for(i = 0; i < depth; i++)
f(d);
return 0;
}

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 
#include 
#include 
#include 
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("%f\n", (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)

スレッド数 1:
6002     40.1713  libc-2.3.2.so            (no symbols)
1639     10.9698  vmlinux                  mark_offset_tsc
673       4.5044  vmlinux                  apic_timer_interrupt
668       4.4709  vmlinux                  default_idle
453       3.0319  vmlinux                  timer_interrupt
365       2.4429  vmlinux                  find_busiest_group
358       2.3961  bash                     (no symbols)
347       2.3225  vmlinux                  _spin_lock
294       1.9677  mt                       f
254       1.7000  vmlinux                  scheduler_tick
スレッド数 2:
20827    46.7844  libc-2.3.2.so            (no symbols)
4488     10.0815  vmlinux                  _spin_lock
2599      5.8382  vmlinux                  futex_wake
1504      3.3785  vmlinux                  futex_wait
1410      3.1673  vmlinux                  mark_offset_tsc
1372      3.0820  vmlinux                  sysenter_past_esp
937       2.1048  vmlinux                  drop_key_refs
645       1.4489  vmlinux                  default_idle
594       1.3343  vmlinux                  queue_me
588       1.3208  mt                       f
スレッド数 4:
32288    27.3093  vmlinux                  _spin_lock
27406    23.1800  libc-2.3.2.so            (no symbols)
6155      5.2059  vmlinux                  futex_wait
6088      5.1492  vmlinux                  futex_wake
4422      3.7401  vmlinux                  schedule
3695      3.1252  vmlinux                  sysenter_past_esp
2943      2.4892  vmlinux                  drop_key_refs
2713      2.2947  vmlinux                  queue_me
2059      1.7415  vmlinux                  find_vma
2003      1.6941  vmlinux                  find_busiest_group
1489      1.2594  vmlinux                  __get_user_4
スレッド数 8:
35957    28.3251  vmlinux                  _spin_lock
31088    24.4895  libc-2.3.2.so            (no symbols)
7048      5.5521  vmlinux                  futex_wake
7030      5.5379  vmlinux                  futex_wait
4251      3.3487  vmlinux                  sysenter_past_esp
3219      2.5358  vmlinux                  drop_key_refs
3215      2.5326  vmlinux                  schedule
3196      2.5176  vmlinux                  queue_me
2291      1.8047  vmlinux                  find_vma
1716      1.3518  mt                       f

この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を使うこともできますが、ここでは割愛します。

関連記事

Linux
2008年1月15日
ダンプ解析講座
Linux
2008年8月15日
hping3によるフィルタリングルールの検証
負荷分散
2007年9月1日
負荷分散型クラスタ解説 - UltraMonkey
お気軽にお問い合わせください

VA Linuxでは、「障害解析・サポートサービス」をご提供しております。
サービスに関する詳細は、「障害解析・サポートサービス (VA Quest)」の説明ページをご覧ください。

お問い合わせフォームはこちら
ページトップ