RubyProf

• http://shugo.net/jit/20050322.html

profile.rbと比べるとかなり高速になっていると思います。

Ruby用のプロファイラ。よさげ。

% wget http://shugo.net/archive/ruby-prof/ruby-prof-0.1.tar.gz
% tar xf ruby-prof-0.1.tar.gz
% cd ruby-prof-0.1
% ruby extconf.rb
% make
% sudo make install
install -p -m 0755 prof.so /usr/local/lib/site_ruby/1.8/i386-linux
install -p -m 0644 ./lib/unprof.rb /usr/local/lib/site_ruby/1.8

bench-md5.rb

require "md5"
require "benchmark"

Benchmark.bm {|x|
  x.report { 
    10000.times {
      t = MD5.hexdigest("t")
    }
  }
}

まず、普通に動かす。

% ruby bench-md5.rb
     user     system      total        real
 0.230000   0.000000   0.230000 (  0.219177)

古い方でプロファイルしてみる。

% ruby -rprofile bench-md5.rb
     user     system      total        real
 0.070000   1.450000   1.520000 (  1.518790)
 %   cumulative   self              self     total
time   seconds   seconds    calls  ms/call  ms/call  name
57.14     0.04      0.04    10000     0.00     0.00  Digest::MD5#hexdigest
42.86     0.07      0.03        1    30.00    70.00  Integer#times
14.29     0.08      0.01        1    10.00    10.00  Profiler__.start_profile
略

新しいRubyProfでプロファイルしてみる。

% ruby -runprof bench-md5.rb
     user     system      total        real
 0.030000   0.280000   0.310000 (  0.303526)
 %%   cumulative   self              self     total
time   seconds   seconds    calls  ms/call  ms/call  name
74.29    0.260     0.260    10000     0.03     0.03  Digest::MD5#hexdigest
14.29    0.310     0.050        1    50.00   310.00  Integer#times
11.43    0.350     0.040        3    13.33    13.33  Kernel.require
略

速い。感激!

10倍にしてみる。

% ruby bench-md5.rb
     user     system      total        real
 1.350000   0.050000   1.400000 (  1.404073)

% ruby -rprofile bench-md5.rb
     user     system      total        real
 0.590000  12.860000  13.450000 ( 13.474452)
 %   cumulative   self              self     total
time   seconds   seconds    calls  ms/call  ms/call  name
73.77     0.45      0.45        1   450.00   590.00  Integer#times
22.95     0.59      0.14   100000     0.00     0.00  Digest::MD5#hexdigest
 4.92     0.62      0.03        1    30.00    30.00  Profiler__.start_profile
 1.64     0.63      0.01        1    10.00   600.00  Benchmark::Report#report

% ruby -runprof bench-md5.rb
     user     system      total        real
 0.070000   1.810000   1.880000 (  1.869506)
 %%   cumulative   self              self     total
time   seconds   seconds    calls  ms/call  ms/call  name
72.11    1.370     1.370   100000     0.01     0.01  Digest::MD5#hexdigest
26.84    1.880     0.510        1   510.00  1880.00  Integer#times
 0.53    1.890     0.010        7     1.43     1.43  String#gsub!
 0.53    1.900     0.010        3     3.33     6.67  Kernel.require
 0.00    1.900     0.000       39     0.00     0.00  Module#method_added

やっぱ速い。しかも正確だ。

% ruby -runprof test-suite-basic.rb
use clock(3) for profiling
Loaded suite test-suite-basic
Started
................................................................................
................................................................................
................................................................................
................................................................................
................................................................................
.........................
Finished in 41.414011 seconds.

425 tests, 2758 assertions, 0 failures, 0 errors
/usr/local/lib/site_ruby/1.8/unprof.rb:30: [BUG] Segmentation fault
ruby 1.8.2 (2005-04-11) [i386-linux]

 total = result.detect { |i|
   i.method_class.nil? && i.method_id == :"#toplevel"
 }.total_time

この真ん中の行でBUGとのこと。拡張ライブラリの問題だろうか。