[Python-ideas] profiling: manual instrumentation with pystones

June 7, 2008

      Hello,

To remove bottlenecks I usually instrument some functions in my application
inside a dedicated test and set speed goals there until they are met.
Then I leave the test to avoid speed regressions, when doable, by
translating times in pystones.

Unless I missed something in the standard library, I feel like there's a
missing tool to do it simply:

- the timeit module is nice to try out small code snippets but is not really
adapted to manually profile the code of an existing application
- the profile module is nice to profile an application as a whole but is not
very handy to gather statistics on specific functions in their real
execution context

What about adding a decorator that fills a statistics mapping in memory
(time+stones), like this:
...
===========
import time
import sys
import logging
from test import pystone
benchtime, stones = pystone.pystones()

def secs_to_kstones(seconds):
    return (stones*seconds) / 1000

stats = {}

def reset_stats():
    global stats
    stats = {}

def log_stats():
    template = '%s : %.2f kstones, %.3f secondes'
    for key, v in stats.items():
        logging.debug(template % (key, v['stones'], v['time']))

if sys.platform == 'win32':
    timer = time.clock
else:
    timer = time.time

def profile(name='stats', stats=stats):
    def _profile(function):
        def __profile(*args, **kw):
            start_time = timer()
            try:
                return function(*args, **kw)
            finally:
                total = timer() - start_time
                kstones = secs_to_kstones(total)
                stats[name] = {'time': total,
                               'stones': kstones}
        return __profile
    return _profile
...
===========
This allows instrumenting the application by decorating some functions,
either inside the application, either in a dedicated test:
...
======
def my_test():
    my.app.slow_stuff = profile('seem slow')(my.app.slow_stuff)
    my.app.other_slow_stuff = profile('seem slow
too')(my.app.other_slow_stuff)
# should not take more than 40k pystones !
    assert stats['seem slow too']['profile'] < 40

    # let's log them
    log_stats()
...
======
Regards,
Tarek

-- 
Tarek Ziadé | Association AfPy | www.afpy.org
Blog FR | http://programmation-python.org
Blog EN | http://tarekziade.wordpress.com/