From f4bc763656a0cb31d5bf2c9e38d68994c6801248 Mon Sep 17 00:00:00 2001
From: Matt Wala <wala1@illinois.edu>
Date: Tue, 12 Jun 2018 15:11:51 -0500
Subject: [PATCH 01/12] Add a decorator for recording execution time.

This change introduces a decorator for recording execution time of a
function. The decorator adds an optional keyword argument to the
decorated function, and the execution time is returned by passing a
dict as the optional keyword argument.
---
 pytools/__init__.py  | 107 +++++++++++++++++++++++++++++++++++--------
 test/test_pytools.py |  17 +++++++
 2 files changed, 106 insertions(+), 18 deletions(-)

diff --git a/pytools/__init__.py b/pytools/__init__.py
index 3d03cfa..c60c3d4 100644
--- a/pytools/__init__.py
+++ b/pytools/__init__.py
@@ -2067,6 +2067,92 @@ def reshaped_view(a, newshape):
 # }}}
 
 
+# {{{ timing utilities
+
+class _TimerResult(Record):
+
+    __slots__ = ["wall_elapsed", "process_elapsed"]
+
+
+class _Timer(object):
+
+    def __init__(self):
+        self.started = False
+        self.finished = False
+
+    def start(self):
+        assert not self.started
+        self.started = True
+
+        import time
+        if sys.version_info >= (3, 3):
+            self.perf_counter_start = time.perf_counter()
+            self.process_time_start = time.process_time()
+
+        else:
+            import timeit
+            self.time_start = timeit.default_timer()
+
+    def stop(self):
+        assert self.started
+        assert not self.finished
+        self.finished = True
+
+        import time
+        if sys.version_info >= (3, 3):
+            self.wall_elapsed = time.perf_counter() - self.perf_counter_start
+            self.process_elapsed = time.process_time() - self.process_time_start
+
+        else:
+            import timeit
+            self.wall_elapsed = timeit.default_timer() - self.time_start
+            self.process_elapsed = None
+
+    def result(self):
+        assert self.finished
+        return _TimerResult(
+                wall_elapsed=self.wall_elapsed,
+                process_elapsed=self.process_elapsed)
+
+
+class record_exec_time(object):  # noqa: N801
+    """A decorator for recording timing data for a function call.
+
+    Timing data is saved inside a dict passed as an optional keyword argument.
+    """
+
+    def __init__(self, arg=None, description=None):
+        self.arg = arg
+        self.description = description
+
+    def __call__(self, wrapped):
+        description = self.description or wrapped.__name__
+
+        from contextlib import contextmanager
+        @contextmanager
+        def time_process(output):
+            timer = _Timer()
+            timer.start()
+            yield
+            timer.stop()
+            output[description] = timer.result()
+
+        def wrapper(*args, **kwargs):
+            if self.arg not in kwargs:
+                return wrapped(*args, **kwargs)
+
+            output = kwargs.pop(self.arg)
+            with time_process(output):
+                return wrapped(*args, **kwargs)
+
+        from functools import update_wrapper
+        new_wrapper = update_wrapper(wrapper, wrapped)
+
+        return new_wrapper
+
+# }}}
+
+
 # {{{ log utilities
 
 class ProcessLogger(object):
@@ -2094,14 +2180,8 @@ class ProcessLogger(object):
         self.logger.log(self.silent_level, "%s: start", self.description)
         self.is_done = False
 
-        import time
-        if sys.version_info >= (3, 3):
-            self.perf_counter_start = time.perf_counter()
-            self.process_time_start = time.process_time()
-
-        else:
-            import timeit
-            self.time_start = timeit.default_timer()
+        self.timer = _Timer()
+        timer.start()
 
         import threading
         self.late_start_log_thread = threading.Thread(target=self._log_start_if_long)
@@ -2124,16 +2204,7 @@ class ProcessLogger(object):
                     sleep_duration)
 
     def done(self, extra_msg=None, *extra_fmt_args):
