2007-08-23

プロファイラのしくみ

UNIX 偏向文書 artu の中で "Measure Before Optimizing" と説く Raymond は, 同時にプロファイラの計測機構 (instrumentation) がもたらすノイズについて注意を促している. 私のプロファイラ信仰に不安が翳を落とす.

gprof

ノイズはさておき, そもそもプロファイラはどんな仕組みで速度を測っているんだろう. gprof のマニュアル によると, GNU 一族のプロファイラは次のように実装されている: まず "-pg" オプションつきの gcc でソースをコンパイルする. この指示を受けたコンパイラは各関数の冒頭に "mcount" という名前の関数呼出しを加える. リンクする C のランタイムも専用バージョン (gcrt0.o) に差し替わる. このランタイムは裏で profil() 関数を使いタイマを仕掛ける. そのタイマは発火毎に現在のプログラム・カウンタ(PC)のレジスタを記録する.

プログラム終了時, ランタイムは mcount() と profil() が集めたデータを "gmon.out" ファイルに出力する. 肝心な gprof の仕事はこの gmon.out をパースして結果を表示するだけらしい. (横柄なやつだ...)

とりあえず試してみよう.

int foo(int n) {
  int x = 0, i = 0, j = 0;
  for (i=0; i<n; i++) { for (j=0; j<n; j++) { x += i*j; } }
  return x;
}

int main(int argc, char* argv[]) {
  int i=0;
  for (i=0; i<1000; ++i) { foo(i); }
  return 0;
}

これをコンパイルすると...

$ gcc -pg -S -O0 main.c
_hello:
  ....
  pushl %ebx
  subl  $20, %esp
  call  ___i686.get_pc_thunk.bx
  call  Lmcount$stub
  ....
  call  L_puts$stub
  ....
  ret
.globl _main
_main:
  ....
  call Lmcount$stub
  ....
  call  _hello
  ....
  ret
....
Lmcount$stub:
  .indirect_symbol mcount
  ....

たしかに mcount() が呼ばれている. (gcrt0.o の確認はパス.) こいつは何をしているんだろうか. あちこち探すと glibc に実装があった. (gmon/mcount.c)

mcount() の引数はレジスタの値がふたつ. 呼出元のプログラムカウンタ frompc と, 現在の selfpc をとる. この値をグローバル変数 _gmonparam のデータ構造に保存している. mcount() に渡る PC 対を gprof では "arc" と呼ぶ. "呼び出しグラフ" の辺 (arc) というわけ. _gmonparam には, 各 arc の通過回数が記録されている.

さっきのコードを動かしてみよう.

$ gcc -pg -O0 main.c
$ ./a.out
$ gprof a.out gmon.out

結果はこんなかんじ:

...
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
100.0       0.10     0.10     1000     0.10     0.10  _foo [1]
  0.0       0.10     0.00        1     0.00   100.00  _main [2]
...

"calls" エントリが呼出回数. 1000 回, ちゃんと記録されているのがわかる. mcount() を埋めこんだ甲斐があった.

さて, mcount() は関数の入口で arc を記録するだけだ. 実行時間は別に測る必要がある. そこで先に紹介した profile() の出番になる. マニュアルから profil() はシステムコールであるかの印象を受けたけれど, これも glibc で実装されている. (sysdeps/posix/profile.c) 呼び出しも glibc に含まれるプロファイル用ランタイムが行う. ユーザの出番はない.

profil() の仕事は profil_counter() 関数をタイマに登録するだけ. UNIX には ITIMER_PROF というプロファイラ専用のタイマが用意されており, 発火すると SIGPROF シグナルが発行される. ユーザ空間で実装されるとはいえカーネルよりの仕組みなのがわかる.

