esm アジャイル事業部 開発者ブログ

永和システムマネジメント アジャイル事業部の開発者ブログです。

プロファイラを使ってRubyのコードをパフォーマンス改善したい

こんにちは。永和システムマネジメントの内角低め担当、はたけやまです。

作成したプログラムが想定していた速度で動かず困ってしまうこと、ありますよね? パフォーマンス改善を行う場合、プロファイラなどを使ってプログラムを計測し、どこがパフォーマンスのボトルネックとなっているかを見つけることが重要です。

Ruby プログラムをプロファイリングするための方法はいくつかありますが、今回は stackprof を使った方法をご紹介します。

stackprof を使ったプロファイリングは以下の手順で行います。

  • 計測対象のプログラムに stackprof を仕込む
  • 計測対象のプログラムを実行する
  • 計測結果からボトルネックを割り出す

計測対象となるプログラム

今回は例題として以下のライフゲームを計測してみます。

記事を読み進めるのに実際に動かす必要はありませんが、ぜひ動かしてみたい!という方は以下の手順でどうぞ。

$ git clone https://github.com/thata/lifegame-ruby.git
$ cd lifegame-ruby/
$ bundle install
$ bundle exec ruby main.rb
(Ctrl-Cで終了)

計測対象のプログラムに stackprof を仕込む

まず stackprof をインストールします。stackprof は RubyGems として提供されているので、Gemfile へ以下を追加して $ bundle install を実行してください。

diff --git a/Gemfile b/Gemfile
index dfc4a95..93fd4d1 100644
--- a/Gemfile
+++ b/Gemfile
@@ -1,3 +1,4 @@
 source "https://rubygems.org"
 
 gem "pry"
+gem "stackprof"

次に計測対象のプログラムへ以下のような感じに stackprof を仕込みます。out パラメータで指定されたファイル( /tmp/stackprof.dump )へプロファイリングの結果が出力されます。

diff --git a/1000_generation.rb b/1000_generation.rb
index 66a209a..41075cd 100644
--- a/1000_generation.rb
+++ b/1000_generation.rb
@@ -14,4 +14,7 @@ def start_game
   end
 end
 
-start_game
+# ブロック内の処理を計測
+StackProf.run(out: '/tmp/stackprof.dump') do
+  start_game
+end

計測対象のプログラムを実行する

次に、計測対象のプログラムを実行してプロファイリング情報を収集します。プロファイリングの結果は先ほど指定した /tmp/stackprof.dump へ出力されます。

$ time bundle exec ruby 1000_generation.rb

stackprof はサンプリング型のプロファイラ(1秒間に1000回スタックフレームを確認してどのメソッドが実行中かを調べる)なため「メソッドの実行割合」は調べることができますが「メソッドの実行時間」は調べることができません。そのため、時間の計測のため time コマンドを利用します。

計測結果からボトルネックを割り出す

出力されたプロファイリング結果を stackprof コマンドで確認します。

$ bundle exec stackprof --limit 100 /tmp/stackprof.dump

(省略)

