(wall) Timing with registry that displays exponentially weighted mean and standard deviation of duration per invocation

ew_timer.py

"""
example usage:
import time
from math import sqrt

def display_out(timer, func, display=print, erase=False):
    if erase:
        display = lambda message: print(f"\r{message}", end='')
    display(
        f"[{timer.name}|{func.__name__}] {timer.iteration}. "
        f"Duration: {timer.duration:.2f} (Started at: {timer.t0}) | "
        f"Mean: {timer.stats.mean:.2f} (Stdev: {sqrt(timer.stats.var):.2f})"
    )

class Foo:
    @Timers.add_output(display_out)
    @Timers.add_output(display_out, display=logging.debug)
    def __init__(self):
        self.initialized = True

    @Timers.register(name='a')
    def foo(self, n):
        time.sleep(n)

    @Timers.register(name='b')
    def bar(self, n):
        self.foo(n)

f = Foo()
# Time hase started!

f.foo(0.5)
f.bar(1)
# [a|foo] 9. Duration: 0.50 (Started at: 2018-05-17 07:40:14.916027) | Mean: 0.67 (Stdev: 0.24)
# [a|foo] 10. Duration: 1.00 (Started at: 2018-05-17 07:40:15.416985) | Mean: 0.83 (Stdev: 0.24)
# [b|bar] 5. Duration: 1.00 (Started at: 2018-05-17 07:40:15.416981) | Mean: 1.00 (Stdev: 0.00)

import pandas as pd
pd.DataFrame(Timers.get_summary())
# Timing of <__main__.Foo object at 0x7f48c7bc7c50> started at 2018-05-17 07:40:12.
#>>  	duration 	iteration 	name 	output                                  	stats                                           	t0
#.. 0  	1.001112 	10      	a   	<function Foo.<lambda> at 0x7f48c7bd8620> 	{'mean': 0.83382476171875, 'var': 0.0556825287... 	2018-05-17 07:40:15.416985
#.. 1  	1.001310 	5       	b   	<function Foo.<lambda> at 0x7f48c7bd8620> 	{'mean': 1.001174375, 'var': 5.647148437498983... 	2018-05-17 07:40:15.416981
"""

import datetime as dt
from functools import partial


def seconds_since(previous):
    return (dt.datetime.utcnow() - previous).total_seconds()

def update_stats(stats, new_obs, alpha=0.5):
    """
    Based on (adapted) equations in:
    http://people.ds.cam.ac.uk/fanf2/hermes/doc/antiforgery/stats.pdf#part9
    """
    if stats.mean is None:
        stats.mean = new_obs
    diff = new_obs - stats.mean
    incr = alpha * diff
    stats.mean = stats.mean + incr
    stats.var = (1-alpha) * (stats.var + diff * incr)
    return stats


class Stats:
    def __init__(self):
        self.mean = None
        self.var = 0


class Timer:
    """An actual instance of a timer"""
    alpha = 0.5

    def __init__(self, name, output=None):
        self.iteration = 0
        self.stats = Stats()
        self.name = name
        self.output = output
        self.t0 = None
        self.duration = None

    def start(self, func):
        def time(*args, **kwargs):
            self.t0 = dt.datetime.utcnow()
            res = func(*args, **kwargs)
            self.duration = seconds_since(self.t0)
            self.stats = update_stats(self.stats, self.duration, self.alpha)
            self.iteration += 1
            if self.output:
                for output in self.output:
                    output(self, func)
            return res
        return time


class Timers:
    """The timer registry"""
    timers=dict()
    started_at = None
    monitored = None

    @classmethod
    def get(cls, name):
        return cls.timers.get(name)

    @classmethod
    def register(cls, name=None):
        if name not in cls.timers:
            output = getattr(cls, 'output', None)
            timer = Timer(name, output)
        else:
            timer = cls.timers[name]
        cls.timers.update({name: timer})
        return timer.start

    @classmethod
    def add_output(cls, disp_func, **disp_args):
        output_func = partial(disp_func, **disp_args)
        if getattr(cls, 'output', None) is None:
            cls.output = []
        cls.output.append(output_func)
        for t in cls.timers.values():
            if getattr(t, 'output', None) is None:
                t.output = []
            t.output.append(output_func)
        return cls.wrapper

    @classmethod
    def wrapper(cls, init):
        cls.monitored = init
        def executor(*args, **kwargs):
            cls.started_at = dt.datetime.utcnow()
            if len(args) > 0:
                cls.monitored = args[0]
            return init(*args, **kwargs)
        return executor

    @classmethod
    def get_summary(cls):
        print(f"Timing of {cls.monitored} started at {cls.started_at:%Y-%m-%d %H:%M:%S}.")
        return [{k: v if k!='stats' else v.__dict__ for k, v in t.__dict__.items()} for t in cls.timers.values()]