🐷

【Rails】処理の計測を `start_time` から卒業した話

2024/01/14に公開

Benchmark

以前までの計測方法

start_time = Time.zone.now

# 計測したい処理

end_time = Time.zone.now
puts end_time - start_time

このやり方をした場合、精度の面で以下のような問題が発生する

  1. 計測したい処理以外の CPU が行なっている処理も含まれる
  2. 実時間を測定するため、システムの負荷や他のプロセス(ネットワーク通信)などの影響を受けやすく、その時の反応によって結果に変動が生まれる
  3. プログラムが 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:
    • usersystem の和
  • 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)

ソースコード

https://github.com/ruby/benchmark/blob/master/lib/benchmark.rb#L122

Discussion