StackProfを使ってrubyプログラムのプロファイリングをする方法


計測エンジニアになろうとしたら苦労したという記事を[技術ブログ](http://developer-blog.finc.co.jp/post/134570739407/rails%E3%82%A2%E3%83%97%E3%83%AA%E3%81%AE%E3%83%AC%E3%82%B9%E3%83%9D%E3%83%B3%E3%82%B9%E9%81%85%E3%81%84%E3%81%8B%E3%82%89%E3%81%AA%E3%82%93%E3%81%A8%E3%81%8B%E3%81%97%E3%81%A6%E3%82%88%E3%81%A8%E7%84%A1%E8%8C%B6%E6%8C%AF%E3%82%8A%E3%81%95%E3%82%8C%E3%81%9F%E3%81%AE%E3%81%A7%E6%80%A5%E9%81%BD%E8%A8%88%E6%B8%AC%E3%82%A8%E3%83%B3%E3%82%B8%E3%83%8B%E3%82%A2%E3%81%AB%E3%81%AA%E3%81%A3%E3%81%A6)に書いたのですが、技術的な部分を備忘録も兼ねてまとめておきます。
Spring_MTさんの[ブログ](http://spring-mt.hatenablog.com/entry/2014/09/21/014930)には大変お世話になりました。(というかREADME + このブログ記事のまとめでしかないような、、、汗)

# profilingとは
プログラムが実行された際、どの部分のコードの実行にどれだけの時間がかかったのかを計測することです。
ではなぜ人はプロファイリングするのでしょうか？
プロファイリングはパフォーマンスのボトルネックを発見し、”遅いプログラムを速くする”手助けになります。プログラムの中で無駄に何度も呼ばれている部分、不要なのに呼びだされている部分、不自然に遅い部分を発見すれば、それを効率化することでプログラムの実行を速くすることができます。

# StackProfとは
Rubyプログラムのプロファイリングに関してはいくつかのツールがありますが、その中でも軽量でかつ使いやすい、本番環境でも簡単に仕込めるという点で優れているのが [tmm1/stackprof](https://github.com/tmm1/stackprof) です。Rubykaigi2014で発表されて少し有名になりました。

これは ruby2.1 以降で導入された、`rb_profile_frames` という軽量なC APIを用いたミドルウェアのプロファイラで、graphviz, flamegraph といった可視化コマンドも内部に持っています。

# StackProfの使い方
Bundlerを使っていれば、Gemfileに追記して`bundle install`すればインストールできます。ただしリリース版(v0.2.7)は若干古く、後述の`--flamegraph` オプションが作動せずエラーが出るので、応急処置ではありますが以下のように最新版をインストールするのが丸いです。

```ruby:Gemfile
  gem 'stackprof', git: "git://github.com/tmm1/stackprof.git", branch: "master"
```

設定は、`config.ru`以下に書きます。設定は以下の通りやると便利です。

```ruby:config.ru
require ::File.expand_path('../config/environment',  __FILE__)

is_stackprof         =  ENV['ENABLE_STACKPROF'].to_i.nonzero?
stackprof_mode       = (ENV['STACKPROF_MODE']       || :wall).to_sym
stackprof_interval   = (ENV['STACKPROF_INTERVAL']   || 1000).to_i
stackprof_save_every = (ENV['STACKPROF_SAVE_EVERY'] || 1 ).to_i
stackprof_path       =  ENV['STACKPROF_PATH']       || 'tmp/stackprof/'
use StackProf::Middleware, enabled:    is_stackprof,
                           mode:       stackprof_mode,
                           raw:        true,
                           interval:   stackprof_interval,
                           save_every: stackprof_save_every,
                           path:       stackprof_path

run Rails.application
```
このように書くことでミドルウェアとしてstackprofを使うことができます。
以下、オプション(enabled, mode, raw, interval, save_every, path)の解説です。

#### enabled
これはStackProfを起動するかどうかを表します。これは環境変数`$ENABLE_STACKPROF`の$0 / 1$で判定します。`export ENABLE_STACKPROF=1`として、`rails s`すればOKです。

また、わざわざrailsを再起動しなくてもStackProfの有効/無効はコンソールから変更することができます。

```ruby
StackProf.running?
StackProf.start
StackProf.stop
```
の3つのコマンドがあります。`running?`メソッドはStackProfが起動中かを判定します。start, stopは名前の通りです。
このように手軽に本番環境でプロファイルをON⇔OFFと切り替えることができるのが便利です。

### mode
よく使われるのは[:cpu, :wall]の2つでしょう。wallは全体での実行時間、cpuはCPU時間＝CPUでの処理の実行時間のみを計測します。

### raw
後述する`--flamegraph`オプションを利用するために必要です。trueにしておきましょう。

### interval
計測タイミングの粒度です。デフォルトは1000[μs] = 1[ms] になっています。

### save_every
何リクエストごとにプロファイル結果をdumpファイルで出力するか、です。毎回のリクエストごとに生成したいときは1にするといいですが出力されすぎる可能性があるので注意。

### path
dumpファイルを出力するディレクトリです。`tmp/stackprof/`以下にでも入れておけばいいでしょう。

# 実際に使ってみる
本番環境で準備が整ったら`StackProf.start`を手動で実行。やめたくなったら`StackProf.stop`で止めればOK。
すると先ほど`path`オプションで設定した`tmp/stackprof/`以下にdumpファイルが生成されています。

```bash
$ ll -h tmp/stackprof/stackprof-wall-*.dump
-rw-r--r--  1 Shunsuke_SAKAI  staff   2.7M 12  9 08:40 tmp/stackprof/stackprof-wall-1416-1449618032.dump
-rw-r--r--  1 Shunsuke_SAKAI  staff   197K 12  9 01:00 tmp/stackprof/stackprof-wall-40150-1449590403.dump
```

この出力結果を見るには

```bash
$ bundle exec stackprof tmp/stackprof/hogehoge.dump
```
とすると、

```
==================================
  Mode: wall(1000)
  Samples: 499 (3.29% miss rate)
  GC: 89 (17.84%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       129  (25.9%)         129  (25.9%)     block in WEBrick::GenericServer#start
        27   (5.4%)          27   (5.4%)     Rack::MiniProfiler.config
        24   (4.8%)          24   (4.8%)     block (2 levels) in Rack::MiniProfiler::TimerStruct::Sql#initialize
        22   (4.4%)          22   (4.4%)     block in Mysql2::Client#query
        11   (2.2%)           9   (1.8%)     block in Bullet::Detector::NPlusOneQuery.caller_in_project
         9   (1.8%)           9   (1.8%)     Rabl::Sources#fetch_manual_template
         8   (1.6%)           8   (1.6%)     Rabl::Engine#attribute
         7   (1.4%)           7   (1.4%)     block in Fog::AWS::SignatureV4#canonical_path
         7   (1.4%)           5   (1.0%)     #<Module:0x007ffa544e1ff0>.escape
         4   (0.8%)           4   (0.8%)     Time#compare_with_coercion
         4   (0.8%)           4   (0.8%)     ActiveSupport::PerThreadRegistry#instance
         4   (0.8%)           4   (0.8%)     Rabl::Engine#child
         3   (0.6%)           3   (0.6%)     Rabl::Engine#initialize
         3   (0.6%)           3   (0.6%)     Fog::HMAC#setup_sha256
         3   (0.6%)           3   (0.6%)     block in ActiveSupport::FileUpdateChecker#max_mtime
```
のように出力結果が表示されます。
呼ばれた回数、及びそれが全体の実行時間のうちどれくらいの割合を占めるのか、を見ることができます。ここのオプション`--limit`を用いることでもっと深くまで表示することができます（デフォルトは30）。

細かく見たい場合はメソッド名を引数にとり、それがどこで呼ばれているかを確かめることができます。

```bash
$ bundle exec stackprof tmp/stackprof/stackprof-wall-5348-1449630859.dump --method "Mysql2::Client#query"
block in Mysql2::Client#query (/usr/local/Cellar/rbenv/0.4.0/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rack-mini-profiler-0.9.3/lib/patches/db/mysql2.rb:22)
  samples:    22 self (4.4%)  /     22 total (4.4%)
  callers:
      22  (  100.0%)  SqlPatches.record_sql
  code:
                                  |    22  |     result, record = SqlPatches.record_sql( args[0] ) do
   22    (4.4%) /    22   (4.4%)  |    23  |       query_without_profiling(*args,&blk)
                                  |    24  |     end
Mysql2::Client#query (/usr/local/Cellar/rbenv/0.4.0/versions/2.2.3/lib/ruby/gems/2.2.0/gems/rack-mini-profiler-0.9.3/lib/patches/db/mysql2.rb:19)
  samples:     2 self (0.4%)  /     78 total (15.6%)
  callers:
      78  (  100.0%)  block in ActiveRecord::ConnectionAdapters::AbstractMysqlAdapter#execute
  callees (76 total):
      76  (  100.0%)  SqlPatches.record_sql
  code:
                                  |    19  |   def query(*args,&blk)
                                  |    20  |     return query_without_profiling(*args,&blk) unless SqlPatches.should_measure?
                                  |    21  |
   76   (15.2%)                   |    22  |     result, record = SqlPatches.record_sql( args[0] ) do
                                  |    23  |       query_without_profiling(*args,&blk)
                                  |    24  |     end
                                  |    25  |     result.instance_variable_set("@miniprofiler_sql_id", record) if result
    2    (0.4%) /     2   (0.4%)  |    26  |     result
                                  |    27  |   end
```

# 可視化してみる
なんだかんだいってVisualizeできると喜んでしまうものです。硬派なプログラマの方はそうでもない？そうですか…

stackprof コマンドのオプションで `--graphviz`や`--flamegraph`が指定できます。
前者はグラフ理論なんかでよく出てくる、ノードとエッジのアレです。
後者は直訳すると"炎のグラフ"となりますが、[こちらの記事](http://d.hatena.ne.jp/yohei-a/20150706/1436208007)が詳しく、参考にするといいと思います。簡単に説明すると、横幅がかかった時間、縦方向の積み重ねがネストした関数呼び出しを表しています。横幅をとってしまう関数が遅くしている要因といえます。


## flamegraphを出す
以下のようにすればOKです。

```bash
$ stackprof tmp/stackprof-wall-5348-1449630859.dump --flamegraph > tmp/fl.js
$ stackprof tmp/stackprof-wall-5348-1449630859.dump --flamegraph-viewer tmp/fl.js
open file:///Users/Shunsuke_SAKAI/.bundler/ruby/2.2.0/stackprof-e252254355f8/lib/stackprof/flamegraph/viewer.html?data=/path/to/your/tmp/fl.js
```
`raw: true`を設定しておくのをお忘れなく。
これで出てきたファイルのリンクをブラウザで開くとflamegraphが表示されます。


# 最後に
プロファイラとベンチマークをうまく使うことで計測時間を出力し、パフォーマンスのボトルネック把握に役立てることができます。こうした計測ツールが流行って、重くなりがちなRailsアプリケーションの高速化によるUXカイゼンなんかが簡単にできるようになると優しい世の中ですね。