1

Here I came up with the solution to the other question asked by me on how to remove all costly calling to debug output function scattered over the function code (slowdown was 25 times with using empty function lambda *p: None).

The solution is to edit function code dynamically and prepend all function calls with comment sign #.

from __future__ import print_function

DEBUG = False

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


def debug(on=False,string='dprint'):
    '''Decorator to comment all the lines of the function code starting with string'''
    def helper(f):      
        if not on:
            import inspect
            source = inspect.getsource(f)
            source = source.replace(string, '#'+string) #Beware! Swithces off the whole line after dprint statement
            with open('temp_f.py','w') as file:
                file.write(source)
            from temp_f import f as f_new
            return f_new            
        else:
            return f #return f intact
    return helper


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

f = debug(DEBUG,'dprint')(f) #If decorator @debug(True) is used above f(), inspect.getsource somehow includes @debug(True) inside the code.

f()

The problems I see now are these:

  • # commets all line to the end; but there may be other statements separated by ;. This may be addressed by deleting all pprint calls in f, not commenting, still it may be not that trivial, as there may be nested parantheses.
  • temp_f.py is created, and then new f code is loaded from it. There should be a better way to do this without writing to hard drive. I found this recipe, but haven't managed to make it work.
  • if decorator is applied with special syntax used @debug, then inspect.getsource includes the line with decorator to the function code. This line can be manually removed from string, but it may lead to bugs if there are more than one decorator applied to f. I solved it with resorting to old-style decorator application f=decorator(f).

What other problems do you see here?

How can all these problems be solved?

What are upsides and downsides of this approach?

What can be improved here?

Is there any better way to do what I try to achieve with this code?


I think it's a very interesting and contentious technique to preprocess function code before compilation to byte-code. Strange though that nobody got interested in it. I think the code I gave may have a lot of shaky points.

Community
  • 1
  • 1
ovgolovin
  • 13,063
  • 6
  • 47
  • 78
  • Oh wow, this sounds tedious. Python needs a precompiler. – Oliver Sep 01 '12 at 16:30
  • Use a decent decorator that returns the decorated function unaltered when debugging is disabled? `if not on: return f` at the start should do. – Martijn Pieters Sep 01 '12 at 16:32
  • @MartijnPieters Martijn, I don't get what you mean! :) `else: return f` doesn't do the same? – ovgolovin Sep 01 '12 at 16:33
  • A quick skim didn't see that anyone mentioned it, but maybe I missed something: I'm pretty sure the reason the `print` function, even in its `lambda *p: None` form, is so slow is because regardless of what you've set `print` to, Python has to know what arguments to pass it. So the string interpolation is happening, whether the args are dumped to stdout or not, and above whatever function call overhead there is. – DSM Sep 01 '12 at 16:49
  • @DSM Yes, parameters are still calculated before call. So removing the call statements from the function code will solve the problem. As Oliver suggested, this removing should be handled by preprocessor. But Python being a highly dynamic language may handle in even during execution with a bit contrived methods though. – ovgolovin Sep 01 '12 at 16:53
  • @ovgolovin: in neither of these questions do you show the *actual* code where you call the debugging calls. 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. – Ned Batchelder Sep 01 '12 at 17:18
  • @NedBatchelder You are exactly right! The slowdown is because of `format` method of strings which are sent as parameters to `print` statements. Code: http://ideone.com/n5PGu (I gave the links in the other question, but they appear to be hardly visible). – ovgolovin Sep 01 '12 at 17:22
  • @NedBatchelder Thank you for the advice. I think that the `dprint` should be refactored to perform formatting later if needed. As Martijn Pieters [noticed](http://stackoverflow.com/questions/12229424/replacing-parts-of-the-function-code-on-the-fly/12229535#comment16387921_12229535), `debug` module provides such a functionality. Unfortunately only with old-style formatting. – ovgolovin Sep 01 '12 at 17:31

2 Answers2

2

A decorator can return either a wrapper, or the decorated function unaltered. Use it to create a better debugger:

from functools import wraps

def debug(enabled=False):
    if not enabled:
        return lambda x: x  # Noop, returns decorated function unaltered

    def debug_decorator(f):
        @wraps(f)
        def print_start(*args, **kw):
            print('{0}() started'.format(f.__name__))
            try:
                return f(*args, **kw)
            finally:
                print('{0}() completed'.format(f.__name__))
        return print_start
    return debug_decorator

The debug function is a decorator factory, when called it produces a decorator function. If debugging is disabled, it simply returns a lambda that returns it argument unchanged, a no-op decorator. When debugging is enabled, it returns a debugging decorator that prints when a decorated function has started and prints again when it returns.

The returned decorator is then applied to the decorated function.

Usage:

DEBUG = True

@debug(DEBUG)
def my_function_to_be_tested():
    print('Hello world!')

To reiterate: when DEBUG is set to false, the my_function_to_be_tested remains unaltered, so runtime performance is not affected at all.

Martijn Pieters
  • 1,048,767
  • 296
  • 4,058
  • 3,343
  • Oh! No. This is not what I'm trying to achieve. In my code debug prints are allover the code, not only at the beginning and at the end. I wan't to delete those prints completely from the code. – ovgolovin Sep 01 '12 at 16:47
  • @ovgolovin: You really want to rethink that approach, I think. :-) Rewriting your python code on-the-fly is usually not a good idea. – Martijn Pieters Sep 01 '12 at 16:47
  • You seem to be not getting the point of what I'm trying to achive. Have a look at this question: http://stackoverflow.com/questions/12223204/switching-off-debug-prints/12227731#12227731 and explain how you solution may help? – ovgolovin Sep 01 '12 at 16:49
  • @ovgolovin: perhaps you should be using the [`logging` module](http://docs.python.org/library/logging.html) instead; calls to `log.debug(msg)` go ignored if the log level is too high. – Martijn Pieters Sep 01 '12 at 16:49
  • @ovgolovin: ah, on that linked question the highest-voted answer is the same as my advise: don't dynamically switch of print statements, use the logging framework instead. – Martijn Pieters Sep 01 '12 at 16:50
  • Logging is even slower than print statements. – ovgolovin Sep 01 '12 at 16:54
  • The question is about complete removing `dprint` call statements or avoid overhead involved with its calling. The overhead is caused by string `format` method I use extensively. And the string is formatted regardless of it will be logged or dumped. – ovgolovin Sep 01 '12 at 16:57
  • 1
    @ovgolovin: That is a pretty broad statement, that depends entirely on the logging configuration. Using `log.debug('formatted message: %s', interpolated_value)` *avoids* string formatting altogether if the debug message would not be logged due to configuration. – Martijn Pieters Sep 01 '12 at 16:57
  • In my code snippet the speed up after removing all prints was 20-fold. And the whole question is about getting rid of the overhead, not to argue if to log better with `logging` module or with `print` statement. In both cases string to be written to log is preformatted, which causes a major slowdown. – ovgolovin Sep 01 '12 at 16:59
  • 2
    @ovgolovin: Sometimes, SO is about teaching a man to fish, not just handing him a fish. :-) Let me repeat: `logging` *does not format the string* if the information is not going to be logged due to the current configuration. – Martijn Pieters Sep 01 '12 at 17:01
  • `log.debug('formatted message: %s', interpolated_value)`: Hm. This is interesting. This postpones the string formatting. But this is very good to be in [the other question](http://stackoverflow.com/questions/12223204/switching-off-debug-prints/12227731). And it has very little to do with this question, which is about editing function on-the-fly (which is more of a puzzle for theaching, not for making something real). – ovgolovin Sep 01 '12 at 17:02
  • @ovgolovin: No, only old-style is supported, see [the documentation](http://docs.python.org/py3k/library/logging.html#logging.Logger.debug). – Martijn Pieters Sep 01 '12 at 17:14
  • Thanks! And about your answer. You write that if debugging is not needed, `f` is returned untouched. The same thing happens in my code. `debug(True)` returns `helper`. `helper` decorates `f`: if `debug` is `True`, than `print` statements are not removed, so this line `return f`; if `DEBUG` is `False`, than `f_new` is returned by `helper` which contains recompiled code with `print` statements commented troughout the code. – ovgolovin Sep 01 '12 at 17:19
  • @ovgolovin: Yes, that indeed the case. – Martijn Pieters Sep 01 '12 at 17:22
1

Here is the solution I came up with after composing answers from another questions asked by me here on StackOverflow.

This solution don't comment anything and just deletes standalone dprint statements. It uses ast module and works with Abstract Syntax Tree, it lets us avoid parsing source code. This idea was written in the comment here.

Writing to temp_f.py is replaced with execution f in necessary environment. This solution was offered here.

Also, the last solution addresses the problem of decorator recursive application. It's solved by using _blocked global variable.

This code solves the problem asked to be solved in the question. But still, it's suggested not to be used in real projects:

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.

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

Other relevant links:

Community
  • 1
  • 1
ovgolovin
  • 13,063
  • 6
  • 47
  • 78