What is the fastest Ruby logger implementation?

Question

I want to find the fastest logger Ruby has to offer. My intuition tells me that syslog would win in this race. But my intuition seems to be wrong. Syslog turns out to be the slowest out of the three loggers I've tested. I'm using my MacBook Pro, OSX 10.6 (Snow Leopard), Intel Core2 Duo, 4GB of RAM and Ruby 1.8.7 built from MacPorts. Am I doing something wrong? Or Ruby's syslog implementation is just that slow? Feel free to post your results if they're different from mine. You are also welcome to add your favorite Ruby logger to the benchmark. My goal is to find the fastest logger available. I'm only interested in pure performance (throughput). Features like multi-target logging is not the concern here.

# loggers_bench.rb

require 'rbench'
require 'activesupport'
require 'syslog'
require 'logger'

buffered = ActiveSupport::BufferedLogger.new('buffered.log')
logger   = Logger.new('logger.log')
syslog   = Syslog.open('rb_syslog')

TIMES = 10_000

RBench.run(TIMES) do
  column :syslog,    :title => 'Syslog'
  column :logger,    :title => 'Logger'
  column :buffered,  :title => 'ActiveSuppoort::BufferedLogger'


  report '#info' do
    syslog {
      300.times do |i|
        syslog.info "hello #{i}"
      end
    }

    logger {
      300.times do |i|
        logger.info "#{Time.now} logging_logger[Process.pid]:  INFO  logging_logger : hello #{i}"
      end
    }
    buffered {
      300.times do |i|
        buffered.info "#{Time.now} logging_logger[Process.pid]:  INFO  logging_logger : hello #{i}"
      end
    }

  end
end

# > RUBYOPT=rubygems ruby loggers_bench.rb 
#                Syslog |  Logger | ActiveSuppoort::BufferedLogger|
# -----------------------------------------------------------------
# #info         158.316 | 117.882 |                        98.707 |

Note that I've only used the simpler form: "hello #{i}" for Syslog (in theory this should be even faster, but it's not). Also my Mac's default syslogd seems to have a limited messages quota (500/sec). The following message is generated from time to time in the syslog:

*** process 1962 exceeded 500 log message per second limit  -  remaining messages this second discarded ***

Answer 1

Ok, I updated the script to include log4r, which is my preference because it supports so many different features. (rolling logs, yay!)

I also included a .flush on the buffered logger, and lessened the test times so it doesn't take forever. log4r was only slightly slower than the buffered logger. That'd be my choice.

# loggers_bench.rb

require 'rbench'

require 'active_support'
require 'stringio'
buffered = ActiveSupport::BufferedLogger.new('buffered.log')
require 'logger'
logger   = Logger.new('logger.log')
require 'syslog'
syslog   = Syslog.open('rb_syslog')
require 'log4r'
log4r = Log4r::Logger.new 'mylog'
log4r.outputters = Log4r::FileOutputter.new('log', :filename => 'log4r.log')

TIMES = 5_000

RBench.run(TIMES) do
  column :syslog,    :title => 'Syslog'
  column :logger,    :title => 'Logger'
  column :buffered,  :title => 'ActiveSuppoort::BufferedLogger'
  column :log4r,     :title => 'log4r'


  report '#info' do
    syslog {
      10.times do |i|
        syslog.info "hello #{i}"
      end
    }

    logger {
      10.times do |i|
        logger.info "#{Time.now} logging_logger[Process.pid]:  INFO  logging_logger : hello #{i}"
      end
    }

    buffered {
      10.times do |i|
        buffered.info "#{Time.now} logging_logger[Process.pid]:  INFO  logging_logger : hello #{i}"
      end
      buffered.flush
    }

    log4r {
      10.times do |i|
        log4r.info "#{Time.now} logging_logger[Process.pid]:  INFO  logging_logger : hello #{i}"
      end
    }
  end
end
#                Syslog |  Logger | ActiveSuppoort::BufferedLogger |   log4r |
# ----------------------------------------------------------------------------
# #info           2.377 |   2.040 |                          1.425 |   1.532 |

Answer 2

I'm guessing that the first part of BufferedLogger's name explains its speed, compared with the other two, which I expect to be writing messages as soon as they're received.

The tradeoff would be the improved throughput of the buffered object with its reduced IO load against the possible loss of log information resulting from a wholesale crash with unflushed messages in store.

I wonder if, to increase throughput without the loss of all message security and at the cost of increased complexity, it might be possible to combine the two forms: use a buffered logger for information that's useful but need not be 100.0000% complete (i.e. small occasional losses don't cause pain) and a non-buffered one of your choice for messages that you simply must have, for legal or diagnostic purposes, say.

If the volume of must-have messages is relatively low compared to the nice-to-haves (and it should be or this approach is probably needlessly complex) then which non-buffered logger you use won't matter much.