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

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