実行時間を測るRubyの関数

チューニングするときボトルネックを探したいです。ボトルネックの候補となる処理を実行したときにどれぐらいの時間が掛かかるのか計測したいです。次の関数を作りました。

def elapsed_time_of(message = '')
  starting = Process.clock_gettime(Process::CLOCK_MONOTONIC)
  ret = yield
  ending = Process.clock_gettime(Process::CLOCK_MONOTONIC)
  p "#{message} spend #{((ending - starting) * 1000).floor(2)}ms"
 
  ret
end

次のように重そうな処理をしているところがあったら

annotations_collection_with_doc.each do |annotations, doc|
  messages += Annotation.prepare_annotations!(annotations, doc, options)
end

ブロックで覆います。

elapsed_time_of('Annotation.prepare_annotations!') do
  annotations_collection_with_doc.each do |annotations, doc|
    messages += Annotation.prepare_annotations!(annotations, doc, options)
  end
end

実行すると、次のログがでます。

"Annotation.prepare_annotations! spend 55831.53ms"

さらにpの代わりに tengu_p Railsエディション - @ledsun blog を使うと、天狗が目立つログが出せます。

@ledsun blog

無味の味は佳境に入らざればすなわち知れず

実行時間を測るRubyの関数

参考