wallclock 1.0

A simple stack-based performance logger

A simple stack-based performance logger.

Wallclock provides some simple tools for identifying slow parts of your code.
It maintains a stack of running timers, and reports the tree of execution
times when the stack empties out.

Simple Usage
------------

To time code with wallclock, use the ``push`` and ``pop`` functions provided
by the wallclock module::

import wallclock

def slow_function():
wallclock.push('slow function')
import time
time.sleep(3)
wallclock.pop('slow function')

def main():
wallclock.push('handling one request', enable=True)
slow_function()
wallclock.pop('handling one request')

main()

This will produce a small tree on ``stderr`` summarizing the time taken to
execute ``main()``::

[3.001 sec] handling one request
[3.001 sec] slow function

The ``push`` function takes one positional argument, which is the label of the
timer being pushed onto wallclock's stack. This is normally a short,
descriptive label for the kind of work that happens under timing. ``push``
also takes one optional keyword argument, ``enable``, which controls whether
this call to ``push`` should start timing (if it's not already started).
``wallclock`` ignores calls to ``push`` until it has been enabled, and
disables itself automatically when the enabling ``push`` is ``pop``ped.

The ``pop`` function takes one positional argument, which is the label to pop.
This allows for simple insertion of ``push``/``pop`` pairs surrounding code
that might return, or might raise an exception, without adding extra
``try``/``except`` blocks or similar (but see below for a better approach).
``wallclock`` will pop timers off of the stack until it finds a timer pushed
with the passed label, or until it empties the timer stack.

Configuration
-------------

``wallclock`` exposes two module-scoped symbols that can be used to control
its behaviour:

* ``wallclock.threshold`` is a number (``float``, ``int``, or ``long``) of
seconds. Any timers whose duration is strictly less than ``threshold`` will
not be recorded. By default, the threshold is approximately 10 milliseconds
(0.01 seconds). Setting the threshold to ``0`` will record every timer.
* ``wallclock.output`` is a callable object used to print recorded times. By
default, it's set to ``wallclock.stderr_output``, which writes the tree to
standard error, but applications can replace this with their own callables.
``wallclock`` invokes ``output`` with one argument, which is the root timer
object. Timer objects have three readable properties:
1. ``label``, which is the label passed to ``push`` when the timer was
created.
2. ``duration``, which is the total time recorded on the timer (in seconds).
3. ``children``, which is a sequence of timer objects that were recorded
while the passed timer object was at the top of the stack.

Automatic Timer Management
--------------------------

Manually inserting calls to ``push`` and ``pop`` works for debugging, but not
so well for leaving wallclock in place afterwards. The ``wallclock`` module
provides some tidier alternatives.

Context Manager
~~~~~~~~~~~~~~~

The ``wallclock.block`` context manager automatically calls ``push`` before
evaluating the block, and ensures ``pop`` is called after exiting the block by
any means::

import wallclock

def slow_function():
with wallclock.block('slow function'):
import time
time.sleep(3)

def main():
with wallclock.block('handling one request', enable=True):
slow_function()

main()

The ``block`` context manager accepts the same arguments that ``push``
accepts: a positional argument labelling the block, and an optional keyword
argument called ``enable`` for controlling whether the block should start
wallclock (if it's not already started).

Decorators
~~~~~~~~~~

The ``wallclock.function`` and ``wallclock.trace_function`` decorators
automatically call ``push`` before executing the decorated function, and
automatically call ``pop`` after the function exits, but before returning to
the caller::

import wallclock

@wallclock.function
def slow_function():
import time
time.sleep(3)

@wallclock.trace_function
def main():
slow_function()

main()

Both decorators determine the label for the pushed timer by examining the
called function's module and name. ``trace_function`` enables wallclock, while
``function`` does not.

Threads
-------

Wallclock makes a reasonable effort to keep a timer stack for each thread.
Timer stacks are kept in a ``threading.threadlocal`` object and are enabled
and disabled on a per-thread basis.

Performance
-----------

Timing your code is not free. While wallclock is noticably faster than a full
profiler, it still introduces overhead to manage the stack of pending timers
and the tree of completed timers. I've found the overhead to be surprisingly
large (a decorated empty function takes ~100x as long as a naked empty
function), but still well within usable limits.

Removing calls that enable wallclock reduces this overhead considerably. You
can further reduce overhead by disabling ``wallclock`` completely by calling
``wallclock.smash()``. This is an irreversible operation which replaces the
``push`` and ``pop`` operations, the ``block`` context manager, and the
``function`` and ``trace_function`` decorators with no-op equivalents.