Want to stay on top? Ruby Weekly is a once-weekly e-mail newsletter covering the latest Ruby and Rails news.
     Feed Icon

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

  1. Jeff says:

    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

  2. Jeff says:

    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.

  3. Jeff says:

    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'.

  4. Lionel says:

    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".

  5. wilig says:

    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

  6. Peter Cooper says:

    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.

  7. Peter Cooper says:

    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.

  8. Jacob Radford says:

    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.

  9. Peter McMaster says:

    ruby -pi -e 'gsub(/^\s*debug_message/,"# no_debug_message")' **/*.rb
    => an overhead of nil.

Other Posts to Enjoy

Twitter Mentions