Skip to content
Browse files

improve accumulator and timer

  • Loading branch information...
1 parent 38a5460 commit cf01e9bb8154851532a50ed3fcd2cd5cf338ce9a @newbrough newbrough committed
Showing with 227 additions and 58 deletions.
  1. +183 −56 src/ooi/timer.py
  2. +1 −0 test/importable/__init__.py
  3. +4 −0 test/importable/create_timer.py
  4. +33 −0 test/ooi/test_accumulator.py
  5. +6 −2 test/ooi/test_timer.py
View
239 src/ooi/timer.py
@@ -1,20 +1,69 @@
"""
-record time taken for code to peform several steps
+record time taken for code to perform several steps
+collect and report statistics for timing and other metrics
+
+NOTE: by default Timer and Accumulator will use special loggers. for example, if you create a Timer
+ in module foo/bar/baz.py:
+ t = Timer()
+ t.log()
"""
import time
import logging
from threading import Lock
import math
+import inspect
+from ooi.logging import log
+
+def _get_calling_module(default_value=None):
+ try:
+ stack = inspect.stack()
+ # stack[0]: call to inspect.stack() on the line above
+ # stack[1]: call to _get_calling_module() below
+ # stack[2] # call to _SelfLogging.__init__() by subclass
+ frame=stack[3] # call to Timer() or Accumulator() by caller
+ if frame and frame[0]:
+ module = inspect.getmodule(frame[0])
+ if module:
+ return module.__name__
+ elif frame[1]:
+ return frame[1]
+ except:
+ log.warning('failed to inspect calling module', exc_info=True)
+ return default_value
+
+class _SelfLogging(object):
+ """ base class provides shared logging behavior of Timer and Accumulator """
+ def __init__(self, name, logger, level, prefix):
+ if name:
+ self.name = name
+ else:
+ self.name = _get_calling_module(default_value='unspecified')
+ if logger:
+ self.logger = logger
+ else:
+ self.logger = logging.getLogger(prefix + '.' + self.name)
+ self.level = level
+
+ def is_log_enabled(self):
+ return self.logger.isEnabledFor(self.level)
+
+ def _log(self):
+ if self.is_log_enabled():
+ self.logger.log(self.level, str(self))
-from logging import log as _log
-class Timer(object):
- def __init__(self, name=None, logger=None, milliseconds=True, number_format='%f'):
- if not name and not logger:
- logging.getLogger(__file__).warn('timer created without a name or logger')
- name = 'unspecified'
- self.tlog = logger or logging.getLogger('timing.'+name)
+class Timer(_SelfLogging):
+ def __init__(self, name=None, logger=None, level=logging.DEBUG, milliseconds=True, number_format='%f'):
+ """
+ @param name: override module name used for default logger with logging.getLogger('timing.'+name)
+ @param logger: override default logger with this
+ @param level: log times at this log level
+ @param milliseconds: report time in milliseconds (vs seconds)?
+ @param number_format: '%f' used by default
+ """
+ super(Timer, self).__init__(name, logger, level, 'timing')
+
self.times = [] # list of tuples (msg, time)
self.complete_step("start")
self.multiplier = 1000 if milliseconds else 1
@@ -39,7 +88,7 @@ def __str__(self):
message += ':'
for pair_o_tuples in zip(self.times[1:],self.times[:-1]):
# looping through adjacent pairs: [(labelN,timeN), (labelN+1,timeN+1)]
- delta = self.multiplier*(pair_o_tuples[1][1]-pair_o_tuples[0][1])
+ delta = self.multiplier*(pair_o_tuples[0][1]-pair_o_tuples[1][1])
label = pair_o_tuples[1][0]
if label:
message += self.label_number_format%(label,delta)
@@ -52,63 +101,141 @@ def _elapsed(self):
last_step = self.times[-1]
return last_step[1]-first_step[1]
- def log(self, level=logging.DEBUG, min=-1):
- if self.tlog.isEnabledFor(level):
- if self._elapsed()>=min:
- self.tlog.debug(str(self))
-
-
-class Accumulator(object):
- def __init__(self, format='%2f'):
+ def log(self, min=0):
+ if min and self._elapsed()>=min:
+ self._log()
+
+_persisted_accumulators = {}
+def get_accumulators():
+ return _persisted_accumulators
+
+class Accumulator(_SelfLogging):
+ """ calculate average, standard deviation, min and max of named values
+ reported directly (with add_value) or results of a Timer (with add)
+
+ callers can log() or query stats get_min(step), get_average(step), etc
+ or use Accumulator(trigger_step='publish', trigger_frequency=500) to automatically log results periodically
+ ie- With arguments above, every 500 times the "publish" step is recorded with add(Timer) or add_value('publish', value)
+ the accumulator will write a log message reporting min, max, average, stddev of each step recorded.
+ By default, it then clears stats (so each log message is the most recent N measurements),
+ or use trigger_clear=False to keep a running average until an explicit clear().
+ """
+ def __init__(self, name=None, logger=None, level=logging.INFO, format='%2f', keys='all',
+ trigger_key=None, trigger_frequency=1000, trigger_clear=True, persist=False):
+ """
+ @param name: override module name used for default logger with logging.getLogger('stats.'+name)
+ @param logger: override default logger with this
+ @param level: log times at this log level
+ @param format: '%2f' used by default
+ @param keys: list of which values to report with str() or log(), 'total' for just total, 'all' for all keys, '!total' for all but total
+ @param trigger_key: count for this key may result in logging
+ @param trigger_frequency: when count of trigger_key is a multiple of this value, log results
+ @param trigger_clear: reset counters after triggered report (False=cumulative average since container start, True=current average)
+ @param persist: keep a reference to this Accumulator, returned by get_accumulators()
+ """
+ super(Accumulator,self).__init__(name, logger, level, 'stats')
self.lock = Lock()
- self.count = { '__total__': 0 }
- self.min = {}
- self.sum = {}
- self.sumsquares = {}
- self.min = {}
- self.max = {}
self.format = '%d values: ' + format + ' min, ' + format + ' avg, ' + format + ' max, ' + format + ' dev'
+ self.keys_arg = keys
+ self.trigger_key = trigger_key
+ self.trigger_frequency = trigger_frequency
+ self.trigger_clear = trigger_clear
+ self.clear()
+ if persist:
+ global _persisted_accumulators
+ _persisted_accumulators[self.name] = self
+
+ def keys(self):
+ if self.keys_arg == 'all':
+ return self.count.keys()
+ elif self.keys_arg == 'total':
+ return ['__total__']
+ elif self.keys_arg == '!total':
+ out = self.count.keys()
+ out.remove('__total__')
+ return out
+ else:
+ return self.keys_arg
+
+ def clear(self):
+ with self.lock:
+ self.count = { '__total__': 0 }
+ self.min = {}
+ self.sum = {}
+ self.sumsquares = {}
+ self.min = {}
+ self.max = {}
+
def add(self, timer):
with self.lock:
for pair_o_tuples in zip(timer.times[:-1], timer.times[1:], xrange(len(timer.times)-1)):
label = pair_o_tuples[1][0] or str(pair_o_tuples[2])
delta = pair_o_tuples[1][1]-pair_o_tuples[0][1]
- self._add(label, delta)
+ self.add_value(label, delta, _can_trigger=False, _have_lock=True)
total = timer.times[-1][1]-timer.times[0][1]
- self._add('__total__', total)
-
- def _add(self, label, delta):
- if label in self.sum:
- self.count[label]+=1
- self.sum[label] += delta
- self.sumsquares[label] += delta*delta
- self.min[label] = min(delta, self.min[label])
- self.max[label] = max(delta, self.max[label])
+ self.add_value('__total__', total, _can_trigger=False, _have_lock=True)
+ self.add_value(timer.name, total, _can_trigger=False, _have_lock=True)
+ self._check_trigger()
+
+ def add_value(self, label, value, _can_trigger=True, _have_lock=False):
+ """
+ @param _can_trigger: when called from add(Timer), avoid trigger until whole Timer is added
+ @param _have_lock: when called from add(Timer), don't need to re-acquire the lock
+ """
+ if not _have_lock:
+ with self.lock:
+ self.add_value(label, value, _can_trigger=_can_trigger, _have_lock=True)
else:
- self.count[label]=1
- self.sumsquares[label] = delta*delta
- self.min[label] = self.max[label] = self.sum[label] = delta
-
- def get_count(self, step='__total__'): return self.count[step]
- def get_min(self, step='__total__'): return self.min[step]
- def get_max(self, step='__total__'): return self.max[step]
-
- def get_average(self, step='__total__'):
- return self.sum[step] / self.count[step]
-
- def get_standard_deviation(self, step='__total__'):
- if self.count[step]<3:
- return 0
- avg = self.get_average(step=step)
- return math.sqrt(self.sumsquares[step]/self.count[step]-avg*avg)
+ if label in self.sum:
+ self.count[label]+=1
+ self.sum[label] += value
+ self.sumsquares[label] += value*value
+ self.min[label] = min(value, self.min[label])
+ self.max[label] = max(value, self.max[label])
+ else:
+ self.count[label]=1
+ self.sumsquares[label] = value*value
+ self.min[label] = self.max[label] = self.sum[label] = value
+ if _can_trigger:
+ self._check_trigger()
+
+ def _check_trigger(self):
+ """ always called while holding lock """
+ if self.trigger_key and self.count[self.trigger_key] and self.count[self.trigger_key]%self.trigger_frequency==0:
+ self.log()
+ if self.trigger_clear:
+ self.clear()
+
+ def get_count(self, key='__total__'):
+ return self.count[key] if key in self.count else 0
+
+ def get_min(self, key='__total__'):
+ return self.min[key] if key in self.min else float('nan')
+ def get_max(self, key='__total__'):
+ return self.max[key] if key in self.max else float('nan')
+
+ def get_average(self, key='__total__'):
+ return self.sum[key] / self.count[key]
+
+ def get_standard_deviation(self, key='__total__'):
+ if self.count[key]<2:
+ return float('nan')
+ avg = self.get_average(key=key)
+ return math.sqrt(self.sumsquares[key]/self.count[key]-avg*avg)
+
+ def __len__(self):
+ return len(self.keys())
def __str__(self):
- return self.to_string()
+ return '\n'.join(['%s: %s' % (key,self.to_string(key)) for key in self.keys()])
- def to_string(self, step='__total__'):
- count = self.get_count()
- if count==0:
- return 'no values reported'
+ def to_string(self, key='__total__'):
+ count = self.get_count(key)
+ if count:
+ return self.format % ( count, self.get_min(key), self.get_average(key),
+ self.get_max(key), self.get_standard_deviation(key))
else:
- return self.format % ( self.get_count(step), self.get_min(step), self.get_average(step),
- self.get_max(step), self.get_standard_deviation(step))
+ return 'no values reported'
+
+ def log(self):
+ self._log()
View
1 test/importable/__init__.py
@@ -0,0 +1 @@
+__author__ = 'jnewbrough'
View
4 test/importable/create_timer.py
@@ -0,0 +1,4 @@
+__author__ = 'jnewbrough'
+
+import ooi.timer
+t = ooi.timer.Timer()
View
33 test/ooi/test_accumulator.py
@@ -0,0 +1,33 @@
+from unittest.case import TestCase
+import unittest
+import time
+import ooi.timer
+from math import fabs
+class TestTimer(TestCase):
+
+ def test_use_case_example(self):
+ a = ooi.timer.Accumulator(keys=['half','done', 'fish' ])
+ t = ooi.timer.Timer()
+ time.sleep(0.05)
+ t.complete_step('half')
+ time.sleep(0.04)
+ t.complete_step('done')
+ a.add(t)
+ a.add_value('fish', 3)
+
+ t = ooi.timer.Timer()
+ time.sleep(0.06)
+ t.complete_step('half')
+ time.sleep(0.05)
+ t.complete_step('done')
+ a.add(t)
+ a.add_value('fish', 3.5)
+ a.add_value('fish', 3.5)
+ a.add_value('fish', 3.5)
+
+ a.log()
+ print str(a)
+ # self.assertNothingCrashed()
+
+if __name__ == '__main__':
+ unittest.main()
View
8 test/ooi/test_timer.py
@@ -12,6 +12,11 @@ def setUp(self):
self.op2_step2_times = iter([ .01, .02, .01, .01])
self.a2 = ooi.timer.Accumulator()
+ def test_found_caller(self):
+ import importable.create_timer
+ t = importable.create_timer.t
+ self.assertEquals('timing.importable.create_timer', t.logger.name)
+
def test_time_event(self):
t = ooi.timer.Timer()
@@ -23,7 +28,6 @@ def test_time_event(self):
self.assertEquals(3, len(t.times))
-
def one_step_operation(self):
t = ooi.timer.Timer()
time.sleep(self.op1_times.next())
@@ -59,7 +63,7 @@ def test_stats_two_steps(self):
pass
self.assertEquals(4, self.a2.get_count())
- self.assertAlmostEqual(self.a2.get_average(), 0.02, places=3 )
+ self.assertAlmostEqual(self.a2.get_average(), 0.02, places=2 )
self.assertNotEquals(0, self.a2.get_standard_deviation())
self.assertAlmostEqual(self.a2.get_average('one'), 0.0075, places=3 )

0 comments on commit cf01e9b

Please sign in to comment.
Something went wrong with that request. Please try again.