7/19/2011

Discardable debug message logging in python

After a short discussion about handling of diagnostics messages in python, and the cost of calling 'do nothing' functions in python, I just had an idea.

The point is to be able to (quite) brainlessly insert calls to some debug logging function through python scripts.

Alas, these calls have a cost, which we are willing to pay for a 'debug' run, but not a 'release' run, where things should go fast (or python-fast to be relative).

One first option would be to have a 'do-nothing' function replacing the logging function in 'release' runs :
if __debug__:
def DBGLOG(message):
print "[D] " + message
else:
def DBGLOG(message):
pass # do nothing
...
DBGLOG("some fancy message")

This works fine, but as CPython does not have any fancy dead code optimization combined with function inlining, it will always evaluate the arguments to the function before doing nothing. Hence, the following call will always cost some time :
DBGLOG("some message with costy parameter : '%s'" + str( [x for x in SOME_LIST ] ))

To prevent evaluating the arguments, we could use a good old if, but I don't like the thought of cluttering code with if statements...
if __debug__:
DBGLOG("some message with costy parameter : '%s'" + str( [x for x in SOME_LIST ] ))
The only form of conditional compilation I could find, in python, is related to the assert statement ; which is only evaluated if the interpreter constant __debug__ is true. We can use this at our advantage here :
assert DBGLOG("some message with costy parameter : '%s'" + str( [x for x in SOME_LIST ] ))
In this case, the parameters are not evaluated in 'release' runs (interpreter running with '-O' option).

Some quick and dirty benchmark comes below :



With the following results, on my machine :

'pass' time: 3.934145msec

'empty logging function' time: 247.512817msec

'if __debug__' time: 3.726006msec

'if ENABLE_DEBUG_MESSAGES' time: 6.114006msec

'assert logging function' time: 3.714085msec


No comments: