Interlude: Do Decorators Impact Performance?

It may occur to you that calling several decorator functions on several elements (especially functions and methods, since I expect there will be more of those than any other single element-type, and they could have any number of arguments, argument-list and keyword-item documentation-items) might impact performance. Will it? The short answer is I'm not sure, but I don't think so. The thinking behind that answer depends heavily on how I expect most of my development to take shape:

• Most of the code I plan on writing I expect to be of a class-library sort of structure: A number of packages and modules that will be imported into the real code.
• As a result, even in cases where there are a lot of decorator-calls taking place, they will happen during the import-process far more often than during real execution. Since an import results in a compiled (*.pyc) file, but only if the corresponding *.py file is newer, decorators will usually run only once each.

These interactions can be demonstrated easily enough...

Standing in for a final program, here is execution.py, which imports and executes MyFunction from decorated.py.

#!/usr/bin/env python
"""execution.py - Decorator proof-of-concept code: A program that calls a 
decorated function"""
import time
startTime = time.time()
print '# +- Importing from decorated'
from decorated import MyFunction
print '# +- Import from decorated complete in %0.6f seconds' % ( 
    time.time() - startTime )

print '# +- Executing in execution'
startTime = time.time()
print '#'*80
MyFunction( 'arg-value 1' )
print '#' + '-'*78 + '#'
MyFunction( 'arg-value 2' )
print '#' + '-'*78 + '#'
MyFunction( 'arg-value 3' )
print '#' + '-'*78 + '#'
MyFunction( 'arg-value 4' )
print '#' + '-'*78 + '#'
print '# +- Executing in execution completed in %0.6f seconds' % ( 
    time.time() - startTime )

Standing in for a fully-decorated class-library, here is decorated.py, which defines the MyFunction function called above, decorating it with the argument function from decorators.py.

#!/usr/bin/env python
"""decorated.py - Decorator proof-of-concept code: The decorators to import"""
import time
startTime = time.time()
print '#    +- Importing from decorators'
from decorators import argument
print '#    +- Import from decorators complete in %0.6f seconds' % ( 
    time.time() - startTime )

@argument( 'argname', 'description' )
def MyFunction( argname ):
    print 'MyFunction( %s <%s> ) called.' % ( argname, 
        type( argname ).__name__ )

Finally, standing in for the documentation-metadata decorators to be built, here is decorators.py.

#!/usr/bin/env python
"""decorators.py - Decorator proof-of-concept code: The decorators to import"""

def argument( name, description, *expects ):
    """
Decorates a function by adding an entry to its __documentationMetadata element 
for the supplied argument."""
    if not expects:
        expects = None
    print '# +- Calling argument( %s <%s>, %s <%s>, %s )' % (
        name, type( name ).__name__, description, type( description ).__name__, 
        str( expects ) )
    def _decorateAddArgument( decoratedItem ):
        """
Performs the actual decoration."""
        print '#    +- Calling _decorateAddArgument( %s <%s> )' % ( 
            decoratedItem.__name__, type( decoratedItem ).__name__ )
        if not hasattr( decoratedItem, '__documentationMetadata' ):
            decoratedItem.__documentationMetadata = {
                'arguments':{},
                }
        decoratedItem.__documentationMetadata[ 'arguments' ][ name ] = {
            'name':name,
            'description':description,
            'expects':expects,
        }
        print '#    +- _decorateAddArgument() complete' 
        return decoratedItem
    print '# +- argument() call complete'
    return _decorateAddArgument

Output from first run of code, no pyc files present.

# +- Importing from decorated
#    +- Importing from decorators
#    +- Import from decorators complete in 0.000471 seconds
# +- Calling argument( argname <str>, description <str>, None )
# +- argument() call complete
#    +- Calling _decorateAddArgument( MyFunction <function> )
#    +- _decorateAddArgument() complete
# +- Import from decorated complete in 0.000993 seconds
# +- Executing in execution
################################################################################
MyFunction( arg-value 1 <str> ) called.
#------------------------------------------------------------------------------#
MyFunction( arg-value 2 <str> ) called.
#------------------------------------------------------------------------------#
MyFunction( arg-value 3 <str> ) called.
#------------------------------------------------------------------------------#
MyFunction( arg-value 4 <str> ) called.
#------------------------------------------------------------------------------#
# +- Executing in execution completed in 0.000265 seconds

################################################################################
mtime for decorated.pyc .... 14:50:44
mtime for decorators.pyc ... 14:50:44

Output from second run of code, pyc files present.

# +- Importing from decorated
#    +- Importing from decorators
#    +- Import from decorators complete in 0.000157 seconds
# +- Calling argument( argname <str>, description <str>, None )
# +- argument() call complete
#    +- Calling _decorateAddArgument( MyFunction <function> )
#    +- _decorateAddArgument() complete
# +- Import from decorated complete in 0.000546 seconds
# +- Executing in execution
################################################################################
MyFunction( arg-value 1 <str> ) called.
#------------------------------------------------------------------------------#
MyFunction( arg-value 2 <str> ) called.
#------------------------------------------------------------------------------#
MyFunction( arg-value 3 <str> ) called.
#------------------------------------------------------------------------------#
MyFunction( arg-value 4 <str> ) called.
#------------------------------------------------------------------------------#
# +- Executing in execution completed in 0.000142 seconds

################################################################################
mtime for decorated.pyc .... 14:50:44
mtime for decorators.pyc ... 14:50:44

The initial run, where the .pyc files are being compiled, does take a little bit longer, and I have to admit that I was surprised to see that the argument() decorator-call executed during the import of decorated, but even with that, the total run-time for that import was still roughly half of what it was during the first run. I'd conclude that there is some (small) performance hit that surfaces because of the decoration, but after adding some time-tracking code to the actual decorator, its run-time seems to stay pretty consistently between 0.0001 and 0.0002 seconds, so the hit is very minimal. While I was surprised that the decorators were executed on each and every import, in retrospect, it makes perfect sense — the import, even of a compiled .pyc file, still has to be interpreted by the runtime engine, and the decorators would logically have to be executed as part of that interpretation process. I briefly added a class with a similar (and decorated) method and calls to that method of an instance to see if the pattern holds true for class-level method also, and it does:

class MyClass( object ):
    @argument( 'argname', 'description' )
    def MyMethod( self, argname ):
        print 'MyFunction( %s <%s> ) called.' % ( 
            argname, type( argname ).__name__ )

# First run:
# ...
# +- Calling argument( argname <str>, description <str>, None )
# +- argument() call complete
#    +- Calling _decorateAddArgument( MyMethod <function> )
#    +- _decorateAddArgument() complete in 0.000023 seconds
# +- Import from decorated complete in 0.017891 seconds
# +- Executing in execution
# ...
# +- Executing in execution completed in 0.000042 seconds

# Second run:
# ...
# +- Calling argument( argname <str>, description <str>, None )
# +- argument() call complete
#    +- Calling _decorateAddArgument( MyMethod <function> )
#    +- _decorateAddArgument() complete in 0.000023 seconds
# +- Import from decorated complete in 0.000500 seconds
# +- Executing in execution
# ...
# +- Executing in execution completed in 0.000037 seconds

So, while there is some small performance hit, it is small — and well within what I'd consider an acceptable range.