【Ruby】rblineprofで行単位の計測を行う方法

rblineprofは行単位のプロファイリングを行うgemです。
rblineprofを利用することで『どの行でどれだけの時間がかかっているか』などが計測できます。

rblineprofの利用手順は以下の通りです。

今回はrblineprofの利用方法について紹介します。

rblineprofをインストール

rblineprofのgemをインストールします。

$ gem install rblineprof

計測対象のコードを『profile = lineprof(/./) do … end』で囲む

rblineprofはlineprof(/./) do ... endで囲まれたソースコードを解析します。

たとえば以下のようになります。
サンプルコードはrblineprofのREADMEに掲載されているものです。

example.rb

require 'rblineprof'

profile = lineprof(/./) do
  sleep 0.001

  100.times do
    sleep 0.001

    1*2*3
    4*5*6
    7*8*9*10*11*12*13*14*15
    2**32
    2**128
  end
end

計測対象のメソッドはlineprof(/./) do ... endの外で定義されていても問題ありません。

example_method.rb

require 'rblineprof'

def calculate
  1*2*3
  4*5*6
  7*8*9*10*11*12*13*14*15
  2**32
  2**128
end

profile = lineprof(/./) do
  sleep 0.001

  100.times do
    sleep 0.001
    calculate()
  end
end

『profile.keys.first』を読み込み、任意のフォーマットで出力する

profile.keys.firstに保存された計測情報に対してFile.readlinesを実行することで行単位の結果が確認できます。
rblineprofでは『経過時間（wall）』『CPU時間』『呼び出し回数』『allocations¹』の計測ができます。

出力のフォーマットは任意です。
たとえば以下の例では『CPU時間』『アイドル時間（wall – cpu）』『呼び出し回数』を出力しています。

example.rb

require 'rblineprof'

profile = lineprof(/./) do
  sleep 0.001

  100.times do
    sleep 0.001

    1*2*3
    4*5*6
    7*8*9*10*11*12*13*14*15
    2**32
    2**128
  end
end

file = profile.keys.first

File.readlines(file).each_with_index do |line, num|
  wall, cpu, calls, allocations = profile[file][num + 1]

  if wall > 0 || cpu > 0 || calls > 0
    printf(
      "% 5.1fms + % 6.1fms (% 4d) | %s",
      cpu / 1000.0,
      (wall - cpu) / 1000.0,
      calls,
      line
    )
  else
    printf "                          | %s", line
  end
end

出力結果

$ ruby example.rb

                          | require 'rblineprof'
                          |
                          | profile = lineprof(/./) do
  0.2ms +    1.1ms (   1) |   sleep 0.001
                          |
 12.9ms +  125.7ms (   1) |   100.times do
  8.4ms +  125.5ms ( 100) |     sleep 0.001
                          |
                          |     1*2*3
                          |     4*5*6
                          |     7*8*9*10*11*12*13*14*15
  0.7ms +    0.1ms ( 100) |     2**32
  1.1ms +    0.1ms ( 100) |     2**128
                          |   end
                          | end
                          |
                          | file = profile.keys.first
                          |
                          | File.readlines(file).each_with_index do |line, num|
                          |   wall, cpu, calls, allocations = profile[file][num + 1]
                          |
                          |   if wall > 0 || cpu > 0 || calls > 0
                          |     printf(
                          |       "% 5.1fms + % 6.1fms (% 4d) | %s",
                          |       cpu / 1000.0,
                          |       (wall - cpu) / 1000.0,
                          |       calls,
                          |       line
                          |     )
                          |   else
                          |     printf "                          | %s", line
                          |   end
                          | end

以下のようにすれば『CPU時間』と『呼び出し回数』だけが出力されます。

example_method.rb

require 'rblineprof'

def calculate
  1*2*3
  4*5*6
  7*8*9*10*11*12*13*14*15
  2**32
  2**128
end

profile = lineprof(/./) do
  sleep 0.001

  100.times do
    sleep 0.001
    calculate()
  end
end

file = profile.keys.first

File.readlines(file).each_with_index do |line, num|
  wall, cpu, calls, allocations = profile[file][num + 1]

  if cpu > 0 || calls > 0
    printf(
      "% 5.1fms (% 4d) | %s",
      cpu / 1000.0,
      calls,
      line
    )
  else
    printf "               | %s", line
  end
end

出力結果

$ ruby example_method.rb

               | require 'rblineprof'
               |
               | def calculate
               |   1*2*3
               |   4*5*6
               |   7*8*9*10*11*12*13*14*15
  0.6ms ( 100) |   2**32
  0.9ms ( 100) |   2**128
               | end
               |
               | profile = lineprof(/./) do
  0.1ms (   1) |   sleep 0.001
               |
 10.1ms (   1) |   100.times do
  5.8ms ( 100) |     sleep 0.001
  3.1ms ( 100) |     calculate()
               |   end
               | end
               |
               | file = profile.keys.first
               |
               | File.readlines(file).each_with_index do |line, num|
               |   wall, cpu, calls, allocations = profile[file][num + 1]
               |
               |   if cpu > 0 || calls > 0
               |     printf(
               |       "% 5.1fms (% 4d) | %s",
               |       cpu / 1000.0,
               |       calls,
               |       line
               |     )
               |   else
               |     printf "               | %s", line
               |   end
               | end

まとめ

以上でrblineprofの利用手順の紹介を終わります。

Twitter(@nishina555)やってます。フォローしてもらえるとうれしいです！

参考

• rblineprofでソースコードの行ごとの処理時間を計測する
• Railsのプロファイラを導入して速度改善をしてみた