背景
巨大化老朽化してきたRailsサービスのパフォーマンス改善作業を行う際、手軽に各種メソッドのベンチマークを取りながらトライアンドエラーを進めたかった。
最初は愚直にbenchmarkライブラリを使ってメソッドのベンチマークを測ろうとした。（ちなみにプロファイラはstackprofなどを使用）
class OldCarsController < ApplicationController
def index
Benchmark.bm 10 do |r| # なんか無茶なやり方
r.report "index action" do
@q = OldCar.ransack(params[:q])
time_consuming_method1
time_consuming_method2
@old_cars = @q.result(distinct: true)
end
end
end
private
def time_consuming_method1
sleep(1)
end
def time_consuming_method2
100000.times { OldCar.new }
end
end
例えばこんな形でindexアクションを実行すると、以下のようなログが出てindexアクションのベンチマークが取れるが、複数のメソッドやアクションのベンチマークを取ろうと思うとその度記述を追記しなくては行けないのが面倒臭いし、ログも一応ログファイルに置いておきたい。
user system total real
index action 2.757912 0.000000 2.757912 ( 3.773948)
また、計測したい処理内容をBenchmark.bm do ~ endで囲うと、その処理部分の戻り値はベンチマークオブジェクトになるので、戻り値を他のメソッドで使用するようなメソッドだとこの計測方法は使いづらい。
class OldCarsController < ApplicationController
def index
Benchmark.bm 10 do |r|
r.report "index action" do
@q = OldCar.ransack(params[:q])
time_consuming_method1
time_consuming_method2
@old_cars = @q.result(distinct: true)
end
end
# 戻り値が@old_carsの値ではなく計測結果のオブジェクトになる
# => [#<Benchmark::Tms:0x000055d3ab7be4c0 @label="index action", @real=3.773947899997438, @cstime=0.0, @cutime=0.0, @stime=0.0, @utime=2.7579119999999993, @total=2.7579119999999993>]
end
# （省略）
end
と言うわけで勉強がてらこれらの問題を解消できそうなgemを作ってみた。
https://github.com/shibatadaiki/Rbenchmarker
実演
require "active_support/core_ext/integer/time"
Rails.application.configure do
config.eager_load = true # 設定をtrueに変更
config.after_initialize do # 設定を追加
Rbenchmarker.setup switch: 'on', output_log_path: nil, except_classes: [], except_modules: []
end
# （省略）
end
class OldCarsController < ApplicationController
rbenchmarker all: __FILE__ # 記述を追加
def index
# （省略）
end
こんな感じで準備して、indexアクションを叩くと
# Logfile created on 2021-02-11 17:18:16 +0000 by logger.rb/v1.4.2
I, [2021-02-11T17:18:16.305563 #1] INFO -- : == Start recording Rbenchmarker ==
I, [2021-02-11T17:18:43.097913 #1] INFO -- :
report def time_consuming_method1 instance method: current time
user: 0.00265500, system: 0.00019400, total: 0.00284900, real: 1.00423010
report def time_consuming_method1 instance method: total time for 1 times called
user: 0.00265500, system: 0.00019400, total: 0.00284900, real: 1.00423010
report def time_consuming_method1 instance method: avarage time
user: 0.00265500, system: 0.00019400, total: 0.00284900, real: 1.00423010
I, [2021-02-11T17:18:45.519836 #1] INFO -- :
report def time_consuming_method2 instance method: current time
user: 2.40189500, system: 0.00000000, total: 2.40189500, real: 2.41995030
report def time_consuming_method2 instance method: total time for 1 times called
user: 2.40189500, system: 0.00000000, total: 2.40189500, real: 2.41995030
report def time_consuming_method2 instance method: avarage time
user: 2.40189500, system: 0.00000000, total: 2.40189500, real: 2.41995030
I, [2021-02-11T17:18:45.521387 #1] INFO -- :
report def index instance method: current time
user: 2.40906800, system: 0.00026500, total: 2.40933300, real: 3.43638710
report def index instance method: total time for 1 times called
user: 2.40906800, system: 0.00026500, total: 2.40933300, real: 3.43638710
report def index instance method: avarage time
user: 2.40906800, system: 0.00026500, total: 2.40933300, real: 3.43638710
通常通りの戻り値を返しつつ、裏でこんな感じのログが出力されるようになった。
（current timeがメソッドが実行されたときのタイム。total timeがプロセス起動中に二回以上同じメソッドが実行された際の総タイム。avarage timeが回数/合計の平均タイム）
とりあえずのタイムは手軽に測れるようになり、勉強にもなったので良しとする。
失敗談
製作を始めた時点では（調査不足で）気づいていなかったが、似たような発想のgemは既にあった。
https://github.com/igorkasyanchuk/benchmark_methods
機能面でいくつか異なる点もあり自分のやりたいことは自分のgemが実現したが、車輪の再発明感は否めなかった。