adding timer

Author: samuelcolvin

HISTORY.rst

@@ -8,6 +8,7 @@ v0.3.0 (2017-10-11)
 * allow ``async/await`` arguments
 * fix subscript
 * fix weird named tuples eg. ``mock > call_args``
+* add ``timer``
 
 v0.2.0 (2017-09-14)
 ...................

devtools/timer.py

@@ -0,0 +1,92 @@
+from statistics import mean, stdev
+from time import time
+
+__all__ = 'Timer',
+
+
+class TimerResult:
+    def __init__(self, name=None, verbose=True):
+        self._name = name
+        self.verbose = verbose
+        self.finish = None
+        self.start = time()
+
+    def capture(self):
+        self.finish = time()
+
+    def elapsed(self):
+        if self.finish:
+            return self.finish - self.start
+        else:
+            return -1
+
+    def str(self, dp=3):
+        if self._name:
+            return '{}: {:0.{dp}f}s elapsed'.format(self._name, self.elapsed(), dp=dp)
+        else:
+            return '{:0.{dp}f}s elapsed'.format(self.elapsed(), dp=dp)
+
+    def __str__(self):
+        return self.str()
+
+
+_SUMMARY_TEMPLATE = '{count} times: mean={mean:0.{dp}f}s stdev={stddev:0.{dp}f}s min={min:0.{dp}f}s max={max:0.{dp}f}s'
+
+
+class Timer:
+    def __init__(self, name=None, verbose=True, file=None, dp=3):
+        self.file = file
+        self.dp = dp
+        self._name = name
+        self._verbose = verbose
+        self.results = []
+
+    def __call__(self, name=None, verbose=None):
+        if name:
+            self._name = name
+        if verbose is not None:
+            self._verbose = verbose
+        return self
+
+    def start(self, name=None, verbose=None):
+        self.results.append(
+            TimerResult(name or self._name, self._verbose if verbose is None else verbose)
+        )
+        return self
+
+    def capture(self, verbose=None):
+        r = self.results[-1]
+        r.capture()
+        print_ = r.verbose if verbose is None else verbose
+        if print_:
+            print(r.str(self.dp), file=self.file, flush=True)
+        return r
+
+    def summary(self, verbose=False):
+        times = set()
+        for r in self.results:
+            if not r.finish:
+                r.capture()
+            if verbose:
+                print('    {}'.format(r.str(self.dp)), file=self.file)
+            times.add(r.elapsed())
+
+        if times:
+            print(_SUMMARY_TEMPLATE.format(
+                count=len(times),
+                mean=mean(times),
+                stddev=stdev(times) if len(times) > 1 else 0,
+                min=min(times),
+                max=max(times),
+                dp=self.dp,
+            ), file=self.file, flush=True)
+        else:
+            raise RuntimeError('timer not started')
+        return times
+
+    def __enter__(self):
+        self.start()
+        return self
+
+    def __exit__(self, exc_type, exc_val, exc_tb):
+        self.capture()

docs/examples/more_debug.py

@@ -0,0 +1,31 @@
+import random
+
+from devtools import debug
+
+# debug.format() behaves the same as debug() except it returns an object to inspect or print
+r = debug.format(x=123, y=321)
+print(r)
+print(repr(r))
+
+values = list(range(int(1e5)))
+# timer can be used as a context manager or directly
+with debug.timer('shuffle values'):
+    random.shuffle(values)
+
+t2 = debug.timer('sort values').start()
+sorted(values)
+t2.capture()
+
+# if used repeatedly a summary is available
+t3 = debug.timer()
+for i in [1e4, 1e6, 1e7]:
+    with t3('sum {}'.format(i), verbose=False):
+        sum(range(int(i)))
+
+t3.summary(verbose=True)
+
+# debug.breakpoint()
+# would drop to a prompt:
+# > /python-devtools/docs/examples/more_debug.py(28)<module>()->None
+# -> debug.breakpoint()
+# (Pdb)

docs/index.rst

@@ -82,6 +82,25 @@ This approach has another advantage: if you forget to remove ``debug(...)`` call
 (which won't have devtools installed) should fail both on execution and linting, meaning you don't end up with
 extraneous debug calls in production code.
 
+Other debug tools
+.................
+
+The debug namespace includes a number of other useful functions:
+
+* ``format()`` same as calling ``debug()`` but returns a ``DebugOutput`` rather than printing the output
+* ``timer()`` returns an instance of *devtool's* ``Timer`` class suitable for timing code execution
+* ``breakpoint()`` introduces a breakpoint using ``pdb``
+
+
+.. literalinclude:: examples/more_debug.py
+
+.. rst-class:: divider
+
+🡣
+
+.. raw:: html
+   :file: ./examples/more_debug.html
+
 Other Tools
 -----------
 

tests/test_timer.py

@@ -0,0 +1,65 @@
+import io
+from time import sleep
+
+import pytest
+
+from devtools import Timer, debug
+
+
+def test_simple():
+    f = io.StringIO()
+    t = debug.timer(name='foobar', file=f)
+    with t:
+        sleep(0.01)
+    v = f.getvalue()
+    assert v == 'foobar: 0.010s elapsed\n'
+
+
+def test_multiple():
+    f = io.StringIO()
+    t = Timer(file=f)
+    for i in [0.001, 0.002, 0.003]:
+        with t(i):
+            sleep(i)
+    t.summary()
+    v = f.getvalue()
+    assert v == (
+        '0.001: 0.001s elapsed\n'
+        '0.002: 0.002s elapsed\n'
+        '0.003: 0.003s elapsed\n'
+        '3 times: mean=0.002s stdev=0.001s min=0.001s max=0.003s\n'
+    )
+
+
+def test_unfinished():
+    t = Timer().start()
+    assert str(t.results[0]) == '-1.000s elapsed'
+
+
+def test_multiple_not_verbose():
+    f = io.StringIO()
+    t = Timer(file=f)
+    for i in [0.001, 0.002, 0.003]:
+        with t(verbose=False):
+            sleep(i)
+    t.summary(True)
+    v = f.getvalue()
+    assert v == (
+        '    0.001s elapsed\n'
+        '    0.002s elapsed\n'
+        '    0.003s elapsed\n'
+        '3 times: mean=0.002s stdev=0.001s min=0.001s max=0.003s\n'
+    )
+
+
+def test_unfinished_summary():
+    f = io.StringIO()
+    t = Timer(file=f).start()
+    t.summary()
+    v = f.getvalue()
+    assert v == '1 times: mean=0.000s stdev=0.000s min=0.000s max=0.000s\n'
+
+
+def test_summary_not_started():
+    with pytest.raises(RuntimeError):
+        Timer().summary()