CubicLouve

Spring_MTの技術ブログです。https://github.com/SpringMT (http://spring-mt.tumblr.com/ からの移転)

stackprofの原理

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

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

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

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

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

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

  1. リクエストを受ける
  2. StackProf.startが呼ばれプロファイリング開始
  3. リクエストを処理する
  4. StackProf.stopを呼びプロファイルングを終了
  5. 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時に、modecpu または 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-teim)でタイマーが減少)を使います。タイマーが満了になるとSIGALRMシグナルが送られます。intervalはマイクロ秒になります。
:cpu setitimer(2)ITIMER_PROF(CPU時間でタイマーが減少)を使います。タイマーが満了になるとSIGPROFシグナルが送られます。intervalはマイクロ秒になります。
:object Rubyの新しいオブジェクト生成の毎にサンプリングします。RubyVM時間とでも言えるかな。

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

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

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

サンプリング結果

各サンプルは複数個のスタックフレームで構成され、スタックフレームはMyClass#methodblock 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

stackprof print_debug

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

  • A#powの場合

pow <- initializeなので、 powsamplestotal_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なので、matchsamplesには1、total_samplesのカウントに2足され、initializeのtotal_samplesに1足されます。

そのため、mathtotal_samplessamplesより約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"

:wall:cpuの使い分け

ネットワークアクセスをする場合をサンプリングしてみます。

  • :wall

stackprof with wall

  • :cpu

stackprof with cpu

ネットワークI/Oの待ち時間やディスクI/Oの待ち時間はCPU時間には反映されないので、:cpuの場合は、ネットワークレイテンシが反映されないです。

これを踏まえると、まずは:wallモードでサンプリングしボトルネックがどこにあるか明らかにしましょう。

I/O待ち多く(特にデータベース外部サービスの外部要因でどうにもならない場合)、ノイズにしかならないので、:cpuモードでもサンプリングするのがよいでしょう。

参照

speakerdeck.com

関数一覧 (Ruby 2.4.0)

macro RTEST (Ruby 2.4.0)

Man page of SIGACTION

Man page of GETITIMER

Man page of SIGSETOPS

real time/user CPU time/system CPU&nbsp;timeの違いをメモsiguniang.wordpress.com

rb_postponed_job_register_oneの説明 d.hatena.ne.jp 「postponed_job」の検索結果 - PB memo

rb_profile_framesの説明 ruby-trunk-changes r43156 - r43183 - PB memo

Ruby 2.1: Profiling Ruby · computer talk by @tmm1

st_updateの説明 ruby-trunk-changes r34141 - r34150 - PB memo