SIGPROF ハンドラの (profil_counter() は PC レジスタの値を引数に profil_count() を呼ぶ. これが本体. 先に profil() から渡しておいた sample 配列に PC を記録する. sample 配列は PC を添字にとる整数配列で, 以下のように PC の呼出回数を覚えておく:

sample[PC/N]++;

配列の大きさや N の値をどう決めるかは悩ましいが, プロファイル用ランタイムはよろしくやってくれる.

gprof の量子化誤差

細かい間隔のタイマで動く profil_counter() は各瞬間の PC を数える. これが実行時間の根拠になる. PC の記録回数が多い関数ほど長く実行されたとみなすわけ. arc を記録する mcount() と違い, profil() は現在の PC だけを記録する. どこから呼ばれたかは無視. だから profile() の結果から直接わかるのは, 自分自身の実行時間 (gprof の出力にある "self" のエントリ) だけだ. これは子の呼び出しを含まない. 子を含む "total" の時間は mcount() の arc 情報と組合せて計算している. 具体的には, total = self + (({子関数 i の実行時間} x {i の呼び出し回数})の総和) となる.

gprof は "子関数 i の実行時間" に平均値を用いている. しかし関数の中には入力によって実行時間の大きく変わるものがある. そうした関数を含む計測に平均という前提をもちこむとトラブルになる.

たとえば 先のサンプルにあった foo() は入力に対し O(N^2) の計算量をもつ. foo() を使った以下のようなプログラムを動かしてみる. 

int bar() {
  int x = 0, i = 0;
  for (i=0; i<10; i++) { x += foo(10000); }
  return x;
}

int baz() {
  int x = 0, i = 0;
  for (i=0; i<10000; i++) { x += foo(10); }
  return x;
}

int main(int argc, char* argv[]) {
  bar();
  baz();
  return 0;
}

プロファイル結果:

  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
100.0       0.38     0.38    10010     0.04     0.04  _foo [1]
  0.0       0.38     0.00        1     0.00     0.38  _bar [5]
  0.0       0.38     0.00        1     0.00   379.62  _baz [4]
  0.0       0.38     0.00        1     0.00   380.00  _main [2]

baz() の実行時間が bar() の 1000 倍になっている. おかしい. ベタにタイマーで測ってみよう. 

int main(int argc, char* argv[]) {
  clock_t start = 0, bar_end = 0, baz_end = 0;
  start = clock();
  bar();
  bar_end = clock();
  baz();
  baz_end = clock();
  printf("bar:%d, baz:%d\n", bar_end-start, baz_end-bar_end);
  return 0;
}

結果:

bar:478, baz:1

この問題は gprof の man にも BUG として言及されている. プロファイル結果は直感に反するなんてよく言うけれど, 事実に反するのは困るなあ... プロファイラだけでなく, 様々な計測を組み合わせるべきなんだろうね.

gprof の限界

gprof は手軽に使えるけれど, 先の誤差をはじめ制限は多い. たとえばプロセスをまたぐ測定はできない. プロセス単位で仕事を分担する UNIX にとってこれは都合が悪い. グローバル変数が多くマルチスレッド対応も弱い. 動作はするが意味のある数字は期待できない. IO などカーネルが遅いのもわからない.

これら問題の多くはプロセス内で動くよう設計された gprof の限界だと言える. 20 年以上前のツールだから仕方ない. 計測業界(?)自体は 20 年かけてそれなりに進歩しており, その成果には庶民が使えるものもある. 有名どころを少し眺めてみたい.

OProfile

OProfile は linux 用の "system-wide" プロファイラ. カーネルのドライバ(+デーモン)として実装されており, プロセスをまたいだシステム全体のの計測ができる. カーネル内の速度もわかるし, マルチスレッドも OK. OProfile はもともと DCPI (Digital Continuous Profiling Infrastructure) という旧 DEC 製の プロファイラからアイデアを得て作られた. だから意図を知るには DCPI の解説記事 が役にたつ. (OProfile のページからもリンクされている.)

DCPI は実運用されているシステムを計測するために作られた. 運用中のシステムを測る以上, オーバーヘッドは極力小さくしたい. またある程度長い時間かけて測りたいから, 集めた大量の計測データもうまく管理する必要がある. Alpha CPU の威信もあって SMP 環境できっちり動かないといけない. 目標は高い. OProfile もこれに倣ってけっこう野心的な作りになっている.

OProfile の基本的な仕組みは profil() に近い. 割り込みを使って PC レジスタを記録し, 各コード/モジュールの実行時間を測る. OS のタイマーを使う profil() に対し, OProfile は CPU の "パフォーマンスカウンタ" を直接使う. パフォーマンスカウンタは CPU 備え付けの計測機構. 各種 "イベント" の回数を数え, 所定の回数になったら割り込みを起こす. イベントは, たとえば速度を測りたいなら命令の実行回数を数えることができる. (イベントの名前や機能は CPU によってまちまち.) パフォーマンスカウンタの割り込みを直接使うこの仕組みは, スケジューラの絡む OS のタイマーより軽い. ハードウェアのドライバがデバイスからの割り込みを直接拾うように, OProfile もある種のドライバとして実装されている. (だからカーネル空間で動く.)

OPorifle ドライバのコードは linux カーネルのツリーに入っている:

ドライバはカーネル空間に溜めこんだデータを定期的にユーザ空間へ掃きだす. ユーザ空間ではデータを受けとるデーモンプロセス oprofiled が待ち構えている. データの受け渡しは専用のファイルシステム oprofilefs を経由して行う. (oprofilefs.c, event_buffer.c など.) oprofiled は仮想ファイルからデータを読みだし, 今度は本当のファイルに保存する.

こうして計測データはカーネルから届き, 解析されるのを待つ. 解析は oreport コマンドを使う. ユーザは oreport でそのファイルを後処理し, 眺めることができる. こんなかんじ (手元に linux マシンがないのでウェブからコピペ) :

$ opreport
CPU: PIII, speed 863.195 MHz (estimated)
Counted CPU_CLK_UNHALTED events (clocks processor is not halted) ...
   506605 54.0125 cc1plus
	   450385 88.9026  cc1plus
	    28201  5.5667  libc-2.3.2.so
	    27194  5.3679  vmlinux
	      677  0.1336  uhci_hcd
               ...
   163209 17.4008 lyx
	    60213 36.8932  lyx
	    23881 14.6322  libc-2.3.2.so
	    21968 13.4600  libstdc++.so.5.0.1
	    13676  8.3794  libpthread-0.10.so
	    12988  7.9579  libfreetype.so.6.3.1
	    10375  6.3569  vmlinux
	     8599  5.2687  libqt-mt.so.3.0.5
               ...
    58962  6.2863 kdeinit
	    16971 28.7829  libqt-mt.so.3.0.5
	    11533 19.5601  libkonsolepart.so
               ...
...

すげー! linux マシンほしいなあ.

OProfile そのほかの見所

さすがに今時のコードだけあって, OProfile は見所が多い. ちょっと紹介.

まず SMP 対策. 前に書いたとおり, OProfile の本体はパフォーマンスカウンタの割り込みハンドラにある. 割り込みハンドラは当然 CPU 毎に並列で動いてほしい. 一方で各 CPU から集めたデータはまとめて oprofiled に渡す必要がある. そこで OProfile では CPU 毎にバッファを用意し, 割り込みハンドラはそこにデータを書き込む. バッファの中味はあふれる前にカーネルのワーカスレッドが回収する.

バッファへの書込みはさぞかしハイテクなのかと思いきや...

void oprofile_add_ext_sample(unsigned long pc, struct pt_regs * const regs,
        unsigned long event, int is_kernel)
{
  struct oprofile_cpu_buffer * cpu_buf = &cpu_buffer[smp_processor_id()];

  if (!backtrace_depth) {
    log_sample(cpu_buf, pc, is_kernel, event);
    return;
  }
  ....
}

CPUID で配列アクセスかよ! 単純だなー. マルチスレッドのプログラミングは案外カーネルの方が楽なんじゃないかしら... 今日もスレッドのバグで半日つぶした私は訝しみたくなる. まあいいです. CPU 毎にバッファを確保するこのアプローチは DCPI から引き継いでいる.

つぎはカーネル内のフック. プロセスをまたぐ以上, PC レジスタだけでは情報が足りない. 今うごいているプロセスが何か, またそのプロセスはどんなライブラリをロードしているのかを知る必要がある. DCPI ではローダを改造してたが, OProfile は既存のコードを置き換えない. かわりに linux カーネルに用意されたプロファイラ用のフックを使う. (buffer_sync.h, linux/profile.h, kernel/profile.c) こんな便利な API があるとは... 比較的最近 (2004 年くらい) に入ったものらしい. 古い OProfile のコードを見るとシステムコールの関数ポインタを上書きしていてびびる. たしかにフックが欲しい.

PC レジスタの記録だけでは呼び出しグラフを作ることができない. OProfile は 0.8 からスタックトレースを記録するようになった. (backtrace.c) おかげで呼び出しグラフの統計もとれる. 記録をするタイミングは PC レジスタの保存と同時. 負荷が気になるけれど便利そう.

カーネル内のがんばりだけでなく, 統計ツール側の工夫もある. OProfile は多くの CPU アーキテクチャをサポートしており, 一方でプロファイルカウンタの仕様は CPU 毎に大きく異なっている. しかし Oprofile ドライバの大部分やデーモンはこの違いを意識しない. プロファイルカウンタからの情報は arch/ 以下の実装に隠蔽され, バイト列としてファイルまで持ち越される. そのバイト列を解釈するのは oreport など後処理ツールの仕事になる. その後処理ツールも CPU の差異をうまいことデータとしてコード外に追い出せている. (oprofile/events/) 感心. (詳しい仕組みはよくからないけど...)

そんなわけで OProfile のしくみを眺めた. カーネルに住み, パフォーマンスカウンタの割り込みで動く profil() の進化形. 移植性は高くツールも充実している. gprof は遠くなりにけり...

DTrace

じゃ次に進みます.

DTrace は Solaris 付属のトレースツール. あるプロセスのシステムコール呼び出しを追跡する strace に対し, DTrace はシステム全体の様々なイベント (システムコール含む) を監視できる. 技術的な概要は USENIX の記事 にまとまっている. 登場したのは 2004 年らしい. ぐぐると Sun の blog もその周辺で盛り上っていた. (私はだいぶあとに ACMQ の記事を読んで知った.)

OProfile が profil() の延長だったのに対し, DTrace は mcount() と gcc -pg に近い. もっぱらコードを書き換えて監視のフックを仕込み, 記録をとる. このフックを DTrace では provider と読んでいる. provider のフックは色々だ. デバッガがやるようにメモリ上のバイナリを 書き換えて記録をとるものもあるし, プログラマがソースコードの中に書き込んでおくこともできる.

mcount() 相当の関数フックは, 動的なコード書き換えを行う (Function Boundary Provider) で実現する. また provider はフレームワークとして拡張可能になっており, 新しい provdier を自由に定義, 追加できるらしい. この拡張性は DTrace のもつ特徴のひとつ. マニュアルにも山ほど provider が載っている. Solaris は多くの provider をカーネル組込みで用意している. たとえばシステムコールのや IO などを監視できる.

DTrace が持つもう一つの特徴は, "D" という awk/C 風 DSL で 集計用のフィルタを記述できるところ. こんなかんじ (記事からコピペ):

syscall::read:entry
{
        self->t = timestamp;
}

syscall::read:return
/self->t/
{
        printf("%d/%d spent %d nsecs in read\n",
            pid, tid, timestamp - self->t);
}

関数名のところがトレースするフックのパターン, カッコの中がフィルタ/集計のロジックらしい.

DSL を用意した理由の一つとして, 先の記事では実行時の安全性を挙げている. D 言語は dtrace コマンドでバイトコードにコンパイルされ, そのバイトコードがカーネル内の VM で動く. VM は意図的に仕様を制約しており, アクセス違反や無限ループはおこらない. だからフックの度に動かしても安全というわけ. やりすぎ感に溢れていて楽しい. コアとおぼしき (dtrace.c) なんて半分くらい VM だもんなあ... raymond も喜んでくれるよ, たぶん.

拡張性を誇示するかのように, DTrace のページ には様々な provider が紹介されている. sh, java, PostgreSQL, JavaScript, Mozilla, Apache ... これらの大半は USDT (Userland Statically Defined Tracing) という provider を使う. プログラムは dtrace が提供する USDT のフック関数をソースコードに埋め込む. (sys/sdt.h) "dtrace enhanced" なプログラムというのは, 要するに DTrace 用のフックをパチったもののこと.

関数を追跡する FBP(Function Boundary Provider) があるのに わざわざ手動のフックを用意しているのは, 関数をまたく高次のトレースを行うためだ. たとえばトランザクションの開始から終了まで, VM 内の call 命令から ret 命令まで, データの受信開始から完了までといった処理のなかには, 一つの関数呼び出しで完結しない制御フローを持つものがある. こうした手続きを関数ベースのトレースで追いかけるのは難しい. USDT を使えば, transaction_start や transaction_end といったトレース対を 自分で定義して埋め込めむことができる. プログラマがアドホックに作るトレースに比べ, USDT は DTrace のインフラを使いまわせるぶん楽ができる.

また USDT のフックにはユーザの定義した引数を渡すことができる. たとえば Java VM のメソッド呼び出し命令を処理する関数で Java のメソッド名を引数にとれる. ふつうのプロファイラにこれは難しいだろう. そのほか readXX() 関数に渡すバイト数を記録するといった使い方もできる. 便利.

具体例は bugzilla にある Gecko 用のパッチ群 #370906 がわかりやすい. (dtrace ファイルを定義する #277393, それを使う #277395, SpiderMonkey 用 #271004)

Sun の人々はがんばってパッチを作っているけれど, できるなら汎用的なフック機構を作り, そこに DTrace のトレースを挿す方がクリーンだと思う. Apache の mod_dtrace は module として dtrace を組み込んでいる. PostgreSQL も "Generic Monitoring Framework" と銘打ち 間接マクロを挟んでいる. (pg_trace.h: 単なるマクロにしては名前がごつすぎる気も...)

それにしても DTrace を使うのはけっこう敷居が高そうだ. 単純なプロファイラならリストを上から順に潰せばいいけれど, こちらはまず監視するトレースにあたりをつけないといけない. 逆にいうと素朴な計測ではみつけにくい問題を調べるための道具だと言える. USENIX の記事も ACMQ の記事も, 発見の難しいプロセスをまたいた性能バグを いかに退治したかのケーススタディが載っている. とても面白い. Sun のページ にはサンプルやチュートリアルが充実している. 最近では Ajax/Java アプリを DTrace で計測 なんて記事もある. あっけにとられた. Solaris 好きなら DTrace プログラミングという特殊技能を身につけるとかっこいいかも.

DTrace は言ってみれば OS 版アスペクト指向プログラミングだ. ログ取りにしか使えないと揶揄された AOP だけれど, DTrace は最初からその目的に特化している. 様々なフックを用意し, 時にはコードを書き換え, あつめたデータを DSL で集計して性能バグを追いつめていく. DTrace はここで紹介した以外にも色々な機能やアイデアが盛り込まれている. テクノロジーとして見所が多い. 満足.

ruby-prof

そろそろ OS の話には疲れてきた. 最後に少し毛色の違うプロファイラを眺めてみよう, ということで ruby-prof に進みます. ruby-prof は ruby 用のプロファイラ. C 言語による拡張として実装されている.

OProfile も DTrace も動かせなかったけれど, これならマカーにも使えそう. まず gprof 用に書いた C のサンプルを ruby に移植しよう. 

def foo n
  (0 ... n).inject(0) do |a,i|
    a + (0 .. n).inject(0) { |b,j| b + i*j }
  end
end

def bar
  (0 ... 10).inject(0) { |a,i| a + foo(1000) }
end

def baz
  (0 ... 1000).inject(0) { |a,i| a + foo(10) }
end

bar
baz

動かす:

$ ruby-prof hello.rb

結果:

Thread ID: 202500
Total: 181.38

 %self     total     self     wait    child    calls  name
 63.09    180.45   114.43     0.00    66.02    22022  Range#each-2
 18.70     33.91    33.91     0.00     0.00 11155882  Fixnum#+
 17.73     32.16    32.16     0.00     0.00 11143132  Fixnum#*
  0.26    181.32     0.47     0.00   180.85     1012  Range#each-1
  0.11    180.65     0.20     0.00   180.45    22022  Enumerable#inject-2
  0.04      0.08     0.08     0.00     0.00    23036  <Class::Object>#allocate
  0.04      0.07     0.07     0.00     0.00    10285  Bignum#+
  0.02    181.37     0.04     0.00   181.33     1012  Object#foo
 ....

ruby-prof は C で書かれた計測部分と ruby で書かれた集計表示部分からなる. C のコード (ruby-prof.c) は約 1600 行. 今回眺めたコードの中では抜群に小さい. これでちゃんとプロファイルがとれるんだから面白いよね.

ruby-prof は計測のためにフックを使う. フックは ruby コアが用意しており, rb_add_event_hook() (thread.c) から登録する. こんな都合のいい API があるとは... なんとなく ruby の ChangeLog を確認.

Wed Mar 16 22:03:15 2005  Shugo Maeda  <shugo@ruby-lang.org>

  * eval.c (rb_add_event_hook): new function to add a hook function for
    interpreter events.

Shugo Maeda さんは ruby-prof の開発者でもある...

コアが汎用的なフックを用意し, 計測機構はプラグインとしてつくる. これは正しい姿だとおもう. ruby-prof 以外にも, たとえば rcov がこのフックを使っている. ruby dtrace も同じ路線で書けそうだ. (さがしてみると dtrace for ruby というのが見つかった. でも容赦なく eval.c をパチっている. 悲しい...)

さて, gprof の量子化誤差を思いだそう. ruby-prof に同じ問題は見られない. 正しく測れているかんじ. 

 %self     total     self     wait    child    calls  name
  ...
  0.02    181.37     0.04     0.00   181.33     1012  Object#foo
  ...
  0.00    178.98     0.00     0.00   178.98        1  Object#bar
  ...
  0.00    181.38     0.00     0.00   181.38        0  Global#[No method]
  0.00      2.40     0.00     0.00     2.40        1  Object#baz

実装をみればすぐ理由がわかる. ruby-prof は関数の出入口にあるフックで時間を測る. だから関数全体の実行時間がわかる. 推測による誤差は入らない.

ruby-prof の C コードはプロファイラのアルゴリズムを理解するのにちょうどいい. ruby 固有の部分は面倒だけれど, プロファイルのロジックは素直に書かれている. データ構造を ruby 側に公開し, 整形は ruby で書くあたりもそれらしくて楽しめた.

まとめなど

そんなわけで gprof, OProfile, DTrace, ruby-prof と 4 種類のプロファイラを眺め, いいかげん飽きました. (ほんとは valgrind も見たかったけど挫折...)

まとめ:

参考リンク