logging.rb

#!/usr/bin/env ruby

# NOTE: does not make sense to measure for large iterations, only as
# much as the logging being done on rails request, it is not as if on
# on a request 10K logging is done. With 50 logging statements i would
# prefer syslog
# NOTE: Also in buffered and syslog the
# log can get lost but logger is more reliable

# TODO: measure IO perf, if syslog logs on remote the io cost will be
# on remote.
# TODO: measure syslog-ng
# TODO: is syslog aysnc
# TODO: scribe logging

# http://stackoverflow.com/questions/1398125/what-is-the-fastest-ruby-logger-implementation/3184703#3184703

require 'benchmark'
require 'rubygems'
require 'fileutils'
require 'active_support'
require 'syslog'
require 'logger'

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

def warmup
  i = 0
  SYSLOG.info "hello #{i}"
  LOGGER.info "#{Time.now} logging_logger[Process.pid]:  INFO  logging_logger : hello #{i}"
  BUFFERED.info "#{Time.now} logging_logger[Process.pid]:  INFO  logging_logger : hello #{i}"
  puts "warmed up..."
end
warmup

TIMES = 10_000

def run_bm(times)
  puts "TIMES: #{times}"
  Benchmark.bm do |x|
    x.report('SYSLOG') { times.times { |i| SYSLOG.info "hello #{i}" } }
    x.report('LOGGER') {
      times.times do |i|
        LOGGER.info "#{Time.now} logging_logger[Process.pid]:  INFO  logging_logger : hello #{i}"
      end
    }
    x.report('BUFFERED') {
      times.times do |i|
        BUFFERED.info "#{Time.now} logging_logger[Process.pid]:  INFO  logging_logger : hello #{i}"
      end
    }
  end
end

[10, 30, 50, 1000, 10_000].each { |times| run_bm(times) }

__END__

== local machine - java and other progs running. 0GB out of 1GB memory free, load is 0.07. Uses syslog.
warmed up...

TIMES: 10
user     system      total        real
SYSLOG  0.000000   0.000000   0.000000 (  0.000117)
LOGGER  0.000000   0.000000   0.000000 (  0.000366)
BUFFERED  0.000000   0.000000   0.000000 (  0.000304)

TIMES: 30
user     system      total        real
SYSLOG  0.000000   0.000000   0.000000 (  0.000623)
LOGGER  0.000000   0.000000   0.000000 (  0.001087)
BUFFERED  0.000000   0.000000   0.000000 (  0.000933)

TIMES: 50
user     system      total        real
SYSLOG  0.000000   0.000000   0.000000 (  0.001084)
LOGGER  0.000000   0.000000   0.000000 (  0.001972)
BUFFERED  0.000000   0.000000   0.000000 (  0.001457)

TIMES: 1000
user     system      total        real
SYSLOG  0.020000   0.010000   0.030000 (  0.033214)
LOGGER  0.020000   0.010000   0.030000 (  0.036477)
BUFFERED  0.010000   0.010000   0.020000 (  0.030270)

TIMES: 10000
user     system      total        real
SYSLOG  0.090000   0.030000   0.120000 (  0.273195)
LOGGER  0.270000   0.110000   0.380000 (  0.369299)
BUFFERED  0.230000   0.080000   0.310000 (  0.320987)


== qa machine - java and other progs running. 3GB memory free, load is 0.01. Uses syslog-ng rather than syslog.
warmed up...

TIMES: 10
user     system      total        real
SYSLOG  0.000000   0.000000   0.000000 (  0.000255)
LOGGER  0.000000   0.000000   0.000000 (  0.000772)
BUFFERED  0.000000   0.000000   0.000000 (  0.000597)
TIMES: 30
user     system      total        real
SYSLOG  0.000000   0.000000   0.000000 (  0.000684)
LOGGER  0.000000   0.000000   0.000000 (  0.002276)
BUFFERED  0.000000   0.000000   0.000000 (  0.001772)
TIMES: 50
user     system      total        real
SYSLOG  0.000000   0.000000   0.000000 (  0.001110)
LOGGER  0.000000   0.010000   0.010000 (  0.003779)
BUFFERED  0.000000   0.000000   0.000000 (  0.003018)
TIMES: 1000
user     system      total        real
SYSLOG  0.010000   0.010000   0.020000 (  0.055048)
LOGGER  0.050000   0.020000   0.070000 (  0.075506)
BUFFERED  0.030000   0.030000   0.060000 (  0.059612)
TIMES: 10000
user     system      total        real
SYSLOG  0.080000   0.120000   0.200000 (  0.684841)
LOGGER  0.430000   0.330000   0.760000 (  0.763459)
BUFFERED  0.400000   0.230000   0.630000 (  0.636149)