14

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?

2
  • Thanks for the answers, but it looks like the logging module already has this problem solved when it comes to string formatting. I was looking for a more general case that I could use when the body of the print statement isn't just % or string.format; for example, ", ".join([x.foo for x in exes if x in whys]) Oct 4, 2011 at 6:46
  • +1 for the "short-circuit" idea! Yep, standard string formatting is solved, but sometimes you have costly custom code to run in order to produce debug output.
    – gatopeich
    Jun 25, 2014 at 9:51

4 Answers 4

4

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.

1
  • Hmm... this is part of what the logger module does for me. logging.debug takes a msg and args, which it later passes to the % operator in LogRecord.getMessage() which is only called when needed. The logging module even gives me a way to override the factory for LogRecords, so I can drop in a subclass that uses string.format instead of %. This isn't a general enough solution, though. Oct 3, 2011 at 12:50
3

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.

1

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

1

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

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.

Not the answer you're looking for? Browse other questions tagged or ask your own question.