Rubyのloggerの出力メッセージをブロックで指定

まとめ

Rubyのloggerでブロックを使った出力ができることを初めて知った

本題

RubyのloggerでDEBUGのログを出力しているが、本番環境ではDEBUGレベルは不要な場合、出力内容が単純な文字列でなくて計算量が必要なとき、無駄に評価をして時間がかかってしまう。

ラムダ使って遅延評価できないかなと思って仕様見たら、もともとブロックを指定することが可能だった。

# 例
logger.debug "bug #{sleep 10; 1}" # 10秒待つ
logger.debug { "bug #{sleep 10; 1}" } # debugレベルの出力がなければ待たない

適当なベンチマーク

ソースコード

logger_benchmark.rb

require 'benchmark'
require 'logger'

arr = Array.new(10, "x")
logger = Logger.new("/dev/null")

puts "Error level"
logger.level = Logger::ERROR
Benchmark.bmbm do |x|
  x.report { 100000.times { logger.debug   "sample log"   } }
  x.report { 100000.times { logger.debug { "sample log" } } }
  x.report { 100000.times { logger.debug   "#{arr.join(",")}" } }
  x.report { 100000.times { logger.debug { "#{arr.join(",")}" } } }
end

puts "\nDebug level"
logger.level = Logger::DEBUG
Benchmark.bmbm do |x|
  x.report { 100000.times { logger.debug   "sample log"   } }
  x.report { 100000.times { logger.debug { "sample log" } } }
  x.report { 100000.times { logger.debug   "#{arr.join(",")}" } }
  x.report { 100000.times { logger.debug { "#{arr.join(",")}" } } }
end

結果

Error level
Rehearsal ------------------------------------
   0.030000   0.000000   0.030000 (  0.027272)
   0.040000   0.010000   0.050000 (  0.052547)
   0.130000   0.000000   0.130000 (  0.126390)
   0.050000   0.000000   0.050000 (  0.052135)
--------------------------- total: 0.260000sec

       user     system      total        real
   0.020000   0.000000   0.020000 (  0.019880)
   0.050000   0.000000   0.050000 (  0.049922)
   0.130000   0.000000   0.130000 (  0.120865)
   0.050000   0.000000   0.050000 (  0.046710)

Debug level
Rehearsal ------------------------------------
   0.220000   1.040000   1.260000 (  1.252479)
   0.320000   1.020000   1.340000 (  1.346189)
   0.300000   1.100000   1.400000 (  1.396905)
   0.360000   1.140000   1.500000 (  1.503674)
--------------------------- total: 5.500000sec

       user     system      total        real
   0.270000   0.980000   1.250000 (  1.253186)
   0.370000   0.970000   1.340000 (  1.336159)
   0.290000   1.110000   1.400000 (  1.402313)
   0.430000   1.100000   1.530000 (  1.522883)

単純な処理ならブロック使わない方が早いけど、重い処理なら（出力しない場合は）当然ブロックの方が早い。