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.