stackprofの原理 - CubicLouve

stackprofがどうやってプロファイルを行っているかを追ってみます。

プロファイルするコードは下記を使います。

stackprof/sample.rb at master · tmm1/stackprof · GitHub

自分用のメモなので、間違い等があるのはご容赦ください。。(随時ブラッシュアップしていければ)

プロファイルを取る仕組み

StackProd::Middleware経由でのプロファイリングの流れは下記の通り。

リクエストを受ける
StackProf.startが呼ばれプロファイリング開始
リクエストを処理する
StackProf.stopを呼びプロファイルングを終了
save_every で指定した回数にリクエスト回数が達した場合、プロファイル結果をファイルに書込む

さらに今回はStackProf.startからStackProf.stopの流れを詳細におっていきます。

準備

gdbでおっていくので、マクロ等も展開できるようにデバッグ情報を付けてrubyをビルドします。

$ wget https://cache.ruby-lang.org/pub/ruby/2.4/ruby-2.4.1.tar.gz
$ tar zxf ruby-2.4.1.tar.gz
$ cd ruby-2.4.1 
# -O0で最適化を無効にし、-g3でデバッグ情報を付ける
./configure optflags="-O0" debugflags="-g3" --prefix="${HOME}/.rbenv/versions/2.4.1-O0_g3"
make
make install

サンプリング

StackProf.startが呼ばれると、stackprof_startが呼ばれます。 https://github.com/tmm1/stackprof/blob/master/ext/stackprof/stackprof.c#L61

start時に、modeをcpu または wallで設定すると、setitimer(2)でintervalで指定した時間(マイクロ秒)のインターバルタイマーを設定し、タイマーが満了したときに送られるシグナルに対してsigaction(2)でサンプリングのシグナルハンドラーを設定します。

stackprofで指定するintervalはサンプリングする間隔(これは時間)で、save_everyはサンプリングした結果をファイル等に保存する間隔(これはリクエスト回数)です。

save_everyはHTTPサーバー向けのオプション(StackProf:: Middlewareでのみ指定可能)で、save_everyで指定した数リクエストがきたら、サンプリング結果を保存します。

save_everyが大きすぎると、サンプリング結果が肥大化し、保存するときに時間がかかってしまいますが、小さいとこまめに保存されるためファイル数が膨大になってしまうので運用しながら要調整です。

modeが:objectの場合は、TracePointを使って、オブジェクトの確保のたびにサンプリングを行います。

mode	説明
:wall	`setitimer(2)` で`ITIMER_REAL`(実時間(時計時間 wall-clock-time)でタイマーが減少)を使います。タイマーが満了になると`SIGALRM`シグナルが送られます。intervalはマイクロ秒になります。
:cpu	`setitimer(2)` で`ITIMER_PROF`(CPU時間でタイマーが減少)を使います。タイマーが満了になると`SIGPROF`シグナルが送られます。intervalはマイクロ秒になります。
:object	Rubyの新しいオブジェクト生成の毎にサンプリングします。RubyのVM時間とでも言えるかな。

シグナルハンドラーはRubyのC-APIのrb_postponed_job_register_oneを使ってサンプリングするjobを登録します。

サンプリングするときには、RubyのC-APIのrb_profile_framesを使って、call stackにアクセスして、スタックフレームを取得します。

ruby/vm_backtrace.c at 249790802db62ff22c79830d4054c449fa3c243b · ruby/ruby · GitHub

サンプリング結果

各サンプルは複数個のスタックフレームで構成され、スタックフレームはMyClass#methodやblock in MySingleton.methodように見えます。

サンプル内のこれらのフレームごとに、stackprofは下記のメタデータを収集します。

(aggregateオプションを有効にした場合のみです。デフォルトでは有効になっています。)

主に個々の部分でメタデータの収集を行っています。

https://github.com/tmm1/stackprof/blob/master/ext/stackprof/stackprof.c#L387

metadata	説明
samples	スタックフレームで一番最初に呼ばれている回数。つまり、サンプリングしたときにまさに呼び出されていた回数。まずこの数字を確認する。
total_samples	スタックフレームの中にふくまれてる回数。
lines	スタックフレームの呼び出されている行とその回数。
edges	このスタックフレームを呼び出したメソッドとその回数

結果

print_method(/pow|newobj|math/)

stackprof print_method(/pow|newobj|math/)

print_text

stackprof result.print_text

graphviz
print_debug

stackprof print_debug

サンプリングしていたときにスタックフレームは下記のようになっています。

A#powの場合

pow <- initializeなので、 powのsamplesとtotal_samplesのカウントに1足され、initializeのtotal_samplesに1足されます。

$ gdb -nw -silen -x ./.gdbinit --args `rbenv which ruby` sample.rb

(gdb) break stackprof.c:387
(gdb) run
(gdb) rb_p rb_profile_frame_method_name(_stackprof.frames_buffer[0])
"pow"
(gdb) rb_p rb_profile_frame_method_name(_stackprof.frames_buffer[1])
"initialize"
(gdb) rb_p rb_profile_frame_method_name(_stackprof.frames_buffer[2])

A#mathの場合 math <- math <- initializeなので、matchのsamplesには1、total_samplesのカウントに2足され、initializeのtotal_samplesに1足されます。

そのため、mathのtotal_samplesはsamplesより約2倍ほど多くなります。

mathは中にブロックがあり、それがスタックに積まれています。

(gdb) rb_p rb_profile_frame_method_name(_stackprof.frames_buffer[0])
"math"
(gdb) rb_p rb_profile_frame_method_name(_stackprof.frames_buffer[1])
"math"
(gdb) rb_p rb_profile_frame_method_name(_stackprof.frames_buffer[2])
"initialize"