profile

http://www.ruby-lang.org/ja/man/?cmd=view;name=profile
出力内容をきちんと理解していなかったのでおさらい。

簡単なスクリプトで実験。

def bar
  sleep 7
end

def zoo
  1000.times{|i| puts i}
end

def foo
  bar
  zoo
end

foo
foo

  %   cumulative   self              self     total

 time   seconds   seconds    calls  ms/call  ms/call  name

 55.64     0.22      0.22     2000     0.11     0.17  Kernel.puts

 20.26     0.30      0.08     4000     0.02     0.02  IO#write

 12.31     0.34      0.05     2000     0.02     0.02  Fixnum#to_s

 11.79     0.39      0.05        2    23.00   195.00  Integer#times

  0.00     0.39      0.00        3     0.00     0.00  Module#method_added

  0.00     0.39      0.00        2     0.00   195.00  Object#foo

  0.00     0.39      0.00        2     0.00     0.00  Object#bar

  0.00     0.39      0.00        2     0.00   195.00  Object#zoo

  0.00     0.39      0.00        2     0.00     0.00  Kernel.sleep

  0.00     0.39      0.00        1     0.00   390.00  #toplevel

とりあえず…

• sleepの時間はカウントされない
• foo()の「total ms/call」には呼び出したbar()の時間も含まれる(当たり前か…)
• foo()の「self ms/call」には呼び出したbar()の時間も含まれないみたい
  • なので、#toplevelの「seconds」「total ms/call」がプログラム全体の実行時間になるのかな