こんにちは。永和システムマネジメントの内角低め担当、はたけやまです。
作成したプログラムが想定していた速度で動かず困ってしまうこと、ありますよね？ パフォーマンス改善を行う場合、プロファイラなどを使ってプログラムを計測し、どこがパフォーマンスのボトルネックとなっているかを見つけることが重要です。
Ruby プログラムをプロファイリングするための方法はいくつかありますが、今回は stackprof を使った方法をご紹介します。
- stackprof
stackprof を使ったプロファイリングは以下の手順で行います。
- 計測対象のプログラムに stackprof を仕込む
- 計測対象のプログラムを実行する
- 計測結果からボトルネックを割り出す
計測対象となるプログラム
今回は例題として以下のライフゲームを計測してみます。
ターミナル上でライフゲーム。 pic.twitter.com/L13eAHgnXa
— はたけやまたかし (@htkymtks) 2021年1月4日
記事を読み進めるのに実際に動かす必要はありませんが、ぜひ動かしてみたい！という方は以下の手順でどうぞ。
$ 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 で華麗に計測しちゃいましょう。
