Eager, re-entrant elapsed time logger

gistfile1.py

from __future__ import print_function
import time
import functools
import contextlib

LOG_FMT = "{name}: {cp} @{total:0.4f}s ({dur:0.4f}s since {prev})"

def coroutine(f):
    @functools.wraps(f)
    def coro(*args, **kwargs):
        c = f(*args, **kwargs)
        next(c)
        return (lambda *args, **kwargs: c.send(*args, **kwargs))
    return coro

@contextlib.contextmanager
def elapsed(name, logger=print):

    @coroutine
    def checkpoint(name):
        cp = "start"
        start = last = time.time()
        while True:
            current = yield
            now = time.time()
            msg = LOG_FMT.format(**{
                "name": name,
                "cp": current,
                "dur": now - last,
                "prev": cp,
                "total": now - start,
            })
            logger(msg)
            last, cp = now, current

    tracker = checkpoint(name)
    yield tracker
    tracker("end")

# with elapsed("foobar") as cp:
#     time.sleep(1)
#     cp("cp1")
#     time.sleep(1)
#     cp("cp2")
#     time.sleep(1)
#     cp("cp3")
#     time.sleep(1)
#
# Output:
# foobar: cp1 @1.0011s (1.0011s since start)
# foobar: cp2 @2.0012s (1.0002s since cp1)
# foobar: cp3 @3.0016s (1.0004s since cp2)
# foobar: end @4.0024s (1.0008s since cp3)