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.