6 """Class for measuring lenghts of nested time intervals.
7 Intervals are opened either like:
14 Or using the with statement:
24 """Opens time interval."""
25 self
.times
.append((time
.time(), [], self
.next_args
))
29 """Closes time interval. Returns tuple (duration, avg_child_duration)."""
31 my_start
, children_durations
, _
= self
.times
[-1]
34 my_duration
= now
- my_start
35 # add duration of this object to the parent list
37 self
.times
[-1][1].append(my_duration
)
39 return (my_duration
, children_durations
)
41 def stop_n_log(self
, comment
=' time elapsed', child_name
='child'):
42 total
, children
= self
.stop()
43 msg
= "%s: %.3f s"%(comment
, total
)
45 c_sum
, c_len
= sum(children
), len(children
)
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%%
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')
58 _
, _
, kwargs
= self
.times
[-1]
59 log
= kwargs
.pop('log', False)
61 return self
.stop_n_log(**kwargs
)
64 def __call__(self
, **kwargs
):
65 self
.next_args
= kwargs
71 def __exit__(self
, *args
):
80 with
t(log
=True, comment
='test loop 1', child_name
='blabla'):
81 for a
in xrange(1000):
83 time
.sleep(random
.random()/20000)
86 with
t(log
=True, comment
='test loop 2', child_name
='blabla2'):
87 for a
in xrange(1000):
89 time
.sleep(random
.random()/20000)
92 t
.stop_n_log(child_name
='test loop')
95 if "__main__" == __name__
:
96 logging
.getLogger().setLevel(logging
.INFO
)