Profiling middleware. Log wallclock, utime, stime and idle time.

about_profiling.rst

Profiling

This gist contain a set of modules to help you to profile your application

ldap_profile.py

___doc__ = """
Allow you to log ldap calls
"""
import ldap.ldapobject
import logging
import time

log = logging.getLogger(__name__)

res_fmt = '%s(%s) - %s - %s(*%r, **%r)'
fmt = '%s - %s - %s(*%r, **%r)'

_ldap_call_orig = ldap.ldapobject.LDAPObject._ldap_call


def _ldap_call(self, func, *args, **kwargs):
    name = func.__name__
    t = time.time()
    results = _ldap_call_orig(self, func, *args, **kwargs)
    t = time.time() - t
    if isinstance(results, int):
        log.info(res_fmt, name, results, t, name, args, kwargs)
    elif name == 'result3':
        log.info(res_fmt, name, args[0], t, name, args, kwargs)
    else:
        log.info(fmt, name, t, name, args, kwargs)
    return results


ldap.ldapobject.LDAPObject._ldap_call = _ldap_call

wsgi_profile.py

__doc__ = """
Profiling middleware. Log wallclock, utime, stime and idle time.

Copy the file in your source tree and wrap your application with the RUsage
middleware::

    from wsgi_profile import RUsage

    application = WSGIAppilcation()
    application = RUsage(application)

You can also use a paste config file::

    [pipeline:main]
    pipeline = profile yourapp

    [filter:profile]
    paste.filter_factory = wsgi_profile:rusage

    [app:yourapp]
    # [app:main]


"""
import resource
import logging
import time
import os

log = logging.getLogger(__name__)


class Stats(object):

    stats_keys = ['ru_utime', 'ru_stime']
    fmt = (
        '%(path)s - time: %(time)s - '
        'stime: %(ru_stime)s - utime: %(ru_utime)s - idle: %(idle)s '
    )

    def __init__(self, environ):
        self.iterator = None
        self.path = (
            '%(REQUEST_METHOD)s %(PATH_INFO)s?%(QUERY_STRING)s') % environ
        self.time = time.time()
        self.bstats = resource.getrusage(resource.RUSAGE_SELF)

    def log_stats(self):
        estats = resource.getrusage(resource.RUSAGE_SELF)
        stats = {'path': self.path}
        for k in self.stats_keys:
            stats[k] = getattr(estats, k) - getattr(self.bstats, k)
        stats['time'] = time.time() - self.time
        stats['idle'] = stats['time'] - (stats['ru_utime'] + stats['ru_stime'])
        log.info(self.fmt, stats)

    def __iter__(self):
        return self

    def next(self):
        try:
            return self.iterator.next()
        except StopIteration:
            self.log_stats()
            raise StopIteration()
    __next__ = next


class RUsage(object):

    def __init__(self, app):
        self.app = app

    def __call__(self, environ, start_response):
        _, ext = os.path.splitext(environ['PATH_INFO'])
        if ext in ('.js', '.css', '.png', '.jpg', '.gif'):
            return self.app(environ, start_response)
        stats = Stats(environ)
        iterator = self.app(environ, start_response)
        if isinstance(iterator, list):
            stats.log_stats()
            return iterator
        else:
            stats.iterator = iterator
            return iter(stats)


def rusage(*args, **kwargs):
    """Middleware factory"""
    return RUsage

wsgi_profile: there's a non-breaking space hidden in '# [app:main]' which makes Python bark, otherwise works like a charm. I dropped it in the lib/python-2.7 folder of my virtualenv.

wsgi_profile: mmm... I think 'idle' would be better renamed as 'wait'. This should take into account the time where the framework is not using the CPU because it is waiting on third party ressources (SQL, LDAP, APIs, etc.)

I'm using a slightly modified version (changed the formatting and display, it's easier to read when integer and real values are justified) : https://gist.github.com/zerodeux/8803753