Efficient Debugging Messages: Why Unnecessary Method Calls Are Bad Mmmkay?

By Peter Cooper / November 7, 2006

I'm creating a library that sorely needs a 'debug mode' where each step of what the library does is printed to the screen for developers to check out. I wanted the debug mode to be easy to set and for the debug messages to be as non-intrusive as possible. Initially I arranged it in such a fashion:

class MyLibrary
  def initialize(options = {})
	# Set @debug here if necessary
  end

  def debug_message(msg)
    return false unless @debug
    # Print debug message in certain way here
  end

  def do_something
    # Do stuff here and in other methods
    debug_message "Such and such message"
    # Do more stuff
  end
end

Each debug message was a simple method call to a routine that only printed the message if debug mode was activated. Simple! I forgot all about it and carried on work.

Later on I decided to benchmark my library with debugging more off. I got average times of 2.7 seconds to perform the heaviest test task with my library 1000 times over. I set out looking for optimizations, and decided to try a different approach with the debugging messages to avoid calling the debug_message method hundreds of times per run:

class MyLibrary
  def initialize(options = {})
	# Set @debug here if necessary
  end

  def debug_message(msg)
    # Print debug message in certain way here
  end

  def do_something
    # Do stuff here and in other methods
    debug_message "Such and such message" if @debug
    # Do more stuff
  end
end

Immediately I saw average times of 1.9 seconds, down 30%! This was little different to the speed without any debugging messages at all, and demonstrates the overhead of calling methods. The downside, of course, is I have to tack on if @debug (or similar) to each of my debugging lines, but.. a small price to pay for 30% more performance.

Comments

Jeff says:
November 8, 2006 at 12:37 am
To REALLY clean it up, make your debug_message take a block, like the standard Logger class can. Then instead of

debug_message "Such and such message" if @debug

you can have

debug_message {"Such and such message"}

I'm not sure what the implementation looks like, but if I figure it out I'll post it. Check it out at http://www.ruby-doc.org/core/classes/Logger.html#M000166
Jeff says:
November 8, 2006 at 12:40 am
And importantly, the execution of the block is wrapped in an 'if' statement within debug_message, so the block only executes when at the appropriate logging level. It's the best of both worlds -- elegance and performance.
Jeff says:
November 8, 2006 at 12:47 am
I guess the simplest possible implementation looks as simple as:

def debug
if(@debug)
puts yield
end
end

Of course, you'll probably be doing something more interesting that a simple 'puts'.
Lionel says:
November 8, 2006 at 1:03 am
I just did some tests with eval to redefine a debug_message method instead of using @debug, was disappointed by the results (calling methods indeed is slow even if they don't do anything) and then thought of using $debug. The results are as follows :

Rehearsal --------------------------------------------
eval 2.116667 0.316667 2.433333 ( 1.523078)
instance 0.616667 0.166667 0.783333 ( 0.484443)
global 0.516667 0.150000 0.666667 ( 0.415333)
----------------------------------- total: 4.566667sec

user system total real
eval 1.983333 0.316667 2.300000 ( 1.424962)
instance 0.633333 0.166667 0.800000 ( 0.485945)
global 0.516667 0.183333 0.700000 ( 0.421243)

So you can get a boost of ~15% by using a global variable instead of an instance one (note that we are speaking of only a 60 nanosecond advantage per call on an Athlon X2 3800+ with ruby 1.8.4 64bit...).

eval uses this class :

class MyBench
def initialize()
eval("def debug_message(msg) end")
end
def do_something(n)
n.times do
debug_message 'my_message'
end
end
end

global uses this one :

class MyBench2
def initialize()
$debug = false
end
def do_something(n)
n.times do
$debug && puts('my_message')
end
end
end

The results are roughly the same with "$debug && puts ..." and "puts ... if $debug".
wilig says:
November 8, 2006 at 1:05 am
Hey Peter,

Couldn't you have used the builtin Logger class for this purpose? There is also another technique that would clean up the code considerably. Have you considered moving all the logging to another file that redefines the class to add all the logging calls? That way at the top of your file you can conditionally include the logging file and incur zero overhead and no code pollution.

Just my 2 cents.

Will
Peter Cooper says:
November 8, 2006 at 2:42 am
Nice investigative work!

Actually, using the && technique probably makes it look pretty nice after all and makes it really obvious it's a debug line.
Peter Cooper says:
November 8, 2006 at 6:05 am
wilig: It didn't need anything as advanced as that. It's really 99% for me while developing it, but I knew I'd be likely to leave the debug lines in so wanted to make them a bit more efficient. Calling Logger, however, would be even slower, I think.
Jacob Radford says:
November 8, 2006 at 10:50 pm
Simple, but nice. In fact, with all of the articles about snippets for textmate and emacs lately, you could just create a shortcut to printing out the entire line needed (with the "if @debug") and all you then have to do is fill in the text message. With something like that, you could be sure of coding it the same everytime and save keystrokes while you are at it.
Peter McMaster says:
November 10, 2006 at 12:00 am
ruby -pi -e 'gsub(/^\s*debug_message/,"# no_debug_message")' **/*.rb
=> an overhead of nil.