-        import time
-        if sys.version_info >= (3, 3):
-            wall_elapsed = time.perf_counter() - self.perf_counter_start
-            process_elapsed = time.process_time() - self.process_time_start
-
-        else:
-            import timeit
-            wall_elapsed = timeit.default_timer() - self.time_start
-            process_elapsed = None
-
+        self.timer.stop()
         self.is_done = True
 
         completion_level = (
diff --git a/test/test_pytools.py b/test/test_pytools.py
index 65514dd..dd1f8a3 100644
--- a/test/test_pytools.py
+++ b/test/test_pytools.py
@@ -223,6 +223,23 @@ def test_reshaped_view():
         pytools.reshaped_view(b, -1)
 
 
+def test_record_exec_time():
+    from pytools import record_exec_time
+
+    @record_exec_time(arg="time")
+    def f(a):
+        return a
+
+    f(1)
+
+    time = {}
+    f(1, time=time)
+
+    assert "f" in time
+    assert hasattr(time["f"], "wall_elapsed")
+    assert hasattr(time["f"], "process_elapsed")
+
+
 if __name__ == "__main__":
     if len(sys.argv) > 1:
         exec(sys.argv[1])
-- 
GitLab


From b7867e924dcdd438cb8b60ce343878f95e67d63e Mon Sep 17 00:00:00 2001
From: Matt Wala <wala1@illinois.edu>
Date: Tue, 12 Jun 2018 15:17:25 -0500
Subject: [PATCH 02/12] Forgot to access wall_elapsed and process_elapsed in
 ProcessLogger

---
 pytools/__init__.py | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/pytools/__init__.py b/pytools/__init__.py
index c60c3d4..5a29e4f 100644
--- a/pytools/__init__.py
+++ b/pytools/__init__.py
@@ -2207,6 +2207,9 @@ class ProcessLogger(object):
         self.timer.stop()
         self.is_done = True
 
+        wall_elapsed = self.timer.wall_elapsed
+        process_elapsed = self.timer.process_elapsed
+
         completion_level = (
                 self.noisy_level
                 if wall_elapsed > self.long_threshold_seconds
-- 
GitLab


From 78cc1a75dde60b3fe559fd5dc7ecd105fe98da79 Mon Sep 17 00:00:00 2001
From: Matt Wala <wala1@illinois.edu>
Date: Tue, 12 Jun 2018 15:17:55 -0500
Subject: [PATCH 03/12] timer -> self.timer

---
 pytools/__init__.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/pytools/__init__.py b/pytools/__init__.py
index 5a29e4f..7f67747 100644
--- a/pytools/__init__.py
+++ b/pytools/__init__.py
@@ -2181,7 +2181,7 @@ class ProcessLogger(object):
         self.is_done = False
 
         self.timer = _Timer()
-        timer.start()
+        self.timer.start()
 
         import threading
         self.late_start_log_thread = threading.Thread(target=self._log_start_if_long)
-- 
GitLab


From 54311bab0eebdb7ebec388bdaeab98977968de5d Mon Sep 17 00:00:00 2001
From: Matt Wala <wala1@illinois.edu>
Date: Tue, 12 Jun 2018 15:18:20 -0500
Subject: [PATCH 04/12] flake8 fix

---
 pytools/__init__.py | 1 +
 1 file changed, 1 insertion(+)

diff --git a/pytools/__init__.py b/pytools/__init__.py
index 7f67747..07923c6 100644
--- a/pytools/__init__.py
+++ b/pytools/__init__.py
@@ -2129,6 +2129,7 @@ class record_exec_time(object):  # noqa: N801
         description = self.description or wrapped.__name__
 
         from contextlib import contextmanager
+        
         @contextmanager
         def time_process(output):
             timer = _Timer()
-- 
GitLab


From e3cb04fa15d15a4a611d48ec6b31b0563998aee7 Mon Sep 17 00:00:00 2001
From: Matt Wala <wala1@illinois.edu>
Date: Tue, 12 Jun 2018 15:18:47 -0500
Subject: [PATCH 05/12] Another flake8 fix (woops)

---
 pytools/__init__.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/pytools/__init__.py b/pytools/__init__.py
index 07923c6..776e6a9 100644
--- a/pytools/__init__.py
+++ b/pytools/__init__.py
@@ -2129,7 +2129,7 @@ class record_exec_time(object):  # noqa: N801
         description = self.description or wrapped.__name__
 
         from contextlib import contextmanager
-        
+
         @contextmanager
         def time_process(output):
             timer = _Timer()
-- 
GitLab


From 22f951f9aadd9a94f672905c522c2a286dec7458 Mon Sep 17 00:00:00 2001
From: Matt Wala <wala1@illinois.edu>
Date: Tue, 12 Jun 2018 15:26:16 -0500
Subject: [PATCH 06/12] Rename: record_exec_time -> record_time

---
 pytools/__init__.py  | 2 +-
 test/test_pytools.py | 6 +++---
 2 files changed, 4 insertions(+), 4 deletions(-)

diff --git a/pytools/__init__.py b/pytools/__init__.py
index 776e6a9..34710d2 100644
--- a/pytools/__init__.py
+++ b/pytools/__init__.py
@@ -2115,7 +2115,7 @@ class _Timer(object):
                 process_elapsed=self.process_elapsed)
 
 
-class record_exec_time(object):  # noqa: N801
+class record_time(object):  # noqa: N801
     """A decorator for recording timing data for a function call.
 
     Timing data is saved inside a dict passed as an optional keyword argument.
diff --git a/test/test_pytools.py b/test/test_pytools.py
index dd1f8a3..026e7de 100644
--- a/test/test_pytools.py
+++ b/test/test_pytools.py
@@ -223,10 +223,10 @@ def test_reshaped_view():
         pytools.reshaped_view(b, -1)
 
 
-def test_record_exec_time():
-    from pytools import record_exec_time
+def test_record_time():
+    from pytools import record_time
 
-    @record_exec_time(arg="time")
+    @record_time(arg="time")
     def f(a):
         return a
 
-- 
GitLab


From 6c96e1e67a5ca06130481db41d29eb681a0f6945 Mon Sep 17 00:00:00 2001
From: Matt Wala <wala1@illinois.edu>
Date: Tue, 12 Jun 2018 15:33:04 -0500
Subject: [PATCH 07/12] Allow passing None as a default argument

---
 pytools/__init__.py | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/pytools/__init__.py b/pytools/__init__.py
index 34710d2..570e9f3 100644
--- a/pytools/__init__.py
+++ b/pytools/__init__.py
@@ -2139,10 +2139,10 @@ class record_time(object):  # noqa: N801
             output[description] = timer.result()
 
         def wrapper(*args, **kwargs):
-            if self.arg not in kwargs:
+            output = kwargs.pop(self.arg, None)
+            if output is None:
                 return wrapped(*args, **kwargs)
 
-            output = kwargs.pop(self.arg)
             with time_process(output):
                 return wrapped(*args, **kwargs)
 
-- 
GitLab


From c1d960a0cb15cab091fec080638bdb7f99e30d1e Mon Sep 17 00:00:00 2001
From: Matt Wala <wala1@illinois.edu>
Date: Tue, 12 Jun 2018 16:17:20 -0500
Subject: [PATCH 08/12] Change interface to avoid ambiguity with regards to
 multiple calls to the same function.

---
 pytools/__init__.py  | 16 +++++++++-------
 test/test_pytools.py | 15 ++++++++-------
 2 files changed, 17 insertions(+), 14 deletions(-)

diff --git a/pytools/__init__.py b/pytools/__init__.py
index 570e9f3..9dddb26 100644
--- a/pytools/__init__.py
+++ b/pytools/__init__.py
@@ -2108,17 +2108,17 @@ class _Timer(object):
             self.wall_elapsed = timeit.default_timer() - self.time_start
             self.process_elapsed = None
 
-    def result(self):
-        assert self.finished
-        return _TimerResult(
-                wall_elapsed=self.wall_elapsed,
-                process_elapsed=self.process_elapsed)
-
 
 class record_time(object):  # noqa: N801
     """A decorator for recording timing data for a function call.
 
     Timing data is saved inside a dict passed as an optional keyword argument.
+    The following fields are written to the dict:
+
+    - *description*
+    - *wall_elapsed*
+    - *process_elapsed*
+
     """
 
     def __init__(self, arg=None, description=None):
@@ -2136,7 +2136,9 @@ class record_time(object):  # noqa: N801
             timer.start()
             yield
             timer.stop()
-            output[description] = timer.result()
+            output["description"] = description
+            output["wall_elapsed"] = timer.wall_elapsed
+            output["process_elapsed"] = timer.process_elapsed
 
         def wrapper(*args, **kwargs):
             output = kwargs.pop(self.arg, None)
diff --git a/test/test_pytools.py b/test/test_pytools.py
index 026e7de..40e1848 100644
--- a/test/test_pytools.py
+++ b/test/test_pytools.py
@@ -226,18 +226,19 @@ def test_reshaped_view():
 def test_record_time():
     from pytools import record_time
 
-    @record_time(arg="time")
+    @record_time(arg="times")
     def f(a):
         return a
 
-    f(1)
+    assert f(1) is 1
+    assert f(1, times=None) is 1
 
-    time = {}
-    f(1, time=time)
+    times = {}
+    f(1, times=times)
 
-    assert "f" in time
-    assert hasattr(time["f"], "wall_elapsed")
-    assert hasattr(time["f"], "process_elapsed")
+    assert "description" in times
+    assert "wall_elapsed" in times
+    assert "process_elapsed" in times
 
 
 if __name__ == "__main__":
-- 
GitLab


From 6d852162e7746993f9c8fcebf4a3e1e59c31690c Mon Sep 17 00:00:00 2001
From: Matt Wala <wala1@illinois.edu>
Date: Wed, 13 Jun 2018 14:49:27 -0400
Subject: [PATCH 09/12] Delete _TimerResult.

---
 pytools/__init__.py | 5 -----
 1 file changed, 5 deletions(-)

diff --git a/pytools/__init__.py b/pytools/__init__.py
index 9dddb26..090f00e 100644
--- a/pytools/__init__.py
+++ b/pytools/__init__.py
@@ -2069,11 +2069,6 @@ def reshaped_view(a, newshape):
 
 # {{{ timing utilities
 
-class _TimerResult(Record):
-
-    __slots__ = ["wall_elapsed", "process_elapsed"]
-
-
 class _Timer(object):
 
     def __init__(self):
-- 
GitLab


From eeafea801c2a6964e9c0013b0c0d7c417d08556b Mon Sep 17 00:00:00 2001
From: Matt Wala <wala1@illinois.edu>
Date: Wed, 13 Jun 2018 14:33:51 -0500
Subject: [PATCH 10/12] Add documentation

---
 pytools/__init__.py | 27 +++++++++++++++++++++++----
 1 file changed, 23 insertions(+), 4 deletions(-)

diff --git a/pytools/__init__.py b/pytools/__init__.py
index 090f00e..87bd264 100644
--- a/pytools/__init__.py
+++ b/pytools/__init__.py
@@ -138,6 +138,11 @@ Helpers for :mod:`numpy`
 .. autofunction:: reshaped_view
 
 
+Timing data
+-----------
+
+.. autoclass:: record_time
+
 Log utilities
 -------------
 
@@ -2107,13 +2112,27 @@ class _Timer(object):
 class record_time(object):  # noqa: N801
     """A decorator for recording timing data for a function call.
 
-    Timing data is saved inside a dict passed as an optional keyword argument.
-    The following fields are written to the dict:
+    Timing data is saved to a :class:`dict` passed as an optional keyword
+    argument. The following entries are written:
 
     - *description*
     - *wall_elapsed*
-    - *process_elapsed*
-
+    - *process_elapsed*.
+
+    Timing data is returned in seconds. Depending on system support,
+    *process_elapsed* may be *None*.
+
+    Example usage::
+
+        >>> from time import sleep
+        >>> @record_time("timing_data")
+        ... def slow_function(n):
+        ...   sleep(n)
+        ...
+        >>> timing_result = {}
+        >>> slow_function(1, timing_data=timing_result)
+        >>> print(timing_result)
+        {'description': 'slow_function', 'wall_elapsed': 1.0052917799912393, 'process_elapsed': 0.0001330000000000081}
     """
 
     def __init__(self, arg=None, description=None):
-- 
GitLab


From c0f1af682147f6bb78704adf70b1fe710976df2e Mon Sep 17 00:00:00 2001
From: Matt Wala <wala1@illinois.edu>
Date: Wed, 13 Jun 2018 14:37:33 -0500
Subject: [PATCH 11/12] Suppress flake8 warning

---
 pytools/__init__.py | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/pytools/__init__.py b/pytools/__init__.py
index 87bd264..d0ccc4e 100644
--- a/pytools/__init__.py
+++ b/pytools/__init__.py
@@ -2133,7 +2133,7 @@ class record_time(object):  # noqa: N801
         >>> slow_function(1, timing_data=timing_result)
         >>> print(timing_result)
         {'description': 'slow_function', 'wall_elapsed': 1.0052917799912393, 'process_elapsed': 0.0001330000000000081}
-    """
+    """  # noqa: E501
 
     def __init__(self, arg=None, description=None):
         self.arg = arg
-- 
GitLab


From 64fde1b6080bed2e8069abd38d8e0d41793191ce Mon Sep 17 00:00:00 2001
From: Matt Wala <wala1@illinois.edu>
Date: Wed, 13 Jun 2018 14:40:09 -0500
Subject: [PATCH 12/12] Clarify when process_elapsed is None.

---
 pytools/__init__.py | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/pytools/__init__.py b/pytools/__init__.py
index d0ccc4e..8dcef80 100644
--- a/pytools/__init__.py
+++ b/pytools/__init__.py
@@ -2119,8 +2119,8 @@ class record_time(object):  # noqa: N801
     - *wall_elapsed*
     - *process_elapsed*.
 
-    Timing data is returned in seconds. Depending on system support,
-    *process_elapsed* may be *None*.
+    Timing data is returned in seconds. For Python versions before 3.3,
+    *process_elapsed* is *None*.
 
     Example usage::
 
-- 
GitLab