Thread safety done right

[haizaar]

Fixes #287.
Creates new timer object on each invocation - this solves both reentrancy and thread safety (added a test for reentrancy).

It's about 5% slower than the previous version with TLS, but in fact it's only 0.12us (micro) difference per function call. Assuming that actual functions will do other things besides updating metrics, I think it's quite negligible.

Here are the detailed performance test results:

Timing manual `observe'
10000000 loops in 14.906 seconds
1.491us per iteration
670.875k iterations per second

Timing ThreadLocalTimer
10000000 loops in 23.368 seconds
2.337us per iteration
427.944k iterations per second

Timing ObjectTimer
10000000 loops in 24.539 seconds
2.454us per iteration
407.510k iterations per second

And the actual performance test code:

from threading import local

from prometheus_client.core import Summary, default_timer, decorate, _Timer


class ThreadLocalTimer(object):
    def __init__(self, callback):
        self._callback = callback
        self._storage = local()
        self.key = "k_{0}".format(id(self))

    def __enter__(self):
        setattr(self._storage, self.key, default_timer())

    def __exit__(self, typ, value, traceback):
        start = getattr(self._storage, self.key)
        # Time can go backwards.
        duration = max(default_timer() - start, 0)
        self._callback(duration)

    def __call__(self, f):
        def wrapped(func, *args, **kwargs):
            with self:
                return func(*args, **kwargs)
        return decorate(f, wrapped)


class ObjectTimer(object):
    def __init__(self, callback):
        self._callback = callback

    def _new_timer(self):
        return self.__class__(self._callback)

    def __enter__(self):
        self._start = default_timer()

    def __exit__(self, typ, value, traceback):
        # Time can go backwards.
        duration = max(default_timer() - self._start, 0)
        self._callback(duration)

    def __call__(self, f):
        def wrapped(func, *args, **kwargs):
            with self._new_timer():
                return func(*args, **kwargs)
        return decorate(f, wrapped)


def time_me(f, iterations=10000000):
    start = default_timer()
    for i in range(iterations):
        f()
    duration = default_timer() - start
    print(iterations, "loops in %.3f seconds" % duration)
    print("%.3fus per iteration" % (duration / iterations * 1000 * 1000))
    print("%.3fk iterations per second" % (iterations / duration / 1000))


def main():
    s = Summary("s", "help")
    st = Summary("st", "help")
    so = Summary("so", "help")

    dummy = lambda: None

    def s_f():
        start = default_timer()
        dummy()
        duration = max(default_timer() - start, 0)
        s.observe(duration)

    st_f = ThreadLocalTimer(st.observe)(lambda: None)
    so_f = ObjectTimer(so.observe)(lambda: None)

    print("\nTiming manual `observe'")
    time_me(s_f)
    print("\nTiming ThreadLocalTimer")
    time_me(st_f)
    print("\nTiming ObjectTimer")
    time_me(so_f)


if __name__ == "__main__":
    main()

[brian-brazil]

Thanks! I think 5% is okay, though it is annoying that Python mutexes are so slow compared to other languages.

[haizaar]

Thanks for merging. When do you plan to craft a new release?

[brian-brazil]

It's on my todo list, probably this week.