Ruby logging and performance

Most folks who have coded in Java understand somewhat how to protect your application for the logging performance sink-hole. The sink occurs when you have turned off debugging, but for some reason your application still runs horribly slow. After much research and sout-ing you figure out that your logging statements are being evaluated, just not logged. This occurs because the String expression is evaluated, which might call a number of toString methods on Objects, and the result is passed to the debug method of the logger. This evaluation is what slows everything down. The same applies to Ruby as well and Ruby in fact has a number of cool tricks to help out and make the code a bit easier.

Java folks will remember this as the standard way to ensure that logging statements that create a lot of Objects or call toString won’t be executed unless the logging level is set correctly:

/* or JDK logging logger.isLoggable(Level.FINEST)*/
if (logger.isDebugEnabled()) {
  logger.debug("My object is " + obj + ". Cool!");

In Ruby there are two forms of logging statements:

logger.debug("My object is " + obj + ". Cool!")
logger.debug{"My object is " + obj + ". Cool!"}

These a very similar but drastically different. The first version evaluates the String and passes the String to the debug method on the logger. The second uses a code block and passes a pointer to the code block to the debug method. The second ensures that the block is not evaluated until the logger has determined that all levels are set correctly and that it should print the logging message. This is really key because in Ruby we can build complex logging statements that would take a bit of time to construct, but ensure they won’t be evaluated unless the correct logging level is set, simply by changing our parens to curlies. Pretty slick. In Java you have to wrap the statement in an if block in order to achieve the same goal.

Here’s another cool trick:

logger.debug("My object is " + obj + ". Cool!") if logger.debug?

This statement is nearly identical to our Ruby logging statement that uses the curly braces instead of parens. The reason is that Ruby will check the if statement at the end of the line before it evaluates the statement itself. Therefore, we can ensure that the string concatenation and conversion of the Object to a string will not occur unless the logger is set to debugging level.

Personally, I prefer the curlies approach as it reduces the overall code.

2 thoughts on “Ruby logging and performance

  1. Great example of improving performance while logging in Ruby. Though, from a maintenance perspective, I’d bet money that “the next guy” who comes along and starts logging will use parens. Why? Simply because he didn’t know the trick and braces look like parens when quickly scanning example code.

    Otherwise, awesome post!


  2. Excellent point! They look very similar. This could help distinquish:

    logger.debug do “foo” end

    (Can you do blocks like that?) But that kinda looks like ass. I think the if statements perhaps are the cleanest way to handle it.


Leave a Reply

Fill in your details below or click an icon to log in: Logo

You are commenting using your account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s