🐷
【Rails】処理の計測を `start_time` から卒業した話
Benchmark
以前までの計測方法
start_time = Time.zone.now
# 計測したい処理
end_time = Time.zone.now
puts end_time - start_time
このやり方をした場合、精度の面で以下のような問題が発生する
- 計測したい処理以外の CPU が行なっている処理も含まれる
- 実時間を測定するため、システムの負荷や他のプロセス（ネットワーク通信）などの影響を受けやすく、その時の反応によって結果に変動が生まれる
- プログラムが CPU にどれだけの時間を消費させたかが分からない
Benchmark を導入して計測する
Benchmark とは
Ruby における、コードの実行にかかかる時間を測定するためのもの
導入
gem 'derailed_benchmarks'
基本実装
# 実装例
Benchmark.bm 10 do |r|
r.report "Hogehoge" do
# 計測したい処理1
end
r.report "Fugafuga" do
# 計測したい処理2
end
end
- 基本これで良い
-
10: ラベルの文字数（ex.Hogehoge）
※ 精度には欠けるので、複数回実行する必要がある
出力結果
user system total real
Hogehoge 0.018880 0.000952 0.019832 ( 0.024261)
Fugafuga 0.222602 0.040298 0.262900 ( 0.411602)
- 数値単位は秒
-
user:- ユーザー CPU 時間
- プログラムが直接実行する操作や計算に対する CPU 時間
-
system:- システム CPU 時間
- OS によるファイル入出力やシステムコールを使用して行なった作業によって、費やした CPU 時間
- OS の機能を呼び出さないプログラムの場合、結果は0
-
total:-
userとsystemの和
-
-
real:- 処理の開始から終了までの実際にかかった時間
-
start_time,end_timeで計測するとき同じように、他の処理の時間も含まれる
その他メソッド
1. benchmark メソッド
-ソース-
def benchmark(caption = "", label_width = nil, format = nil, *labels) # :yield: report
sync = $stdout.sync
$stdout.sync = true
label_width ||= 0
label_width += 1
format ||= FORMAT
print ' '*label_width + caption unless caption.empty?
report = Report.new(label_width, format)
results = yield(report)
Array === results and results.grep(Tms).each {|t|
print((labels.shift || t.label || "").ljust(label_width), t.format(format))
}
report.list
ensure
$stdout.sync = sync unless sync.nil?
end
-
bmメソッドで呼び出されている大元の処理- 出力結果の形式は変わらない
- フォーマットやキャプションを指定することで、ベンチマークの出力をより細かく制御できる
-実装例-
Benchmark.benchmark(Benchmark::CAPTION, 10) do |x|
x.report "Hogehoge" do
# 計測したい処理1
end
x.report "Fugafuga" do
# 計測したい処理2
end
end
-
Benchmark::CAPTION: 出力結果の一行目に表示する文字- ラベル幅に合わせた空白と一緒に出力する
module Benchmark ... def benchmark(caption = "", label_width = nil, format = nil, *labels) # :yield: report ... # 出力 print ' '*label_width + caption unless caption.empty? ... end class Tms # Default caption, see also Benchmark::CAPTION CAPTION = " user system total real\n" ... end # The default caption string (heading above the output times). CAPTION = Benchmark::Tms::CAPTION ... end -
10: ラベルの文字数
2. bmbm メソッド
-ソース-
def bmbm(width = 0) # :yield: job
job = Job.new(width)
yield(job)
width = job.width + 1
sync = $stdout.sync
$stdout.sync = true
# rehearsal
puts 'Rehearsal '.ljust(width+CAPTION.length,'-')
ets = job.list.inject(Tms.new) { |sum,(label,item)|
print label.ljust(width)
res = Benchmark.measure(&item)
print res.format
sum + res
}.format("total: %tsec")
print " #{ets}\n\n".rjust(width+CAPTION.length+2,'-')
# take
print ' '*width + CAPTION
job.list.map { |label,item|
GC.start
print label.ljust(width)
Benchmark.measure(label, &item).tap { |res| print res }
}
ensure
$stdout.sync = sync unless sync.nil?
end
- 測定を2段階（リハーサルと本測定）を実行する
- リハーサル
# リハーサル開始 puts 'Rehearsal '.ljust(width+CAPTION.length,'-') ets = job.list.inject(Tms.new) { |sum,(label,item)| print label.ljust(width) # measureメソッドで実行時間を測定 res = Benchmark.measure(&item) print res.format sum + res }.format("total: %tsec")- 本測定
# 本測定開始 print ' '*width + CAPTION job.list.map { |label,item| # ガベージコレクション実行 GC.start print label.ljust(width) Benchmark.measure(label, &item).tap { |res| print res } }
-実装例-
Benchmark.bmbm do |x|
x.report "Hogehoge" do
# 計測したい処理1
end
x.report "Fugafuga" do
# 計測したい処理2
end
end
-出力結果例-
Rehearsal --------------------------------------------
Hogehoge 0.001664 0.000053 0.001717 ( 0.001670)
Fugafuga 0.000353 0.000000 0.000353 ( 0.000352)
----------------------------------- total: 0.002022sec
user system total real
Hogehoge 0.000500 0.000000 0.000500 ( 0.000483)
Fugafuga 0.000383 0.000000 0.000383 ( 0.000361)
3. measure メソッド
-ソース-
def measure(label = "") # :yield:
t0, r0 = Process.times, Process.clock_gettime(Process::CLOCK_MONOTONIC)
yield
t1, r1 = Process.times, Process.clock_gettime(Process::CLOCK_MONOTONIC)
Benchmark::Tms.new(t1.utime - t0.utime,
t1.stime - t0.stime,
t1.cutime - t0.cutime,
t1.cstime - t0.cstime,
r1 - r0,
label)
end
- 指定した単一のブロックの実行時間を測定する
- 特定の小さなコードや関数などの実行時間を測定したい際に、シンプルに実行できる
-実装例-
result = Benchmark.measure do
# 計測したい処理
end
-出力結果例-
puts result
=> 0.000821 0.000000 0.000821 ( 1.001501)
ソースコード
Discussion