Conditionally evaluated debug statements in Python

Question

Python has a few ways of printing "trace" output. print, import logging, stdout.write can be used to print debugging info, but they all have one drawback: even if the logger's threshold is too high or the stream is closed, Python will still evaluate the arguments to the print statement. (Strict Evaluation) This could cost a string format or more.

The obvious fix is to put the string-creating code into a lambda, and use our own logging function to call the lambda conditionally (this one checks the __debug__ builtin variable, which is set to False whenever python is started with -O for optimizations) :

def debug(f):
  if __debug__:
    print f()
    #stdout.write(f())
    #logging.debug(f())

for currentItem in allItems:
  debug(lambda:"Working on {0}".format(currentItem))

The advantage is not calling str(currentItem) and string.format in release builds, and the disadvantage is having to type in lambda: on every logging statement.

Python's assert statement is treated specially by the Python compiler. If python is run with -O, then any assert statements are discarded without any evaluation. You can exploit this to make another conditionally-evaluated logging statement:

assert(logging.debug("Working on {0}".format(currentItem)) or True)

This line will not be evaluated when Python is started with -O.

The short-circuit operators 'and' and 'or' can even be used:

__debug__ and logging.debug("Working on {0}".format(currentItem));

But now we're up to 28 characters plus the code for the output string.

The question I'm getting to: Are there any standard python statements or functions that have the same conditional-evaluation properties as the assert statement? Or, does anyone have any alternatives to the methods presented here?

Answer 1

I wonder how much a call to logging.debug impacts the performance when there are no handlers.

However the if __debug__: statement is evaluated only once, even in the body of a function

$ python -O
Python 2.6.6 (r266:84292, Dec 26 2010, 22:31:48)
[GCC 4.4.5] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import dis
>>> import logging
>>> def debug(*a, **kw):
...  if __debug__:
...   logging.debug(*a, **kw)
... 
>>> dis.dis(debug)
  2           0 LOAD_CONST               0 (None)
              3 RETURN_VALUE        
>>> 

and the logger can format the message for you using the string formatting operator. Here a slightly modified example taken from the logging.debug documentation

FORMAT = '%(asctime)-15s %(clientip)s %(user)-8s %(message)s'
logging.basicConfig(format=FORMAT)
d = { 'clientip' : '192.168.0.1', 'user' : 'fbloggs' }
debug('Protocol problem: %s', 'connection reset', extra=d)

In this case the message string is never evaluated if the optimizations are turned off.

Answer 2

if all your debug function will take is a string, why not change it to take a format string and the arguments:

debug(lambda:"Working on {0}".format(currentItem))

becomes

debug("Working on {0}", currentItem)

and

if __debug__:
    def debug(format, *values):
        print format.format(*values)
else:
    def debug(format, *values): pass

this has all the advantages of your first option without the need for a lambda and if the if __debug__: is moved out the of function so that it is only tested once when the containing module is loaded the overhead of the statement is just one function call.

Answer 3

any standard python statements or function with the same conditional behavior as assert -> no, as far as I know.

Note that no string interpolation is performed by logging functions if the threshold is too high (but you still pay for the method call and some of the checks inside).

You can expand on Dan D.'s suggestion by monkeypatching logging.logger when you code starts:

import logging
if __debug__:
    for methname in ('debug', 'info', 'warning', 'error', 'exception'):
         logging.logger.setattr(methname, lambda self, *a, **kwa: None)

and then use logging as usual. You can even change the initial test to allow the replacement of the logging methods even in non optimized mode

Answer 4

You could use the eval method:

import inspect

def debug(source):
  if __debug__:
    callers_locals = inspect.currentframe().f_back.f_locals
    print eval(source, globals(),  callers_locals)

for currentItem in ('a', 'b'):
  debug('"Working on {0}".format(currentItem)')