Switching off debug prints

Question

Sometimes I have a lot of prints scattered around function to print debug output. To switch this debug outputs I came up with this:

def f(debug=False): 
    print = __builtins__.print if debug else lambda *p: None

Or if I need to print something apart from debug message, I create dprint function for debug messages.

The problem is, when debug=False, this print statements slow down the code considerably, because lambda *p: None is still called, and function invocation are known to be slow.

So, my question is: Is there any better way to efficiently disable all these debug prints for them not to affect code performance?

---

All the answers are regarding my not using logging module. This is a good to notice, but this doesn't answer the question how to avoid function invocations that slow down the code considerably - in my case 25 times (if it's possible (for example by tinkering with function code object to through away all the lines with print statements or somehow else)). What these answers suggest is replacing print with logging.debug, which should be even slower. And this question is about getting rid of those function calls completely.

I tried using logging instead of lambda *p: None, and no surprise, code became even slower.

---

Maybe someone would like to see the code where those prints caused 25 slowdown: http://ideone.com/n5PGu

And I don't have anything against logging module. I think it's a good practice to always stick to robust solutions without some hacks. But I thinks there is nothing criminal if I used those hacks in 20-line one-time code snippet.

---

Not as a restriction, but as a suggestion, maybe it's possible to delete some lines (e.g. starting with print) from function source code and recompile it? I laid out this approach in the answer below. Though I would like to see some comments on that solution, I welcome other approaches to solving this problem.

Answer 1

You should use the logging module instead. See http://docs.python.org/library/logging.html

Then you can set the log level depending on your needs, and create multiple logger objects, that log about different subjects.

import logging
#set your log level
logging.basicConfig(level=logging.DEBUG)
logging.debug('This is a log message')

---

In your case: you could simply replace your print statement with a log statement, e.g.:

import logging
print = __builtins__.print if debug else logging.debug

now the function will only be print anything if you set the logging level to debug

logging.basicConfig(level=logging.DEBUG)

But as a plus, you can use all other logging features on top! logging.error('error!')

Answer 2

Ned Batchelder wrote in the comment:

I suspect the slow down is in the calculation of the arguments to your debug function. You should be looking for ways to avoid those calculations. Preprocessing Python is just a distraction.

And he is right as slowdown is actually caused by formatting string with format method which happens regardless if the resulting string will be logged or not.

So, string formatting should be deferred and dismissed if no logging will occur. This may be achieved by refactoring dprint function or using log.debug in the following way:

log.debug('formatted message: %s', interpolated_value)

If message won't be logged, it won't be formatted, unlike print, where it's always formatted regardless of if it'll be logged or discarded.

The solution on log.debug's postponed formatting gave Martijn Pieters here.

Answer 3

Another solution could be to dynamically edit code of f and delete all drpint calls. But this solution is highly unrecommended to be used:

You are correct, you should never resort to this, there are so many ways it can go wrong. First, Python is not a language designed for source-level transformations, and it's hard to write it a transformer such as comment_1 without gratuitously breaking valid code. Second, this hack would break in all kinds of circumstances - for example, when defining methods, when defining nested functions, when used in Cython, when inspect.getsource fails for whatever reason. Python is dynamic enough that you really don't need this kind of hack to customize its behavior.

Here is the code of this approach, for those who like to get acquainted with it:

from __future__ import print_function

DEBUG = False

def dprint(*args,**kwargs):
    '''Debug print'''
    print(*args,**kwargs)

_blocked = False
def nodebug(name='dprint'):
    '''Decorator to remove all functions with name 'name' being a separate expressions'''
    def helper(f):      
        global _blocked
        if _blocked:
            return f

        import inspect, ast, sys

        source = inspect.getsource(f)        
        a = ast.parse(source) #get ast tree of f

        class Transformer(ast.NodeTransformer):
            '''Will delete all expressions containing 'name' functions at the top level'''
            def visit_Expr(self, node): #visit all expressions
                try:
                    if node.value.func.id == name: #if expression consists of function with name a
                        return None #delete it
                except(ValueError):
                    pass
                return node #return node unchanged
        transformer = Transformer()
        a_new = transformer.visit(a)
        f_new_compiled = compile(a_new,'<string>','exec')

        env = sys.modules[f.__module__].__dict__
        _blocked = True
        try:
            exec(f_new_compiled,env)
        finally:
            _blocked = False
        return env[f.__name__]         
    return helper


@nodebug('dprint')        
def f():
    dprint('f() started')
    print('Important output')
    dprint('f() ended')
    print('Important output2')


f()

More information: Replacing parts of the function code on-the-fly

Answer 4

As a hack, yes, that works. (And there is no chance in hell those lambda no-ops are your app's bottleneck.)

However, you really should be doing logging properly by using the logging module.

See http://docs.python.org/howto/logging.html#logging-basic-tutorial for a basic example of how this should be done.

Answer 5

You definitely need to use the logging module of Python, it's very practical and you can change the log level of your application. Example:

>>> import logging
>>> logging.basicConfig(level=logging.DEBUG)
>>> logging.debug('Test.')
DEBUG:root:Test.