utils/timer.py

   1 import time
   2 import math
   3 import logging
   4
   5 class Timer:
   6     """Class for measuring lenghts of nested time intervals.
   7     Intervals are opened either like:
   8
   9     >>> t = Timer()
  10     >>> t.start()
  11     >>> do_stuff()
  12     >>> t.stop()
  13
  14     Or using the with statement:
  15
  16     >>> with t():
  17            do_stuff()
  18     """
  19     def __init__(self):
  20         self.times = []
  21         self.next_args = {}
  22
  23     def start(self):
  24         """Opens time interval."""
  25         self.times.append((time.time(), [], self.next_args))
  26         self.next_args = {}
  27
  28     def stop(self):
  29         """Closes time interval. Returns tuple (duration, avg_child_duration)."""
  30         now = time.time()
  31         my_start, children_durations, _ = self.times[-1]
  32         del self.times[-1]
  33
  34         my_duration = now - my_start
  35         # add duration of this object to the parent list
  36         if self.times:
  37             self.times[-1][1].append(my_duration)
  38
  39         return (my_duration, children_durations)
  40
  41     def stop_n_log(self, comment='  time elapsed', child_name='child'):
  42         total, children = self.stop()
  43         msg = "%s: %.3f s"%(comment, total)
  44         if children:
  45             c_sum, c_len = sum(children), len(children)
  46             mean = c_sum / c_len
  47             sd = 0
  48             if c_len > 1:
  49                 sd = math.sqrt(sum( (val - mean)**2 for val in children ) / (c_len - 1))
  50             msg += """, time not spent in children (overhead) %.3f s = %.2f%%
  51   #%d x %s took %.3f s:
  52   mean: %.3f s (sd = %.3f s)"""%(
  53                 total - c_sum, 100.0 * (total - c_sum) / total,
  54                 c_len, child_name, c_sum, mean, sd)
  55         logging.info(msg + '\n')
  56
  57     def stop_arg(self):
  58         _, _, kwargs = self.times[-1]
  59         log = kwargs.pop('log', False)
  60         if log:
  61             return self.stop_n_log(**kwargs)
  62         return self.stop()
  63
  64     def __call__(self, **kwargs):
  65         self.next_args = kwargs
  66         return self
  67
  68     def __enter__(self):
  69         self.start()
  70
  71     def __exit__(self, *args):
  72         self.stop_arg()
  73
  74 import random
  75
  76 def test():
  77     t = Timer()
  78
  79     t.start()
  80     with t(log=True, comment='test loop 1', child_name='blabla'):
  81         for a in xrange(1000):
  82             with t():
  83                 time.sleep(random.random()/20000)
  84
  85     # eq to
  86     with t(log=True, comment='test loop 2', child_name='blabla2'):
  87         for a in xrange(1000):
  88             t.start()
  89             time.sleep(random.random()/20000)
  90             t.stop()
  91
  92     t.stop_n_log(child_name='test loop')
  93
  94
  95 if "__main__" == __name__:
  96     logging.getLogger().setLevel(logging.INFO)
  97     test()
  98
  99