Guarding Logger Statements In Ruby

December 9, 2009

Whether you are a Java or a Ruby programmer, I'm sure you are familiar with this idiom:

require 'logger'

log = Logger.new(STDOUT)
log.level = Logger::INFO

log.debug("hello")
log.info("Done")

That's a simple logger where the log level is set to info, so the debug statement isn't logged, but the info statement is. One gotcha to look out for is something like this:

require 'logger'

log = Logger.new(STDOUT)
log.level = Logger::INFO

def fib(n)
  if n < 1
    0
  elsif n < 2
    1
  else
    fib(n-1) + fib(n-2)
  end
end

log.debug("fib(30) => #{fib(30)}")
log.info("Done")

This also just logs "Done", but it take more than a few seconds to do so. The reason why is that even though you aren't logging the string that gets passed to debug, the ruby interpreter still has to incur the cost of generating the string and passing it to debug, where it gets ignored.

If you are an old Java programmer like me, you'll probably know you can fix it like this:

require 'logger'

log = Logger.new(STDOUT)
log.level = Logger::INFO

def fib(n)
  if n < 1
    0
  elsif n < 2
    1
  else
    fib(n-1) + fib(n-2)
  end
end

if log.debug?
  log.debug("fib(30) => #{fib(30)}")
end
log.info("Done")

That works, but it's not the Ruby way of doing it. It's the idiomatic way of doing it in Java, but that is due to the fact that Java doesn't have anonymous functions nor a concise syntax for creating them. The Ruby way of doing it is:

require 'logger'

log = Logger.new(STDOUT)
log.level = Logger::INFO

def fib(n)
  if n < 1
    0
  elsif n < 2
    1
  else
    fib(n-1) + fib(n-2)
  end
end

log.debug { "fib(30) => #{fib(30)}" }
log.info("Done")

The difference between this version and the original is that instead of passing a string to debug, we pass a block that returns a string when it is called. We don't have to wrap it in an if statement because the block can be conditionally evaluated based on the current log level.

The difference between the if statement and the block is admittedly minor. That being said, prefer the block syntax. :)

The important thing to remember is that if you have a debug statement that does any kind of calculating, pass it a block instead of just a string to avoid the overhead associated with unnecessarily building the string.

Posted in Technology | Tags RubyOnRails, Ruby, Java

Comments

1.

I've been using Ruby for a while now, once at a .net shop and now at a pure java shop and I'm still not convinced that doing things the Rubyest way is always the best idea. Little things like this can cause a lot of painful debugging to someone who's not intimately familiar with the language. What happened to the days of "write clear, obvious code" even at the expense of a couple more lines? I always prefer clarity over terseness. If I wrote the above I'd feel obligated to write a comment explaining the construct anyway.

# Posted By jw on Tuesday, February 2 2010 at 8:59 PM

Comments Disabled