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.
To time code with wallclock, use the ``push`` and ``pop`` functions provided
by the wallclock module::
wallclock.push('handling one request', enable=True)
wallclock.pop('handling one request')
This will produce a small tree on ``stderr`` summarizing the time taken to
[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.
``wallclock`` exposes two module-scoped symbols that can be used to control
* ``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
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.
The ``wallclock.block`` context manager automatically calls ``push`` before
evaluating the block, and ensures ``pop`` is called after exiting the block by
with wallclock.block('slow function'):
with wallclock.block('handling one request', enable=True):
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).
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
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.
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.
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.
TODO: Brief introduction on what you do with files - including link to relevant help section.