What is the fastest Ruby registrar implementation?

Question

I want to find the fastest Ruby logger that can offer. My intuition tells me that syslog will win this race. But my intuition seems wrong. Syslog was the slowest of the three handlers I tested. I am using a MacBook Pro, OSX 10.6 (Snow Leopard), Intel Core2 Duo, 4 GB of RAM and Ruby 1.8.7 created from MacPorts. Am I doing something wrong? Or is Ruby syslog implementation also slow? Feel free to post your results if they differ from mine. You can also add your favorite ruby ​​registrar to the benchmark. My goal is to find the fastest registrar. I am only interested in pure performance (bandwidth). Features such as multi-purpose logging are not a problem 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 used only a simpler form: "hello # {i}" for Syslog (theoretically this should be even faster, but it is not). In addition, my Mac default syslogd has a limited message quota (500 / sec). From time to time, the following message is generated in syslog:

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

Answer 1

I assume that the first part of the BufferedLogger name explains its speed, compared to the other two, which I expect to write messages immediately after receiving them.

The trade-off will be improved throughput of a buffered object with a reduced I / O load with respect to the possible loss of log information resulting from a failure to work with unstated messages in the store.

Interestingly, in order to increase throughput without losing all the security of messages and due to the increased complexity, two forms could be combined: use a buffered logger for information that is useful, but does not require 100.0000% (for example, small random losses do not cause pain) and not buffered of your choice for messages that you simply must have, for legal or diagnostic purposes, say.

If the volume of required messages is relatively small compared to the ones you like to use (and this should be, or this approach is probably unnecessarily complicated), then which unbuffered registrar you use does not really matter.

Answer 2

Ok, I updated the script to include log4r, which I prefer because it supports so many different functions. (rolling magazines, yay!)

I also included .flush on a buffered logger and reduced the testing time so that it doesn’t forever. log4r was only slightly slower than a buffered logger. That would 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 3

tried with syslog-ng, and the results are:

TIME: 50
full user system SYSLOG 0.000000 0.000000 0.000000 (0.006187)
LOGGER 0.000000 0.010000 0.010000 (0.003698)
BUFFERED 0.000000 0.000000 0.000000 (0.003069)

a buffer recorder looks better.

Answer 4

You should also look at the logging structure (http://github.com/TwP/logging). There is a test file (https://github.com/TwP/logging/blob/master/test/benchmark.rb), on which you can see some comparisons with log4r and the main ruby ​​logger.