Ruby標準のBenchmarkモジュールを利用したベンチマークの実行・確認方法

Ruby

Rubyの標準で用意されているBenchmarkモジュールを利用するとベンチマークテストが実行できます。

今回はBenchmarkモジュールを利用したベンチマークテストの実行および結果の確認方法について紹介します。

Benchmarkを利用したベンチマークテストの実行方法

計測対象の処理をBenchmark.bmで囲むことで、ベンチマークテストの結果がコンソールログに出力されます。

Benchmarkモジュールを利用したベンチマークテストの文法は以下の通りです。

Benchmark.bm do |x|
  x.report { 計測する処理 }　# {} の代わりに do~endも利用可能
end

ベンチマークテストの結果にはラベル付けができます。
ラベル付けをした場合の文法は以下の通りです。なお『ラベルの幅』はラベルが複数あった場合に表示位置を調整するためだけのものなので任意です。

Benchmark.bm(ラベルの幅) do |x|
  x.report(ラベル名) { 計測するロジック }
end

ベンチマークの確認方法

Benchmarkモジュールによるベンチマークは4項目で評価されます。
ベンチマークの項目の意味は以下の通りです。

項目 意味
user ユーザー（アプリケーション）のCPU時間
system システム（OS）のCPU時間
total userとsystemの合計
real 経過時間

つまり、数値が小さいほど処理が高速ということを意味しています。

たとえば以下のようにするとループ処理のベンチマークが取得できます。

require 'benchmark'

n = 50000
Benchmark.bm do |x|
  x.report { for i in 1..n; a = "1"; end }
  x.report { n.times do   ; a = "1"; end }
  x.report { 1.upto(n) do ; a = "1"; end }
end

結果は以下の通りです。

    user     system      total        real
1.033333   0.016667   1.016667 (  0.492106)
1.483333   0.000000   1.483333 (  0.694605)
1.516667   0.000000   1.516667 (  0.711077)

ラベル付けをした場合は以下のようになります。

require 'benchmark'

n = 50000
Benchmark.bm(7) do |x|
  x.report("for:")   { for i in 1..n; a = "1"; end }
  x.report("times:") { n.times do   ; a = "1"; end }
  x.report("upto:")  { 1.upto(n) do ; a = "1"; end }
end

             user     system      total        real
for:     1.050000   0.000000   1.050000 (  0.503462)
times:   1.533333   0.016667   1.550000 (  0.735473)
upto:    1.500000   0.016667   1.516667 (  0.711239)

参考: ベンチマークテスト実行中にRailsのログからSQLを消す方法

たとえばpluck(:id)とmap(&:id)のどちらが高速なのかを調べるため、Railsアプリケーションに以下のようなベンチマークを埋め込んだとします。

n = 20000
Benchmark.bm(10) do |x|
  x.report("pluck(:id)") { n.times { Student.all.pluck(:id) } }
  x.report("map(&:id)") { n.times { Student.all.map(&:id) } }
end

ベンチマークの結果をRailsログから確認しようとするとSQLのログが邪魔で見えにくいです。

実行結果

                 user     system      total        real
pluck(:id)    (0.5ms)  SELECT `students`.`id` FROM `students`
  ↳ app/controllers/students_controller.rb:19:in `block (3 levels) in index'
  CACHE  (0.0ms)  SELECT `students`.`id` FROM `students`
  ↳ app/controllers/students_controller.rb:19:in `block (3 levels) in index'
  CACHE  (0.0ms)  SELECT `students`.`id` FROM `students`
  ↳ app/controllers/students_controller.rb:19:in `block (3 levels) in index'
  CACHE  (0.0ms)  SELECT `students`.`id` FROM `students`
  ↳ app/controllers/students_controller.rb:19:in `block (3 levels) in index'
  CACHE  (0.0ms)  SELECT `students`.`id` FROM `students`
  ↳ app/controllers/students_controller.rb:19:in `block (3 levels) in index'
  0.002801   0.003985   0.006786 (  0.012958)
map(&:id)    Student Load (1.0ms)  SELECT `students`.* FROM `students`
  ↳ app/controllers/students_controller.rb:20:in `map'
  CACHE Student Load (0.1ms)  SELECT `students`.* FROM `students`
  ↳ app/controllers/students_controller.rb:20:in `map'
  CACHE Student Load (0.0ms)  SELECT `students`.* FROM `students`
  ↳ app/controllers/students_controller.rb:20:in `map'
  CACHE Student Load (0.0ms)  SELECT `students`.* FROM `students`
  ↳ app/controllers/students_controller.rb:20:in `map'
  CACHE Student Load (0.0ms)  SELECT `students`.* FROM `students`
  ↳ app/controllers/students_controller.rb:20:in `map'
  0.015031   0.000974   0.016005 (  0.025743)

ActiveRecord::Base.loggerをnilにするとSQLのログが非表示になります。ベンチマークを実行している間だけ一時的にActiveRecord::Base.logger = nilとすることで結果が見やすくなります。

+   base_logger = ActiveRecord::Base.logger
+   ActiveRecord::Base.logger = nil
    n = 20000
    Benchmark.bm(10) do |x|
      x.report("pluck(:id)") { n.times { Student.all.pluck(:id) } }
      x.report("map(&:id)") { n.times { Student.all.map(&:id) } }
    end
+   ActiveRecord::Base.logger = base_logger

実行結果

                 user     system      total        real
pluck(:id)   1.444674   0.019573   1.464247 (  1.468776)
map(&:id)    2.077519   0.005431   2.082950 (  2.089609)

まとめ

Benchモジュールを利用方法
  • 『Benchmark.bm do~end』で処理を囲むことでベンチマークテストができる
  • ベンチマークの値が小さいほど処理は高速
  • userはアプリケーションの、systemはOSのCPU時間

参考

RECOMMEND