こんにちは。学生アルバイトのKawaguchiです。
作成したプログラムが遅く、この原因を特定するのに時間がかかってしまった...そんな経験はないでしょうか？
今回は、プログラムの遅い箇所を特定する方法を紹介していきます。
(Ruby単体プログラムの場合のみを対象とした内容となっております。)

サンプルコード

複数ファイルで構成されたプログラムでも、遅い箇所を特定できることを示すために、別ファイルで定義されたメソッドを呼び出して使用するサンプルを用意しました。

ファイル構成

.
├── main.rb
└── script
    ├── fast_method.rb
    └── slow_method.rb

main.rb

fast と slow メソッドを別ファイルから呼び出し、実行します。

require './script/fast_method.rb'
require './script/slow_method.rb'

fast
slow

script/fast_method.rb

早い処理の例として、0.01秒 sleep するだけの fast メソッドがあります。

def fast
  sleep 0.01
end

script/slow_method.rb

遅い処理の例として、1万回 Hoge クラスのインスタンスであるオブジェクトを生成して、0から10000までの整数の中から、ランダムに1つの整数を返す slow メソッドがあります。(明らかによろしくない箇所がありますね...)

class Hoge
  def initialize
    @integers = (0..10000).to_a
  end

  def random_integer
    @integers.sample
  end
end

def slow
  10000.times do
    hoge = Hoge.new
    hoge.random_integer
  end
end

とここまでサンプルコードの説明をしてきましたが、本当に遅いのか確認するために main.rb を実行してみましょう。

$ ruby main.rb

何も出力されませんが、プログラムの実行が終了するのに数秒かかりましたね。

それでは、このコードを例として、どのメソッドが遅いか (今回は、fast とslow メソッドのどちらが遅いか)、そして、そのメソッド中のどの処理が遅いか特定していきましょう。(このサンプルの場合、メソッド名や中のコードから分かりそうですが...)

特定していく流れ

使用gem

• rblineprof : 行ごとにかかっている時間を計測してくれる
• rblineprof-report : 計測結果を整形して出力してくれる

インストール

gem install rblineprof
gem install rblineprof-report

または Gemfile を使用する場合

gem 'rblineprof'
gem 'rblineprof-report'

$ bundle install

使用方法

main.rb

require 'rblineprof'
require 'rblineprof-report'

# すべてのRubyファイルを対象にする (gemなども計測される)
# target = /./

# カレントディレクトリ以下のRubyファイルを対象にする
target = /#{Dir.pwd}\/./

profile = lineprof(target) do
  require './script/fast_method.rb'
  require './script/slow_method.rb'

  fast
  slow
end
LineProf.report(profile)

各コードについて説明していきます。
target にはプロファイルを取りたい Ruby ファイルのパスを指定します。 このパスは文字列か正規表現で指定でき、今回はカレントディレクトリ以下の全 Ruby ファイルを対象にするために、
target = /#{Dir.pwd}\/./と正規表現で指定しています。
そして、profile = lineprof(target) doとend の間にプロファイルを取りたい処理を書きます。
最後に LineProf.report(profile)で結果を出力させます。

この Ruby ファイルを以下のコマンドで実行すると...

$ ruby main.rb

実行結果

[LineProf] ===============================================================

main.rb
               |   9  
               |  10  profile = lineprof(target) do
   0.6ms     1 |  11    require './script/fast_method.rb'
   0.2ms     1 |  12    require './script/slow_method.rb'
               |  13  
  12.7ms     1 |  14    fast
 4555.5ms     1 |  15    slow
               |  16  end
               |  17  LineProf.report(profile)
script/fast_method.rb
               |   1  def fast
  12.7ms     1 |   2    sleep 0.01
               |   3  end
script/slow_method.rb
               |   1  class Hoge
               |   2    def initialize
 4471.6ms 20000 |   3      @integers = (0..10000).to_a
               |   4    end
               |   5  
               |   6    def random_integer
   8.6ms 10000 |   7      @integers.sample
               |   8    end
               |   9  end
               |  10  
               |  11  def slow
 4555.5ms     1 |  12    10000.times do
 4512.6ms 20000 |  13      hoge = Hoge.new
  24.3ms 10000 |  14      hoge.random_integer
               |  15    end
               |  16  end

各ファイルのどの行がどのくらい時間がかかっているかが、分かりやすく出力されました。

main.rb の結果を見ると、15行目の slow が 4555.5 ミリ秒で、fast に比べて圧倒的に遅いことが分かりましたね。
そして、slow メソッドが定義されている script/slow_method.rb の結果から、13行目の hoge = Hoge.newがボトルネックだったことが判明しました。(気付いてた方も多いでしょうが...)
遅かった原因は、1万回のループの中で、毎回 Hoge クラスの initialize メソッドで0から10000までの整数の配列を作っていたことでした。この処理はループの外で一度だけ行った方が良いですよね。

では、この遅かった箇所を修正したら早くなるか確かめてみましょう。

script/slow_method.rb

class Hoge
  def initialize
    @integers = (0..10000).to_a
  end

  def random_integer
    @integers.sample
  end
end

@hoge = Hoge.new

def slow
  10000.times do
    @hoge.random_integer
  end
end

slow メソッドの外で@hoge = Hoge.newをするようにしました。

もう一度以下のコマンドで実行すると...

$ ruby main.rb

実行結果

[LineProf] ===============================================================

main.rb
               |   9  
               |  10  profile = lineprof(target) do
   0.7ms     1 |  11    require './script/fast_method.rb'
   0.7ms     1 |  12    require './script/slow_method.rb'
               |  13  
  10.5ms     1 |  14    fast
  39.9ms     1 |  15    slow
               |  16  end
               |  17  LineProf.report(profile)
script/fast_method.rb
               |   1  def fast
  10.5ms     1 |   2    sleep 0.01
               |   3  end
script/slow_method.rb
               |   1  class Hoge
               |   2    def initialize
   0.5ms     2 |   3      @integers = (0..10000).to_a
               |   4    end
               |   5  
               |   6    def random_integer
  10.1ms 10000 |   7      @integers.sample
               |   8    end
               |   9  end
               |  10  
   0.5ms     2 |  11  @hoge = Hoge.new
               |  12  
               |  13  def slow
  39.8ms     1 |  14    10000.times do
  29.1ms 10000 |  15      @hoge.random_integer
               |  16    end
               |  17  end

slow メソッドが 4555.5 ミリ秒から、39.9 ミリ秒へと劇的に速くなりましたね！
みなさんもRubyプログラムが遅くてお困りの際には、是非この方法を使ってみてはいかがでしょうか？