diff --git a/synapse/metrics/__init__.py b/synapse/metrics/__init__.py index 1acaa3fd09..c161c17e9f 100644 --- a/synapse/metrics/__init__.py +++ b/synapse/metrics/__init__.py @@ -19,7 +19,9 @@ from __future__ import absolute_import import logging from resource import getrusage, getpagesize, RUSAGE_SELF -from .metric import CounterMetric, CallbackMetric, TimerMetric, CacheMetric +from .metric import ( + CounterMetric, CallbackMetric, DistributionMetric, CacheMetric +) logger = logging.getLogger(__name__) @@ -59,8 +61,8 @@ class Metrics(object): def register_callback(self, *args, **kwargs): return self._register(CallbackMetric, *args, **kwargs) - def register_timer(self, *args, **kwargs): - return self._register(TimerMetric, *args, **kwargs) + def register_distribution(self, *args, **kwargs): + return self._register(DistributionMetric, *args, **kwargs) def register_cache(self, *args, **kwargs): return self._register(CacheMetric, *args, **kwargs) diff --git a/synapse/metrics/metric.py b/synapse/metrics/metric.py index 6b7d3358bc..45d2752a20 100644 --- a/synapse/metrics/metric.py +++ b/synapse/metrics/metric.py @@ -101,35 +101,37 @@ class CallbackMetric(BaseMetric): for k in sorted(value.keys())] -class TimerMetric(CounterMetric): - """A combination of an event counter and a time accumulator, which counts - both the number of events and how long each one takes. +class DistributionMetric(CounterMetric): + """A combination of an event counter and an accumulator, which counts + both the number of events and accumulates the total value. Typically this + could be used to keep track of method-running times, or other distributions + of values that occur in discrete occurances. TODO(paul): Try to export some heatmap-style stats? """ def __init__(self, *args, **kwargs): - super(TimerMetric, self).__init__(*args, **kwargs) + super(DistributionMetric, self).__init__(*args, **kwargs) - self.times = {} + self.totals = {} # Scalar metrics are never empty if self.is_scalar(): - self.times[()] = 0 + self.totals[()] = 0 - def inc_time(self, msec, *values): + def inc_by(self, inc, *values): self.inc(*values) - if values not in self.times: - self.times[values] = msec + if values not in self.totals: + self.totals[values] = inc else: - self.times[values] += msec + self.totals[values] += inc def render_item(self, k): keystr = self._render_key(k) return ["%s:count%s %d" % (self.name, keystr, self.counts[k]), - "%s:msec%s %d" % (self.name, keystr, self.times[k])] + "%s:total%s %d" % (self.name, keystr, self.totals[k])] class CacheMetric(object): diff --git a/synapse/storage/_base.py b/synapse/storage/_base.py index 2708d3c5b6..104e8e3cf6 100644 --- a/synapse/storage/_base.py +++ b/synapse/storage/_base.py @@ -38,9 +38,9 @@ transaction_logger = logging.getLogger("synapse.storage.txn") metrics = synapse.metrics.get_metrics_for("synapse.storage") -sql_query_timer = metrics.register_timer("queries", labels=["verb"]) -sql_txn_timer = metrics.register_timer("transactions", labels=["desc"]) -sql_getevents_timer = metrics.register_timer("getEvents", labels=["desc"]) +sql_query_timer = metrics.register_distribution("queries", labels=["verb"]) +sql_txn_timer = metrics.register_distribution("transactions", labels=["desc"]) +sql_getevents_timer = metrics.register_distribution("getEvents", labels=["desc"]) caches_by_name = {} cache_counter = metrics.register_cache( @@ -143,7 +143,7 @@ class LoggingTransaction(object): finally: msecs = (time.time() * 1000) - start sql_logger.debug("[SQL time] {%s} %f", self.name, msecs) - sql_query_timer.inc_time(msecs, sql.split()[0]) + sql_query_timer.inc_by(msecs, sql.split()[0]) class PerformanceCounters(object): @@ -268,7 +268,7 @@ class SQLBaseStore(object): self._current_txn_total_time += end - start self._txn_perf_counters.update(desc, start, end) - sql_txn_timer.inc_time(self._current_txn_total_time, desc) + sql_txn_timer.inc_by(self._current_txn_total_time, desc) with PreserveLoggingContext(): result = yield self._db_pool.runInteraction( @@ -672,7 +672,7 @@ class SQLBaseStore(object): def update_counter(desc, last_time): curr_time = self._get_event_counters.update(desc, last_time) - sql_getevents_timer.inc_time(curr_time - last_time, desc) + sql_getevents_timer.inc_by(curr_time - last_time, desc) return curr_time cache = self._get_event_cache.setdefault(event_id, {}) @@ -727,7 +727,7 @@ class SQLBaseStore(object): def update_counter(desc, last_time): curr_time = self._get_event_counters.update(desc, last_time) - sql_getevents_timer.inc_time(curr_time - last_time, desc) + sql_getevents_timer.inc_by(curr_time - last_time, desc) return curr_time d = json.loads(js) diff --git a/tests/metrics/test_metric.py b/tests/metrics/test_metric.py index 193908b44e..1ca3e45a26 100644 --- a/tests/metrics/test_metric.py +++ b/tests/metrics/test_metric.py @@ -16,7 +16,7 @@ from tests import unittest from synapse.metrics.metric import ( - CounterMetric, CallbackMetric, TimerMetric, CacheMetric + CounterMetric, CallbackMetric, DistributionMetric, CacheMetric ) @@ -97,37 +97,37 @@ class CallbackMetricTestCase(unittest.TestCase): ]) -class TimerMetricTestCase(unittest.TestCase): +class DistributionMetricTestCase(unittest.TestCase): def test_scalar(self): - metric = TimerMetric("thing") + metric = DistributionMetric("thing") self.assertEquals(metric.render(), [ 'thing:count 0', - 'thing:msec 0', + 'thing:total 0', ]) - metric.inc_time(500) + metric.inc_by(500) self.assertEquals(metric.render(), [ 'thing:count 1', - 'thing:msec 500', + 'thing:total 500', ]) def test_vector(self): - metric = TimerMetric("queries", labels=["verb"]) + metric = DistributionMetric("queries", labels=["verb"]) self.assertEquals(metric.render(), []) - metric.inc_time(300, "SELECT") - metric.inc_time(200, "SELECT") - metric.inc_time(800, "INSERT") + metric.inc_by(300, "SELECT") + metric.inc_by(200, "SELECT") + metric.inc_by(800, "INSERT") self.assertEquals(metric.render(), [ 'queries:count{verb="INSERT"} 1', - 'queries:msec{verb="INSERT"} 800', + 'queries:total{verb="INSERT"} 800', 'queries:count{verb="SELECT"} 2', - 'queries:msec{verb="SELECT"} 500', + 'queries:total{verb="SELECT"} 500', ])