add timer and accumulator

src/ooi/timer.py

@@ -4,34 +4,100 @@
 
 import time
 import logging
+from threading import Lock
+import math
+
+from logging import log as _log
 
 class Timer(object):
-    def __init__(self, name, milliseconds=True):
-        self.log = logging.getLogger('timing.'+name)
+    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)
         self.times = [] # list of tuples (msg, time)
-        self.next_step("")
+        self.complete_step("start")
         self.multiplier = 1000 if milliseconds else 1
+        self.lone_number_format = ' '+number_format
+        self.label_number_format = ' %s='+number_format
 
-    def next_step(self, label=None):
+    def complete_step(self, label=None):
         self.times.append((label, time.time()))
 
-    def last_step(self, label=None):
-        self.next_step(label)
-        self._log()
-
-    def _log(self):
-        if self.log.isEnabledFor(logging.DEBUG):
-            first_step = self.times[0]
-            last_step = self.times[-1]
-            elapsed = last_step[1]-first_step[1]
-            message = 'elapsed %f:' % (self.multiplier*elapsed)
-
-            previous_step = first_step
-            for this_step in self.times[1:]:
-                message += ' '
-                if this_step[0]:
-                    message += this_step[0]+'='
-                delta = self.multiplier*(this_step[1]-previous_step[1])
-                message += '%f' % delta
-                previous_step = this_step
-            self.log.debug(message)
+    def __str__(self):
+        # special case if only have start time (complete_step never called)
+        if len(self.times)==1:
+            return 'start time: ' + self.times[0][1]
+
+        # otherwise message has format: elapsed TOTAL unit
+        message = 'elapsed' + self.lone_number_format%self.multiplier*self._elapsed() + ' s' if self.multiplier==1 else ' ms'
+        if len(self.times)==2:
+            return message
+
+        # or: elapsed TOTAL unit: num1 num2 ...
+        # or: elapsed TOTAL unit: step1=num1 step2=num2 ...
+        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])
+            label = pair_o_tuples[1][0]
+            if label:
+                message += self.label_number_format%(label,delta)
+            else:
+                message += self.lone_number_format%delta
+        return message
+
+    def _elapsed(self):
+        first_step = self.times[0]
+        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):
+        self.lock = 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)
+            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])
+        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)

test/ooi/test_timer.py

@@ -0,0 +1,68 @@
+from unittest.case import TestCase
+import unittest
+import time
+import ooi.timer
+from math import fabs
+class TestTimer(TestCase):
+    def setUp(self):
+        self.op1_times = iter([ .01, .02 ])
+        self.a1 = ooi.timer.Accumulator()
+
+        self.op2_step1_times = iter([ .005, .015, .005, .005])
+        self.op2_step2_times = iter([ .01, .02, .01, .01])
+        self.a2 = ooi.timer.Accumulator()
+
+    def test_time_event(self):
+        t = ooi.timer.Timer()
+
+        time.sleep(0.01)
+        t.complete_step('pause')
+
+        time.sleep(0.02)
+        t.complete_step()
+
+        self.assertEquals(3, len(t.times))
+
+
+    def one_step_operation(self):
+        t = ooi.timer.Timer()
+        time.sleep(self.op1_times.next())
+        t.complete_step()
+        self.a1.add(t)
+
+    def test_stats_one_step(self):
+        try:
+            while True:
+                self.one_step_operation()
+        except StopIteration:
+            pass
+
+        self.assertEquals(2, self.a1.get_count())
+        self.assertAlmostEqual(self.a1.get_average(), 0.015, places=3 )
+        self.assertTrue( fabs(self.a1.get_average()-0.015)<.001 )
+        self.assertEquals(0, self.a1.get_standard_deviation())
+
+
+    def two_step_operation(self):
+        t = ooi.timer.Timer()
+        time.sleep(self.op2_step1_times.next())
+        t.complete_step('one')
+        time.sleep(self.op2_step2_times.next())
+        t.complete_step('two')
+        self.a2.add(t)
+
+    def test_stats_two_steps(self):
+        try:
+            while True:
+                self.two_step_operation()
+        except StopIteration:
+            pass
+
+        self.assertEquals(4, self.a2.get_count())
+        self.assertAlmostEqual(self.a2.get_average(), 0.02, places=3 )
+        self.assertNotEquals(0, self.a2.get_standard_deviation())
+        self.assertAlmostEqual(self.a2.get_average('one'), 0.0075, places=3 )
+
+
+if __name__ == '__main__':
+    unittest.main()