Rubyプログラムをプロファイラで計測する

今回は、Rubyのプロファイルを取得する機能についてのメモ。

プロファイラの実行

Rubyでは標準でプロファイルを取る機能が用意されています。ここでいうプロファイルとは、どの処理にどれ位時間が掛かってるかや、どの処理が何回呼ばれたかという分析結果です。rubyコマンドに -r profile オプションをつけて実行することで、プロファイルを取る事が出来ます。

ruby -r profile test.rb

因みに私はeclipseから実行することが主なので、eclipseから実行する場合の手順ものせておきます。

[Run As]->[Run Configurations ...]から、ArgumentsタブのInterpreter argumentsに -r profileオプションをつけます。

では、物は試しということで、簡単なfizzbuzz問題のプログラムのプロファイルを取ってみましょう。

プログラム

(1..100).each do |x|
  if x % 15 == 0 then
    puts "FizzBuzz"
  elsif x % 3 == 0 then
    puts "Fizz"
  elsif x % 5 == 0 then
    puts "Buzz"
  else 
    puts x
  end
end

実行結果

1
2
Fizz
4
Buzz
.
.
中略
.
.
Fizz
97
98
Fizz
Buzz
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
  0.00     0.00      0.00        1     0.00     0.00  TracePoint#enable
  0.00     0.00      0.00        3     0.00     0.00  Thread.current
  0.00     0.00      0.00        1     0.00     0.00  Mutex#lock
  0.00     0.00      0.00        1     0.00     0.00  MonitorMixin#mon_enter
  0.00     0.00      0.00        1     0.00     0.00  Kernel#respond_to_missing?
  0.00     0.00      0.00        1     0.00     0.00  Kernel#respond_to?
  0.00     0.00      0.00        1     0.00     0.00  Gem.suffixes
  0.00     0.00      0.00        4     0.00     0.00  Gem.find_unresolved_default_spec
  0.00     0.00      0.00        1     0.00     0.00  Array#each
  0.00     0.00      0.00        1     0.00     0.00  Gem::Specification.unresolved_deps
  0.00     0.00      0.00        1     0.00     0.00  MonitorMixin#mon_check_owner
  0.00     0.00      0.00        1     0.00     0.00  Mutex#unlock
  0.00     0.00      0.00        1     0.00     0.00  MonitorMixin#mon_exit
  0.00     0.00      0.00        4     0.00     0.00  IO#set_encoding
  0.00     0.00      0.00        2     0.00     0.00  IO#sync=
  0.00     0.00      0.00        1     0.00     0.00  Kernel#gem_original_require
  0.00     0.00      0.00        1     0.00     0.00  Kernel#require
  0.00     0.00      0.00      261     0.00     0.00  Fixnum#%
  0.00     0.00      0.00      261     0.00     0.00  Fixnum#==
  0.00     0.00      0.00       53     0.00     0.00  Fixnum#to_s
  0.00     0.00      0.00      200     0.00     0.00  IO#write
  0.00     0.00      0.00      100     0.00     0.00  IO#puts
  0.00     0.00      0.00      100     0.00     0.00  Kernel#puts
  0.00     0.00      0.00      100     0.00     0.00  nil#
  0.00     0.00      0.00        1     0.00     0.00  Range#each
  0.00     0.00      0.00        1     0.00     0.00  TracePoint#disable
  0.00     0.01      0.00        1     0.00    10.00  #toplevel

このような感じで、実行結果の後にプロファイルが出力されます。今回は単純なプログラムなので時間計測はほぼ意味が無いですが、剰余演算子の処理が何回行われたかというような情報は得られます。

各項目の意味

それぞれがどのような意味かは、リファレンスマニュアルに詳しいので引用します。

1. 全体時間のパーセンテージ
2. 全体時間の総和(単位は秒)
3. 正味時間の総和(秒)
4. 呼び出された回数
5. 1回の呼び出し当たりの平均正味時間(ミリ秒)
6. 1回の呼び出し当たりの平均全体時間(ミリ秒)
7. メソッド名

https://docs.ruby-lang.org/ja/latest/library/profile.html

その他のプロファイラ

標準で利用できるprofile以外にも、ruby-profという軽量なプロファイラ等いろいろあるようなので使って見ようと思います。