bundle exec ruby 1000_generation.rb  1.97s user 0.15s system 96% cpu 2.203 total
==================================
  Mode: wall(1000)
  Samples: 1756 (0.00% miss rate)
  GC: 55 (3.13%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       760  (43.3%)         760  (43.3%)     LifeGame#alive?
      1086  (61.8%)         534  (30.4%)     LifeGame#num_of_neighbors
       213  (12.1%)         213  (12.1%)     LifeGame#cell_str
       314  (17.9%)         101   (5.8%)     LifeGame#dump_cell
        48   (2.7%)          48   (2.7%)     (sweeping)
      1383  (78.8%)          45   (2.6%)     LifeGame#next_generation
      1338  (76.2%)          44   (2.5%)     LifeGame#next_generation_cell
         6   (0.3%)           6   (0.3%)     (marking)
      1701  (96.9%)           3   (0.2%)     Object#start_game
         1   (0.1%)           1   (0.1%)     LifeGame#initialize
        55   (3.1%)           1   (0.1%)     (garbage collection)
      1701  (96.9%)           0   (0.0%)     <main>
      1701  (96.9%)           0   (0.0%)     <main>
      1701  (96.9%)           0   (0.0%)     block in <main>

出力された結果を見ると、LifeGame#alive?LifeGame#num_of_neighbors に比較的時間がかかっていることが分かります。

パフォーマンス改善してみる

alive? はあまり高速化しようがなかったので、num_of_neighbors で無駄な計算を行わないようにしてみます。

diff --git a/lib/life_game.rb b/lib/life_game.rb
index fdf877a..de370e4 100644
--- a/lib/life_game.rb
+++ b/lib/life_game.rb
@@ -66,74 +66,52 @@ private
 
   def num_of_neighbors(x, y)
     n = 0
-    _x = 0
-    _y = 0
+    # セルをループさせるため、画面の端のセルを逆側の端のセルとつなげる
+    left_x = x - 1
+    left_x = @width - 1 if left_x < 0
+    right_x = x + 1
+    right_x = 0 if right_x >= @width
+    up_y = y - 1
+    up_y = @height - 1 if up_y < 0
+    down_y = y + 1
+    down_y = 0 if down_y >= @height
 
     # left
-    _x = x - 1
-    _x = @width - 1 if _x < 0
-    _y = y
-    if alive?(_x, _y)
+    if alive?(left_x, y)
       n += 1
     end
 
     # right
-    _x = x + 1
-    _x = 0 if _x >= @width
-    _y = y
-    if alive?(_x, _y)
+    if alive?(right_x, y)
       n += 1
     end
 
     # up
-    _x = x
-    _y = y - 1
-    _y = @height - 1 if _y < 0
-    if alive?(_x, _y)
+    if alive?(x, up_y)
       n += 1
     end
 
     # down
-    _x = x
-    _y = y + 1
-    _y = 0 if _y >= @height
-    if alive?(_x, _y)
+    if alive?(x, down_y)
       n += 1
     end
 
     # upleft
-    _x = x - 1
-    _x = @width - 1 if _x < 0
-    _y = y - 1
-    _y = @height - 1 if _y < 0
-    if alive?(_x, _y)
+    if alive?(left_x, up_y)
       n += 1
     end
 
     # upright
-    _x = x + 1
-    _x = 0 if _x >= @width
-    _y = y - 1
-    _y = @height - 1 if _y < 0
-    if alive?(_x, _y)
+    if alive?(right_x, up_y)
       n += 1
     end
 
     # downright
-    _x = x + 1
-    _x = 0 if _x >= @width
-    _y = y + 1
-    _y = 0 if _y >= @height
-    if alive?(_x, _y)
+    if alive?(right_x, down_y)
       n += 1
     end
 
     # downleft
-    _x = x - 1 
-    _x = @width - 1 if _x < 0
-    _y = y + 1
-    _y = 0 if _y >= @height
-    if alive?(_x, _y)
+    if alive?(left_x, down_y)
       n += 1
     end
 

再度計測してみると、以下のように若干パフォーマンスが改善しました。やったね。

  • 実行時間
    • 2.203秒 → 1.842秒
  • 全体に占めるnum_of_neighborsの割合
    • 30.4% → 18.9%
bundle exec ruby 1000_generation.rb  1.62s user 0.14s system 95% cpu 1.842 total
==================================
  Mode: wall(1000)
  Samples: 1391 (0.00% miss rate)
  GC: 53 (3.81%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
       694  (49.9%)         694  (49.9%)     LifeGame#alive?
       743  (53.4%)         263  (18.9%)     LifeGame#num_of_neighbors
       196  (14.1%)         196  (14.1%)     LifeGame#cell_str
       297  (21.4%)         101   (7.3%)     LifeGame#dump_cell
      1035  (74.4%)          44   (3.2%)     LifeGame#next_generation
        40   (2.9%)          40   (2.9%)     (sweeping)
       991  (71.2%)          34   (2.4%)     LifeGame#next_generation_cell
        13   (0.9%)          13   (0.9%)     (marking)
      1338  (96.2%)           6   (0.4%)     Object#start_game
      1338  (96.2%)           0   (0.0%)     <main>
      1338  (96.2%)           0   (0.0%)     <main>
      1338  (96.2%)           0   (0.0%)     block in <main>
        53   (3.8%)           0   (0.0%)     (garbage collection)

終わりに

今回は stackprof を使ってパフォーマンスの計測と改善を行いました。

モニタリング系の SaaSとして Datadog や New Relic などがありますが、それらレポートだけじゃ良くわからないよーという時は懐に忍ばせた stackprof で華麗に計測しちゃいましょう。

参考