From 0cca2e641da7ecdcbe65dd436dc76ef649d0a079 Mon Sep 17 00:00:00 2001 From: Ron Cohen Date: Mon, 2 Mar 2015 20:20:07 +0100 Subject: [PATCH 1/5] Expose a context manager for histograms - Makes it a lot easier to use AppMetrics to time specific parts of the code - Modifies the documentation a little, to make it clear that `with_histogram` will in fact "time" your code when used in a decorator. --- README.rst | 10 +++++++++- appmetrics/histogram.py | 8 ++++++++ appmetrics/tests/test_histogram.py | 7 +++++++ 3 files changed, 24 insertions(+), 1 deletion(-) diff --git a/README.rst b/README.rst index 8c0b11c..cd56aba 100644 --- a/README.rst +++ b/README.rst @@ -54,7 +54,7 @@ an internal registry, so you can access it in different places in your applicati The ``metrics`` registry is thread-safe, you can safely use it in multi-threaded web servers. -Now let's decorate some function:: +Using the ``with_histogram`` decorator we can time a function:: >>> import time, random >>> @metrics.with_histogram("test") @@ -70,6 +70,14 @@ and let's see the results:: >>> metrics.get("test") {'arithmetic_mean': 0.41326093673706055, 'kind': 'histogram', 'skewness': 0.2739718270714368, 'harmonic_mean': 0.14326954591313346, 'min': 0.0613858699798584, 'standard_deviation': 0.4319169569113129, 'median': 0.2831099033355713, 'histogram': [(1.0613858699798584, 3), (2.0613858699798584, 0)], 'percentile': [(50, 0.2831099033355713), (75, 0.2831099033355713), (90, 0.895287036895752), (95, 0.895287036895752), (99, 0.895287036895752), (99.9, 0.895287036895752)], 'n': 3, 'max': 0.895287036895752, 'variance': 0.18655225766752892, 'geometric_mean': 0.24964828731906127, 'kurtosis': -2.3333333333333335} +It is also possible to time specific sections of the code by using the ``time`` context manager:: + + >>> import time, random + ... def my_worker(): + ... with metrics.metric("test").time(): + ... time.sleep(random.random()) + ... + Let's print the metrics data on the screen every 5 seconds:: >>> from appmetrics import reporter diff --git a/appmetrics/histogram.py b/appmetrics/histogram.py index 30f6a36..5ce08e8 100644 --- a/appmetrics/histogram.py +++ b/appmetrics/histogram.py @@ -21,6 +21,7 @@ import time import operator import math +from contextlib import contextmanager from . import statistics, exceptions, py3comp @@ -339,6 +340,13 @@ def raw_data(self): return self.reservoir.values + @contextmanager + def time(self): + t1 = time.time() + yield + t2 = time.time() + self.notify(t2-t1) + def get(self): """Return the computed statistics over the gathered data""" diff --git a/appmetrics/tests/test_histogram.py b/appmetrics/tests/test_histogram.py index 2e7bad2..0e6fa0e 100644 --- a/appmetrics/tests/test_histogram.py +++ b/appmetrics/tests/test_histogram.py @@ -361,6 +361,13 @@ def test_notify(self): [mock.call(1.2)]) nt.assert_equal(result, self.reservoir.add.return_value) + def test_time(self): + self.histogram.notify = mock.Mock() + with self.histogram.time(): + pass + + nt.assert_equal(self.histogram.notify.call_count, 1) + def test_raw_data(self): result = self.histogram.raw_data() nt.assert_equal(result, self.reservoir.values) From 22637fc94bdd534a5546e42c3b726013c2b43f10 Mon Sep 17 00:00:00 2001 From: Ron Cohen Date: Mon, 2 Mar 2015 21:20:54 +0100 Subject: [PATCH 2/5] PEP8 --- appmetrics/histogram.py | 62 ++++++++++++++++++++++++----------------- 1 file changed, 36 insertions(+), 26 deletions(-) diff --git a/appmetrics/histogram.py b/appmetrics/histogram.py index 5ce08e8..9c2d58e 100644 --- a/appmetrics/histogram.py +++ b/appmetrics/histogram.py @@ -33,15 +33,16 @@ def search_greater(values, target): """ - Return the first index for which target is greater or equal to the first item of the tuple found in values + Return the first index for which target is greater or equal to the first + item of the tuple found in values """ first = 0 last = len(values) while first < last: - middle = (first+last)//2 + middle = (first + last) // 2 if values[middle][0] < target: - first = middle+1 + first = middle + 1 else: last = middle @@ -52,13 +53,15 @@ class ReservoirBase(object): __metaclass__ = abc.ABCMeta """ - Base class for reservoirs. Subclass and override _do_add, _get_values and _same_parameters + Base class for reservoirs. Subclass and override _do_add, _get_values and + _same_parameters """ def add(self, value): """ Add a value to the reservoir - The value will be casted to a floating-point, so a TypeError or a ValueError may be raised. + The value will be casted to a floating-point, so a TypeError or a + ValueError may be raised. """ if not isinstance(value, float): @@ -74,7 +77,6 @@ def values(self): return self._get_values() - @property def sorted_values(self): """ @@ -85,7 +87,8 @@ def sorted_values(self): def same_kind(self, other): """ - Return True if "other" is an object of the same type and it was instantiated with the same parameters + Return True if "other" is an object of the same type and it was + instantiated with the same parameters """ return type(self) is type(other) and self._same_parameters(other) @@ -105,15 +108,17 @@ def _get_values(self): @abc.abstractmethod def _same_parameters(self, other): """ - Return True if this object has been instantiated with the same parameters as "other". + Return True if this object has been instantiated with the same + parameters as "other". Override in subclasses """ class UniformReservoir(ReservoirBase): """ - A random sampling reservoir of floating-point values. Uses Vitter's Algorithm R to produce a statistically - representative sample (http://www.cs.umd.edu/~samir/498/vitter.pdf) + A random sampling reservoir of floating-point values. Uses Vitter's + Algorithm R to produce a statistically representative sample + (http://www.cs.umd.edu/~samir/498/vitter.pdf) """ def __init__(self, size=DEFAULT_UNIFORM_RESERVOIR_SIZE): @@ -130,8 +135,8 @@ def _do_add(self, value): self._values[self.count] = value changed = True else: - # not randint() because it yields different values on python 3, it - # would be a nightmare to test. + # not randint() because it yields different values on + # python 3, it would be a nightmare to test. k = int(random.uniform(0, self.count)) if k < self.size: self._values[k] = value @@ -201,7 +206,8 @@ def _do_add(self, value): def tick(self, now): target = now - self.window_size - # the values are sorted by the first element (timestamp), so let's perform a dichotomic search + # the values are sorted by the first element (timestamp), so let's + # perform a dichotomic search idx = search_greater(self._values, target) # older values found, discard them @@ -230,14 +236,16 @@ class ExponentialDecayingReservoir(ReservoirBase): See http://dimacs.rutgers.edu/~graham/pubs/papers/fwddecay.pdf """ - #TODO: replace the sort()s with a proper data structure (btree/skiplist). However, since the list - # is keep sorted (and it should be very small), the sort() shouldn't dramatically slow down - # the insertions, also considering that the search can be log(n) in that way + # TODO: replace the sort()s with a proper data structure (btree/skiplist). + # However, since the list is keep sorted (and it should be very small), + # the sort() shouldn't dramatically slow down the insertions, also + # considering that the search can be log(n) in that way RESCALE_THRESHOLD = 3600 EPSILON = 1e-12 - def __init__(self, size=DEFAULT_UNIFORM_RESERVOIR_SIZE, alpha=DEFAULT_EXPONENTIAL_DECAY_FACTOR): + def __init__(self, size=DEFAULT_UNIFORM_RESERVOIR_SIZE, + alpha=DEFAULT_EXPONENTIAL_DECAY_FACTOR): self.size = size self.alpha = alpha self.start_time = time.time() @@ -250,13 +258,15 @@ def __init__(self, size=DEFAULT_UNIFORM_RESERVOIR_SIZE, alpha=DEFAULT_EXPONENTIA def _lookup(self, timestamp): """ - Return the index of the value associated with "timestamp" if any, else None. - Since the timestamps are floating-point values, they are considered equal if their absolute - difference is smaller than self.EPSILON + Return the index of the value associated with "timestamp" if any, else + None. Since the timestamps are floating-point values, they are + considered equal if their absolute difference is smaller than + self.EPSILON """ idx = search_greater(self._values, timestamp) - if idx < len(self._values) and math.fabs(self._values[idx][0] - timestamp) < self.EPSILON: + if (idx < len(self._values) + and math.fabs(self._values[idx][0] - timestamp) < self.EPSILON): return idx return None @@ -275,7 +285,7 @@ def _do_add(self, value): self.rescale(now) rnd = random.random() - weighted_time = self.weight(now-self.start_time) / rnd + weighted_time = self.weight(now - self.start_time) / rnd changed = False @@ -306,14 +316,13 @@ def rescale(self, now): original_values = self._values[:] self._values = [] for i, (k, v) in enumerate(original_values): - k *= math.exp(-self.alpha * (now-self.start_time)) + k *= math.exp(-self.alpha * (now - self.start_time)) self._put(k, v) self.count = len(self._values) self.start_time = now self.next_scale_time = self.start_time + self.RESCALE_THRESHOLD - def _get_values(self): return [y for x, y in self._values[:max(self.count, self.size)]] @@ -325,7 +334,8 @@ def __repr__(self): class Histogram(object): - """A metric which calculates some statistics over the distribution of some values""" + """A metric which calculates some statistics over the distribution of some + values""" def __init__(self, reservoir): self.reservoir = reservoir @@ -345,7 +355,7 @@ def time(self): t1 = time.time() yield t2 = time.time() - self.notify(t2-t1) + self.notify(t2 - t1) def get(self): """Return the computed statistics over the gathered data""" From 5dd1925b302b1fe2755d762f7fb2a0bd4e8483b2 Mon Sep 17 00:00:00 2001 From: Ron Cohen Date: Mon, 2 Mar 2015 21:21:16 +0100 Subject: [PATCH 3/5] Added a comment for `time`. --- appmetrics/histogram.py | 1 + 1 file changed, 1 insertion(+) diff --git a/appmetrics/histogram.py b/appmetrics/histogram.py index 9c2d58e..5dccde8 100644 --- a/appmetrics/histogram.py +++ b/appmetrics/histogram.py @@ -352,6 +352,7 @@ def raw_data(self): @contextmanager def time(self): + """A context manager which times execution of a piece of code""" t1 = time.time() yield t2 = time.time() From fdc5bafa7e75e0f83479e442c82981517eeaaf62 Mon Sep 17 00:00:00 2001 From: Torsten Rehn Date: Tue, 23 Jun 2015 20:32:01 +0200 Subject: [PATCH 4/5] refactor some things into get_or_create_histogram() --- appmetrics/metrics.py | 21 ++++++++++++++++----- 1 file changed, 16 insertions(+), 5 deletions(-) diff --git a/appmetrics/metrics.py b/appmetrics/metrics.py index 3f0fad1..b827a33 100644 --- a/appmetrics/metrics.py +++ b/appmetrics/metrics.py @@ -160,13 +160,12 @@ def new_reservoir(reservoir_type='uniform', *reservoir_args, **reservoir_kwargs) return reservoir_cls(*reservoir_args, **reservoir_kwargs) -def with_histogram(name, reservoir_type="uniform", *reservoir_args, **reservoir_kwargs): +def get_or_create_histogram(name, reservoir_type, *reservoir_args, **reservoir_kwargs): """ - Time-measuring decorator: the time spent in the wrapped function is measured - and added to the named metric. - metric_args and metric_kwargs are passed to new_histogram() + Will return a histogram matching the given parameters or raise + DuplicateMetricError if it can't be created due to a name collision + with another histogram with different parameters. """ - reservoir = new_reservoir(reservoir_type, *reservoir_args, **reservoir_kwargs) try: @@ -181,6 +180,18 @@ def with_histogram(name, reservoir_type="uniform", *reservoir_args, **reservoir_ raise DuplicateMetricError( "Metric {!r} already exists with a different reservoir: {}".format(name, hmetric.reservoir)) + return hmetric + + +def with_histogram(name, reservoir_type="uniform", *reservoir_args, **reservoir_kwargs): + """ + Time-measuring decorator: the time spent in the wrapped function is measured + and added to the named metric. + metric_args and metric_kwargs are passed to new_histogram() + """ + + hmetric = get_or_create_histogram(name, reservoir_type, *reservoir_args, **reservoir_kwargs) + def wrapper(f): @functools.wraps(f) From edba4a4e67fbffeac332e555ea64c6997196052d Mon Sep 17 00:00:00 2001 From: Torsten Rehn Date: Tue, 23 Jun 2015 20:33:21 +0200 Subject: [PATCH 5/5] move context manager from Histogram class to metrics module --- README.rst | 4 ++-- appmetrics/histogram.py | 9 --------- appmetrics/metrics.py | 16 +++++++++++++++ appmetrics/tests/test_histogram.py | 7 ------- appmetrics/tests/test_metrics.py | 32 ++++++++++++++++++++++++++++++ 5 files changed, 50 insertions(+), 18 deletions(-) diff --git a/README.rst b/README.rst index cd56aba..1b671bb 100644 --- a/README.rst +++ b/README.rst @@ -70,11 +70,11 @@ and let's see the results:: >>> metrics.get("test") {'arithmetic_mean': 0.41326093673706055, 'kind': 'histogram', 'skewness': 0.2739718270714368, 'harmonic_mean': 0.14326954591313346, 'min': 0.0613858699798584, 'standard_deviation': 0.4319169569113129, 'median': 0.2831099033355713, 'histogram': [(1.0613858699798584, 3), (2.0613858699798584, 0)], 'percentile': [(50, 0.2831099033355713), (75, 0.2831099033355713), (90, 0.895287036895752), (95, 0.895287036895752), (99, 0.895287036895752), (99.9, 0.895287036895752)], 'n': 3, 'max': 0.895287036895752, 'variance': 0.18655225766752892, 'geometric_mean': 0.24964828731906127, 'kurtosis': -2.3333333333333335} -It is also possible to time specific sections of the code by using the ``time`` context manager:: +It is also possible to time specific sections of the code by using the ``timer`` context manager:: >>> import time, random ... def my_worker(): - ... with metrics.metric("test").time(): + ... with metrics.timer("test"): ... time.sleep(random.random()) ... diff --git a/appmetrics/histogram.py b/appmetrics/histogram.py index 5dccde8..1c0e555 100644 --- a/appmetrics/histogram.py +++ b/appmetrics/histogram.py @@ -21,7 +21,6 @@ import time import operator import math -from contextlib import contextmanager from . import statistics, exceptions, py3comp @@ -350,14 +349,6 @@ def raw_data(self): return self.reservoir.values - @contextmanager - def time(self): - """A context manager which times execution of a piece of code""" - t1 = time.time() - yield - t2 = time.time() - self.notify(t2 - t1) - def get(self): """Return the computed statistics over the gathered data""" diff --git a/appmetrics/metrics.py b/appmetrics/metrics.py index b827a33..daac5ea 100644 --- a/appmetrics/metrics.py +++ b/appmetrics/metrics.py @@ -18,6 +18,7 @@ Main interface module """ +from contextlib import contextmanager import functools import threading import time @@ -240,6 +241,21 @@ def fun(*args, **kwargs): return wrapper +@contextmanager +def timer(name, reservoir_type="uniform", *reservoir_args, **reservoir_kwargs): + """ + Time-measuring context manager: the time spent in the wrapped block + if measured and added to the named metric. + """ + + hmetric = get_or_create_histogram(name, reservoir_type, *reservoir_args, **reservoir_kwargs) + + t1 = time.time() + yield + t2 = time.time() + hmetric.notify(t2 - t1) + + def tag(name, tag_name): """ Tag the named metric with the given tag. diff --git a/appmetrics/tests/test_histogram.py b/appmetrics/tests/test_histogram.py index 0e6fa0e..2e7bad2 100644 --- a/appmetrics/tests/test_histogram.py +++ b/appmetrics/tests/test_histogram.py @@ -361,13 +361,6 @@ def test_notify(self): [mock.call(1.2)]) nt.assert_equal(result, self.reservoir.add.return_value) - def test_time(self): - self.histogram.notify = mock.Mock() - with self.histogram.time(): - pass - - nt.assert_equal(self.histogram.notify.call_count, 1) - def test_raw_data(self): result = self.histogram.raw_data() nt.assert_equal(result, self.reservoir.values) diff --git a/appmetrics/tests/test_metrics.py b/appmetrics/tests/test_metrics.py index df4730e..61c615e 100644 --- a/appmetrics/tests/test_metrics.py +++ b/appmetrics/tests/test_metrics.py @@ -372,6 +372,38 @@ def f2(v1, v2): return v1*v2 + @mock.patch('appmetrics.histogram.Histogram.notify') + def test_timer(self, notify): + with mm.timer("test"): + pass + + assert_equal(notify.call_count, 1) + + @mock.patch('appmetrics.histogram.Histogram.notify') + def test_timer_multiple(self, notify): + with mm.timer("test"): + pass + + with mm.timer("test"): + pass + + assert_equal(notify.call_count, 2) + + @raises(exceptions.DuplicateMetricError) + def test_timer_multiple_different_reservoir(self): + with mm.timer("test", reservoir_type="sliding_window"): + pass + + with mm.timer("test"): + pass + + @raises(exceptions.DuplicateMetricError) + def test_timer_multiple_different_type(self): + mm.new_gauge("test") + + with mm.timer("test"): + pass + @raises(exceptions.InvalidMetricError) def test_tag_invalid_name(self): mm.tag("test", "test")