ruby-profとKCacheGrindでプロファイル野郎になる

速さが足りない!!!!!
f:id:mirakui:20100919160528p:image
そんな時はプロファイリングの時間ですね。
Rubyには標準添付ライブラリとして profile というプロファイラがついてくる。でもこのライブラリはあまりに遅すぎて実用に耐えないから、多分誰も使っていない。ほとんどのRubyistruby-prof を使っていることだろう。
今回はこの ruby-prof を使って Ruby プログラムのプロファイリングする方法を紹介する。

計測する(ruby-prof)

ruby-profはrubygemsで簡単に入る。

$ gem install ruby-prof

ruby-profというコマンドラインツールがインストールされる。これを使うと、プログラムを変更することなく手軽にプロファイリングを行うことができる。ruby-profコマンドのusageは以下のとおり。

ruby_prof 0.9.2
Usage: ruby_prof [options] <script.rb> [--] [script-options]

Options:
    -p, --printer=printer            Select a printer:
                                       flat - Prints a flat profile as text (default).
                                       flat_with_line_numbers - same as flat, with line numbers.
                                       graph - Prints a graph profile as text.
                                       graph_html - Prints a graph profile as html.
                                       call_tree - format for KCacheGrind
                                       call_stack - prints a HTML visualization of the call tree
                                       dot - Prints a graph profile as a dot file
    -m, --min_percent=min_percent    The minimum percent a method must take before
                                       being included in output reports.
                                       this option is not supported for call tree.
    -f, --file=path                  Output results to a file instead of standard out.
        --mode=measure_mode          Select what ruby-prof should measure:
                                       process - Process time (default).
                                       wall - Wall time.
                                       cpu - CPU time (Pentium and PowerPCs only).
                                       allocations - Object allocations (requires patched Ruby interpreter).
                                       memory - Allocated memory in KB (requires patched Ruby interpreter).
                                       gc_runs - Number of garbage collections (requires patched Ruby interpreter).
                                       gc_time - Time spent in garbage collection (requires patched Ruby interpreter).
        --replace-progname           Replace $0 when loading the .rb files.
    -v                               Show version, set $VERBOSE to true, profile script
    -d                               Set $DEBUG to true
    -h, --help                       Show help message
        --version                    Show version 0.9.2

KCacheGrindでビジュアライズするためには、以下のようにcall_treeオプションを指定する。

$ ruby-prof -f <output> -p call_tree <your-script.rb>

結果をビジュアライズする(KCacheGrind)

はっきり言ってプロファイリングは可視化が命だと思う。ruby-profではテキストやHTMLでプロファイリング結果を出力することもできるが、複雑なプログラムのプロファイリングでは、KCacheGrindのような可視化ツールを使うことで飛躍的に効率を上げることができる。
今回はMac OSX 10.6.4からKCacheGrindを使ってプロファイリング結果の可視化をおこなう。

$ sudo port install kcachegrind

このとき、俺の環境だとなぜかホームディレクトリに .kde ディレクトリが root 権限で作られてしまい、うまく起動できなかった。もしそうなった場合は

$ sudo chown -R your-user:you-group ~/.kde

とすればいい。

起動するには以下のコマンドを実行する。

$ kachegrind

ruby-profで出力した結果を読み込ませると、こんな感じになる。
f:id:mirakui:20100919160525p:image

直感的なツールなので、操作は小一時間いじってればわかるとおもう。

ハマりポイント

KCacheGrindを使って複雑なプログラムをプロファイリングすると、いくつかの処理がCycleとしてまとめられてしまうことがある。
f:id:mirakui:20100919160526p:image
これではうまく分析できないので、Do Cycle Detection をオフにしましょう。全部展開してくれます。
f:id:mirakui:20100919160527p:image
これ。

Railsアプリケーションのプロファイリング(Rails3)

Railsアプリの分析も驚くほど簡単。ruby-profならね。

Rails3になってから、script/performance/profiler がなくなってしまったので、自分でruby-profを仕込む必要がある。
そのやり方はいくつかある。

  1. ruby-prof script/rails server する
    • この方法はイマイチ。Railsのサーバ起動のオーバヘッドまで計測されてしまう。
  2. rack-contrib の Rack::Profiler を使う
    • rack-contribという、rackミドルウェア詰め合わせセットの中に、Rack::Profilerというのがある。これが一番スマートかもしれない。
  3. around_filter で ruby-prof を仕込む
    • 特定のアクションだけちょっと測ってみたいというときは、この方法もいいかも。
準備(キャッシュとか)

development環境だと、クラスキャッシュなどが無効になっているので、productionに近い環境での正しい計測ができない。
かと言って、development.rbをプロファイリングのたびに書き換えるのは面倒なので、 profiler という environment を用意することにした。
以下のようにする。

# config/environments/profiler.rb
  :
config.cache_classes = true
config.action_controller.perform_caching = true
  :

もちろん、database.ymlにもprofilerという環境を設定する必要がある。

起動するときは、

$ script/rails server -e profiler
rack-contribを使う編

Gemfileに以下を追加して bundle install 。

gem 'rack-contrib'

config.ruに以下を記述する。

require 'rack/contrib/profiler'
use Rack::Profiler if Rails.env.profiler?

これだけ。

profiler環境で以下のオプションをつけて適当にページにアクセスすると、

?profile=process_time

ページは表示されずに、call_tree形式のプロファイル結果がダウンロード(!)される。それをKCacheGrindに読ませればOK。

around_filterを使う編

Rack::Profilerがうまく動かなかったときなどは、コントローラにruby-profを直接仕込めばプロファイリングできる。

around_filter :profiler, :only => [:show], if => lambda{Rails.env.profiler?}

def profiler
  ::RubyProf.start
  yield
  result = ::RubyProf.stop
  printer = ::RubyProf::CallTreePrinter.new(result)
  path = Rails.root.join("tmp/process_time.tree")
  File.open(path, 'w') do |f|
    printer.print(f, :min_percent => 0, :print_file => true)
  end
end

# プロファイリングしたいアクション
def show
  ;
end

まとめ

これで君も今日からプロファイル野郎だ!!! どんどん世界を縮めましょう。