Quick Start

Installing

First, install the timermiddleware package:

pip install timermiddleware

Setting up your timers

You can time as much or as little of your code (or code in other packages) as you like. The method for setting up your timers is best shown by example:

# yourapp/lib/middleware.py

from timermiddleware import Timer, TimerMiddleware

class MyTimerMiddleware(TimerMiddleware):
    def timers(self):
        import pymongo
        import urllib2

        return [
            # Create a 'mongo' timer, timing 3 specific methods of the Collection class
            Timer('mongo', pymongo.collection.Collection, 'count', 'find', 'find_one'),

            # Add a single 'mongo' timer. Time and sum all methods of the Cursor class
            Timer('mongo', pymongo.cursor.Cursor, '*'),

            # Alternatively, add a separate timer for each Cursor method called, e.g.,
            # 'mongo.count', 'mongo.__getitem__', 'mongo.distinct', etc.
            Timer('mongo.{method_name}', pymongo.cursor.Cursor, '*'),

            # Add a timer for each Jinja2 macro, named according to the macro name
            # NB: This has too much overhead to use in production
            Timer('jinja.macro.{instance.name}', jinja2.runtime.Macro, '__call__'),

            # Create a new timer to time the urlopen function of the urllib2 module
            Timer('urlopen', urllib2, 'urlopen'),
        ]

Installing the middleware

Next, we need to wrap our app with our new middleware:

# yourapp/config/middleware.py

from your.lib.middleware import MyTimerMiddleware
app = MyTimerMiddleware(app, app_conf)

Configuring the logger

By default, the middleware uses a logger named ‘stats’, so we need to make sure we have one. Below is a sample configuration:

# development.ini

[logger_stats]
level = INFO
handlers = stats
qualname = stats
propagate = 0

[handler_stats]
class = handlers.RotatingFileHandler
args = ('/tmp/stats.log', 'a', 1048576, 5)
level = NOTSET
formatter = stats

[formatter_stats]
format = {"time": "%(asctime)s,%(msecs)03d", "level": "%(levelname)-5.5s", "name": "%(name)s", "message": %(message)s}
datefmt = %Y-%m-%d %H:%M:%S

By default, the stats are logged as json, which makes parsing easier later.

Turning it on

Finally, tell the middleware what percentage of requests to gather stats for:

# development.ini

[app:main]
stats.sample_rate = .5

In this example, we’re timing 50% of our requests.

That’s it! As you make requests to your app, you’ll see json-formatted timing stats written to /tmp/stats.log.

Other Features

Logging debug info

Timermiddleware can log debug information for every instrumented call. To enable this extended logging, simply configure a logger for the timermiddleware package:

[logger_timermiddleware]
level = DEBUG
handlers =
qualname = timermiddleware

With the debug_each_call keyword arg, you can turn off this extended logging on a per-Timer basis as well. For example:

Timer('socket_read', socket._fileobject, 'read', debug_each_call=False)

Logging additional values

Timermiddleware has a before_logging hook, which gives you a chance to modify the ‘stat record’ (dictionary of values to be logged) before it’s actually written to the log. An example:

class MyTimerMiddleware(TimerMiddleware):
    def timers(self):
        import urllib2
        return [Timer('urlopen', urllib2, 'urlopen')]

    def before_logging(self, stat_record):
        username = stat_record.request.environ.get('yourapp.user')
        stat_record.add('username', username)
        return stat_record

In this example, we pull an app-specific variable out of the WSGI environ and log it with each stat record. stat_record.request is a webob.Request object for the current request.

Timing generator functions

Generator functions (i.e., functions that use yield) don’t actually execute the body of the function when called. Instead, they return an implicit generator object whose next() method is repeatedly called, which is where the work of the generator function is done. Thus, timing the generator function yields a cumulative time of very nearly 0.

Now, if a timed function returns a generator object, that generator object is implicitly wrapped so that the next() method is timed. To preserve the call counts of the generator function (and not unduly inflate them by the calls to the generator’s next()), a new timing bucket is created with the suffix of .next appended to the name of the bucket used for the generator function itself. The call count of the .next bucket will be large (one more than the total number of results returned), but the cumulative time will be what you are interested in for the generator function.

Getting Help

If you need help, there’s a discussion forum and ticket tracker at http://sf.net/p/timermiddleware. You can also find us hanging out in #allura on freenode IRC.