Rubyのスクリプトを計測する

性能測定系のツール類について調べたので結果をまとめた。

time

まずはtimeコマンドで実行時間を計測してみる。

% time ruby target.rb
ruby target.rb  174.91s user 0.97s system 98% cpu 2:58.53 total

% \time ruby target.rb
      186.63 real       181.51 user         1.32 sys

zshの場合、timeはシェル組み込みコマンドなので/usr/bin/timeを使いたければ\timeと打てばいい。タイミングによって結果がばらつくので何度か測る。

ベンチマーク

ベンチマークを測るには標準添付ライブラリbenchmarkを使えばいい。

require 'benchmark'

n = 10_000_000 
Benchmark.bm do |benchmark|
  benchmark.report { Array.new(n, 'A') }
  benchmark.report { n.times.map { 'A' } }
  benchmark.report { ary = []; n.times { ary << 'A' } }
end
% ruby bm.rb 
       user     system      total        real
   0.020000   0.020000   0.040000 (  0.036583)
   2.390000   0.280000   2.670000 (  2.867167)
   2.230000   0.110000   2.340000 (  2.347568)

プロファイラ

Rubyにはプロファイラがいくつかある。今回は profile、ruby-prof、stackprof の3つを試した。

profile

Rubyにはprofileというプロファイラが標準添付されている。解析したいスクリプトのなかでrequire 'profile'しておくと標準出力に解析結果が表示される。

require 'profile'
100_000.times.map { rand(100) }
% ruby prof.rb
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 35.54     1.61      1.61   100000     0.02     0.02  Kernel#rand
 32.23     3.07      1.46   100000     0.01     0.03  nil#
 24.28     4.17      1.10        2   550.00  2265.00  Integer#times
  7.95     4.53      0.36   100000     0.00     0.00  Kernel#respond_to_missing?
  0.00     4.53      0.00        1     0.00     0.00  TracePoint#enable
  0.00     4.53      0.00        1     0.00     0.00  Mutex#unlock
  0.00     4.53      0.00        1     0.00     0.00  MonitorMixin#mon_exit
  0.00     4.53      0.00        1     0.00     0.00  MonitorMixin#mon_check_owner
  0.00     4.53      0.00        1     0.00     0.00  MonitorMixin#mon_enter
  0.00     4.53      0.00        1     0.00     0.00  Mutex#lock
  0.00     4.53      0.00        3     0.00     0.00  Thread.current
  0.00     4.53      0.00        1     0.00  4530.00  Enumerator#each
  0.00     4.53      0.00        1     0.00  4530.00  Enumerable#map
  0.00     4.53      0.00        1     0.00     0.00  TracePoint#disable
  0.00     4.53      0.00        1     0.00  4530.00  #toplevel

ruby-prof

標準添付の profile は遅いので ruby-prof を使ったほうがいい。

% gem install ruby-prof

デフォルトでは標準出力に結果が表示される。

% ruby-prof target.rb
Thread ID: 70219398003680
Fiber ID: 70219398364240
Total: 1314.089420
Sort by: self_time

 %self      total      self      wait     child     calls  name
 50.43    662.748   662.748     0.000     0.000 618962610   String#== 
 48.53   1299.981   637.703     0.000   662.278    43664   Array#include? 
  0.17      2.210     2.210     0.000     0.000   111209   Array#to_h 
  0.16      2.097     2.097     0.000     0.000  1149031   Hash#[] 
  0.16      8.160     2.046     0.000     6.115     1503   Array#map 
  0.15   1303.287     1.937     0.000  1301.350     2656   Array#reject 
  0.10      1.329     1.329     0.000     0.000   111288   String#split 
  0.08      1.076     1.076     0.000     0.000   111209   Array#transpose 
  0.04      0.526     0.526     0.000     0.000       37   Array#uniq! 
  0.04      0.475     0.475     0.000     0.000   396519   String#to_i 
  0.03      0.389     0.389     0.000     0.000   394780   Fixnum#+ 
  0.01      0.163     0.163     0.000     0.000   111248   String#chomp 
  0.01      0.084     0.084     0.000     0.000       39   IO#readlines 
  0.01      0.083     0.083     0.000     0.000    55213   String#[] 
  0.00      0.046     0.046     0.000     0.000     5798   IO#write 
  0.00      0.065     0.019     0.000     0.046     2899   <Object::Object>#write 
  0.00      0.009     0.009     0.000     0.000     3987   Fixnum#to_s 
  0.00      0.845     0.007     0.000     0.838     1387   Enumerable#reduce 

各カラムの意味は下記の通り(引用元:ruby-prof/flat.txt

The columns are:

    %self        - The percentage of time spent in this method, derived from self_time/total_time
    cumulative   - The sum of the time spent in this method and all the methods listed above it.
    total        - The time spent in this method and its children.
    self         - The time spent in this method.
    children     - The time spent in this method's children.
    calls        - The number of times this method was called.
    self/call    - The average time spent per call in this method.
  total/call   - The average time spent per call in this method and its children.
  name         - The name of the method.

今度はcall_stack形式で可視化した結果をHTMLで出力してみる。

% ruby-prof -p call_stack -f call_stack.html target.rb
% open call_stack.html

stackprof

RubyKaigi2014 で @tmm1 が紹介していた stackprof も試してみた。GCの頻度なども計測できる。

% gem install stackprof
require 'stackprof'

StackProf.run(mode: :cpu, out: 'tmp/stackprof-cpu-myapp.dump') do
  load './target.rb'
end
% ruby loader.rb
% stackprof tmp/stackprof-cpu-*.dump --text --limit 10       
==================================
  Mode: cpu(1000)
  Samples: 60047 (0.36% miss rate)
  GC: 847 (1.41%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
     56675  (94.4%)       56675  (94.4%)     block (2 levels) in Object#print_result
      1057   (1.8%)        1057   (1.8%)     block in Object#parse_file
       896   (1.5%)         896   (1.5%)     #<Object:0x007f93d4856ac8>.write
       120   (0.2%)         120   (0.2%)     block in Object#parse_file
        73   (0.1%)          73   (0.1%)     block (3 levels) in <top (required)>
        72   (0.1%)          72   (0.1%)     block (3 levels) in <top (required)>
        58   (0.1%)          58   (0.1%)     block (2 levels) in Object#print_result
        49   (0.1%)          49   (0.1%)     block in Object#print_result
        44   (0.1%)          44   (0.1%)     block (2 levels) in Object#print_result
        43   (0.1%)          43   (0.1%)     block (3 levels) in <top (required)>

Rubyのしくみ -Ruby Under a Microscope-

Rubyのしくみ -Ruby Under a Microscope-