ActiveState Code

Recipe 440573: Use function annotation to track elapsed execution time

This function annotates the a given function with its elapsed execution time in minutes, seconds, and milli seconds. The attricbute is a tuple named func_time. This function could also be used as a python 2.4 decorator.

Python 
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
import sys
import time

def timeit(f):
    """ Annotate a function with its elapsed execution time. """
    def timed_f(*args, **kwargs):
         t1 = time.time()

         try:
             f(*args, **kwargs)
         finally:
             t2 = time.time()

         timed_f.func_time = ((t2 - t1) / 60.0, t2 - t1, (t2 - t1) * 1000.0)

         if __debug__:
             sys.stdout.write("%s took %0.3fm %0.3fs %0.3fms\n" % (
                 f.func_name,
                 timed_f.func_time[0],
                 timed_f.func_time[1],
                 timed_f.func_time[2],
             ))

    return timed_f


def timeme():
    time.sleep(2)

timeme = timeit(timeme)

Discussion

Example $ python -i example.py

>>> timeme()
timeme took 0.033m 1.999s 1999.470ms
>>> timeme.func_time
(0.033321801821390787, 1.9993081092834473, 1999.3081092834473)

This provides a relatively straight forward way of tracking elapsed execution time and using it when you need it.

Comments

  1. 1. At 9:31 p.m. on 26 oct 2005, Edward Loper said:

    Re: Use function annotation to track elapsed execution time. Here's a slight extension that will give you the min, max, and average time spent in a function. It might be useful for very simplistic profiling.

    def timeit(f):
    """ Annotate a function with its elapsed execution time. """
    def timed_f(*args, **kwargs):
        t1 = time.time()

        try:
            f(*args, **kwargs)
        finally:
            t2 = time.time()

        dt = t2-t1
        timed_f.func_maxtime = max(dt, getattr(timed_f, 'func_maxtime', 0))
        timed_f.func_mintime = min(dt, getattr(timed_f, 'func_mintime',
                                               sys.maxint))
        timed_f.func_numcalls = getattr(timed_f, 'func_numcalls',0)+1
        timed_f.func_avgtime = ((dt+((timed_f.func_numcalls-1) *
                                     getattr(timed_f, 'func_avgtime',0))) /
                                timed_f.func_numcalls)

    return timed_f

def print_functimes(f):
    print 'Avg running time: %f secs' % f.func_avgtime
    print 'Max running time: %f secs' % f.func_maxtime
    print 'Min running time: %f secs' % f.func_mintime
    print 'Number of calls: %d' % f.func_numcalls

    (BTW, to be a friendly decorator, it's probably a good idea to copy the __doc__, __name__, etc attributes from f to timed_f.)

  2. 2. At 6:02 p.m. on 30 oct 2005, Walter Brunswick said:

    How exactly is this function supposed to be called?

  3. 3. At 9:31 a.m. on 27 mar 2006, Matteo Bertini said:

    Add a return value to timed_f. The timed_f function doesn't return any value.

    Adding a:

    res = f(...)

    and a

    return res

    at the end solves the problem of timing a function that returns something.

Sign in to comment