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 :

	import contextlib
	import time
	@contextlib.contextmanager
	def time_print(prefix):
	t0 = time.time()
	yield
	t1 = time.time()
	print "'%s' time: %fmsec" % (prefix, (t1-t0)*1000)
	def DBG_empty(message):
	"""
	Release version of debug logging function: do nothing
	"""
	pass
	def DBG(message):
	"""
	Debug logging function
	"""
	return True
	ITERATIONS = 30000
	ENABLE_DEBUG_MESSAGES = False
	SOME_LIST = xrange(8)
	with time_print("pass"):
	for x in xrange(ITERATIONS):
	pass
	with time_print("empty logging function"):
	for x in xrange(ITERATIONS):
	DBG_empty( "some message with costy parameter : '%s'" + str( [x for x in SOME_LIST ] ) )
	with time_print("if __debug__"):
	for x in xrange(ITERATIONS):
	if __debug__:
	DBG("some message with costy parameter : '%s'" + str( [x for x in SOME_LIST ] ))
	with time_print("if ENABLE_DEBUG_MESSAGES"):
	for x in xrange(ITERATIONS):
	if ENABLE_DEBUG_MESSAGES:
	DBG("some message with costy parameter : '%s'" + str( [x for x in SOME_LIST ] ))
	with time_print("assert logging function"):
	for x in xrange(ITERATIONS):
	assert DBG("some message with costy parameter : '%s'" + str( [x for x in SOME_LIST ] ))

view raw python_assert_debug_logging.py hosted with ❤ by GitHub

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