【Ruby on Rails】ruby-profでコードの処理速度を測定する

■やりたいこと

コードの実行中にどの部分が時間を消費しているかを特定したい

■使用ツール

ruby-prof

※プロファイリングツールは ruby-prof の他に stackprof も有力らしい

■手順

1. gemfile に ruby-prof を追加

gem 'ruby-prof'

2. インストール実行

bundle install

3. controller を編集

# ruby-prof をロード
require 'ruby-prof'

class TestController
  def test
    result = RubyProf.profile do
      # 測定したい処理をここに記述する
    end

    # 測定結果を出力する
    output_path = './rubyprof.out'
    File.open(output_path , 'w') { | f |
      RubyProf::FlatPrinter.new(result).print(f)
    }
  end
end

4. 測定したい処理を実行後、出力結果を確認する
上記の例では rubyprof.out というファイルが出力されているはずなので確認する。
結果を見やすくしてくれるツール等もあるが面倒くさい場合はテキストエディタでそのまま開いて良し。

出力結果サンプル

Measure Mode: wall_time
Thread ID: 70325959779980
Fiber ID: 93369140
Total: 0.198714
Sort by: self_time

%self total self wait child calls name location
13.07 0.042 0.026 0.016 0.000 53 Mysql2::Client#_query
4.54 0.009 0.009 0.000 0.000 122 IO#write
4.29 0.009 0.009 0.000 0.000 61 Kernel#caller
3.65 0.007 0.007 0.000 0.000 8336 String#sub
3.61 0.117 0.007 0.002 0.108 932 *Array#each
1.40 0.136 0.003 0.000 0.133 743 *#handle_interrupt
1.18 0.009 0.002 0.003 0.003 2169 *Class#new
0.96 0.002 0.002 0.000 0.000 254 Regexp#===
0.69 0.003 0.001 0.000 0.002 284 Array#map
0.65 0.001 0.001 0.000 0.000 2417 Regexp#match?

%self - The percentage of time spent in this method, derived from self_time/total_time.
total - The time spent in this method and its children.
self - The time spent in this method.
wait - The amount of time this method waited for other threads.
child - The time spent in this method's children.
calls - The number of times this method was called.
name - The name of the method.
location - The location of the method.

総処理時間0.198714秒のうちクエリの実行で0.042秒（13.07%）使ってるなとか、53回呼び出されてるな等読み取れる