Merge pull request #5 from ancestor-mithril/dev

Changing behavior of `out` parameter
Previous behavior:
* if `out` is passed to the decorator, the elapsed time is stored in the `dict` using the fully qualified name as key.

New behavior:
* if `out` is passed to the decorator, the number of function calls, the elapsed time and the "own time" is stored using the fully qualified name as key.

README.md

@@ -49,7 +49,7 @@ For more advanced usage, consider registering a timed decorator and using it aft
     * `file_path` (`str`): If not `None`, writes the measurement at the end of the given file path. For thread safe file writing configure use `logger_name` instead. Default: `None`.
     * `logger_name` (`str`): If not `None`, uses the given logger to print the measurement. Can't be used in conjunction with `file_path`. Default: `None`. See [Using a logger](#using-a-logger).
     * `return_time` (`bool`): If `True`, returns the elapsed time in addition to the wrapped function's return value. Default: `False`.
-    * `out` (`dict`): If not `None`, stores the elapsed time in nanoseconds in the given dict using the fully qualified function name as key.  If the key already exists, adds the time to the existing value. Default: `None`. See [Storing the elapsed time in a dict](#storing-the-elapsed-time-in-a-dict).
+    * `out` (`dict`): If not `None`, stores the elapsed time in nanoseconds in the given dict using the fully qualified function name as key, in the following format: (function call counts, total elapsed time, total "own time"). If the key already exists, updates the existing value. The elapsed time is equal to "own time" for the simple timed decorator. For the nested time decorator, the elapsed time is different from "own time" only when another function decorated with a nested timer is called during the execution of the current function. Default: `None`. See [Storing the elapsed time in a dict](#storing-the-elapsed-time-in-a-dict).
     * `use_qualname` (`bool`): If `True`, If `True`, uses the qualified name of the function when logging the elapsed time. Default: `False`.
 
 2. `nested_timed` is similar to `timed`, however it is designed to work nicely with multiple timed functions that call each other, displaying both the total execution time and the difference after subtracting other timed functions on the same call stack. See [Nested timing decorator](#nested-timing-decorator).
@@ -410,8 +410,8 @@ print(ns)
 ```
 Prints
 ```
-{'fn': 1000767300}
-{'fn': 2001006100}
+{'fn': [1, 1000672000, 1000672000]}
+{'fn': [2, 2001306900, 2001306900]}
 ```
 
 ### Compatible with PyTorch tensors
@@ -486,15 +486,15 @@ def main():
 if __name__ == '__main__':
     my_measurements = {}
     create_timed_decorator("MyCustomTimer",
+                           nested=False,  # This is true by default
                            collect_gc=False,  # I don't want to explicitly collect garbage
                            disable_gc=True,  # I don't want to wait for garbage collection during measuring
                            stdout=False,  # I don't wat to print stuff to console
                            out=my_measurements  # My measurements dict
                            )
     main()
-    for key, value in my_measurements.items():
-        print(f'Function {key} took {value / 1e+9}s')
-    print()
+    for key, (counts, elapsed, own_time) in my_measurements.items():
+        print(f'Function {key} was called {counts} time(s) and took {elapsed / 1e+9}s')
     print()
 
     # Now I can do stuff with my measurements.
@@ -506,30 +506,31 @@ if __name__ == '__main__':
         for j in range(i + 1, len(functions)):
             fn_2 = functions[j]
             if fn_1.startswith(fn_2):
-                ratio = my_measurements[fn_1] / my_measurements[fn_2] * 100
+                _, elapsed_1, _ = my_measurements[fn_1]
+                _, elapsed_2, _ = my_measurements[fn_2]
+                ratio = elapsed_1 / elapsed_2 * 100
                 print(f'* took {ratio:.2f}% from {fn_2}')
         print()
 ```
 
 Prints:
 ```
-Function main.<locals>.nested_function.<locals>.function_2 took 0.8016428s
-Function main.<locals>.nested_function.<locals>.function_3 took 0.6014647s
-Function main.<locals>.nested_function took 1.403586s
-Function main.<locals>.function_1 took 0.2006981s
-Function main took 1.6045189s
-
+Function main.<locals>.nested_function.<locals>.function_2 was called 4 time(s) and took 0.8019482s
+Function main.<locals>.nested_function.<locals>.function_3 was called 2 time(s) and took 0.6010157s
+Function main.<locals>.nested_function was called 2 time(s) and took 1.403365s
+Function main.<locals>.function_1 was called 2 time(s) and took 0.2007625s
+Function main was called 1 time(s) and took 1.6043592s
 
 Function main.<locals>.nested_function.<locals>.function_3:
-* took 42.85% from main.<locals>.nested_function
-* took 37.49% from main
+* took 42.83% from main.<locals>.nested_function
+* took 37.46% from main
 
 Function main.<locals>.nested_function.<locals>.function_2:
-* took 57.11% from main.<locals>.nested_function
-* took 49.96% from main
+* took 57.14% from main.<locals>.nested_function
+* took 49.99% from main
 
 Function main.<locals>.nested_function:
-* took 87.48% from main
+* took 87.47% from main
 
 Function main.<locals>.function_1:
 * took 12.51% from main

tests/test_usage.py

@@ -106,7 +106,7 @@ def fn_2():
         self.assertIn(fn_2.__name__, logged[1])
         self.assertIn(fn_2.__qualname__, logged[1])
 
-    def test_ns_output(self):
+    def test_dict_output(self):
         out = {}
 
         @timed(out=out, stdout=False)
@@ -115,8 +115,38 @@ def fn():
 
         fn()
 
-        self.assertIsInstance(out[fn.__qualname__], int)
-        self.assertGreater(out[fn.__qualname__], 1e+8)
+        counts, elapsed, own_time = out[fn.__qualname__]
+        self.assertEqual(counts, 1)
+        self.assertIsInstance(elapsed, int)
+        self.assertGreater(elapsed, 1e+8)
+        self.assertEqual(elapsed, own_time)
+
+        fn()
+        counts, elapsed, own_time = out[fn.__qualname__]
+        self.assertEqual(counts, 2)
+        self.assertIsInstance(elapsed, int)
+        self.assertGreater(elapsed, 2e+8)
+        self.assertEqual(elapsed, own_time)
+
+    def test_dict_output_with_nested_timed(self):
+        out = {}
+
+        @nested_timed(out=out, stdout=False)
+        def fn1():
+            @nested_timed(out=out, stdout=False)
+            def fn2():
+                sleep(0.1)
+
+            fn2()
+
+        fn1()
+
+        counts_1, elapsed_1, own_time_1 = out[fn1.__qualname__]
+        counts_2, elapsed_2, own_time_2 = out[fn1.__qualname__ + '.<locals>.fn2']
+
+        self.assertTrue(counts_1 == counts_2 == 1)
+        self.assertEqual(own_time_2, elapsed_2)
+        self.assertGreater(elapsed_1, own_time_1)
 
     def test_qualname(self):
         out = {}

timed_decorator/nested_timed.py

@@ -4,7 +4,7 @@
 from time import perf_counter_ns
 from typing import Union
 
-from .utils import nop, TimeFormatter, InputFormatter, synchronize_cuda, Logger, write_mutable
+from .utils import nop, TimeFormatter, InputFormatter, synchronize_cuda, Logger, update_timing_dict
 
 nested_level = 0
 nested_times = dict()
@@ -35,7 +35,7 @@ def nested_timed(collect_gc: bool = True,
     time_formatter = TimeFormatter(use_seconds, precision)
     input_formatter = InputFormatter(show_args, show_kwargs, display_level, sep)
     logger = Logger(stdout, file_path, logger_name)
-    ns_out = write_mutable if out is not None else nop
+    update_dict = update_timing_dict if out is not None else nop
 
     def decorator(fn):
         @wraps(fn)
@@ -75,7 +75,7 @@ def wrap(*args, **kwargs):
                 nested_times[nested_level].append(elapsed)
 
             fn_name = fn.__qualname__ if use_qualname else fn.__name__
-            ns_out(out, fn.__qualname__, elapsed)
+            update_dict(out, fn.__qualname__, elapsed, own_time)
             logger('\t' * nested_level + f'{input_formatter(fn_name, *args, **kwargs)} '
                                          f'-> total time: {time_formatter(elapsed)}, '
                                          f'own time: {time_formatter(own_time)}')

timed_decorator/simple_timed.py

@@ -4,7 +4,7 @@
 from time import perf_counter_ns
 from typing import Union
 
-from .utils import nop, TimeFormatter, InputFormatter, synchronize_cuda, Logger, write_mutable
+from .utils import nop, TimeFormatter, InputFormatter, synchronize_cuda, Logger, update_timing_dict
 
 
 def timed(collect_gc: bool = True,
@@ -47,15 +47,19 @@ def timed(collect_gc: bool = True,
         return_time (bool): If `True`, returns the elapsed time in addition to the wrapped function's return value.
             Default: `False`.
         out (dict): If not `None`, stores the elapsed time in nanoseconds in the given dict using the fully qualified
-            function name as key. If the key already exists, adds the time to the existing value. Default: `None`.
+            function name as key, in the following format: (function call counts, total elapsed time, total "own time").
+            If the key already exists, updates the existing value. The elapsed time is equal to "own time" for the simple
+            timed decorator. For the nested time decorator, the elapsed time is different from "own time" only when
+            another function decorated with a nested timer is called during the execution of the current function.
+            Default: `None`.
         use_qualname (bool): If `True`, uses the qualified name of the function when logging the elapsed time. Default:
             `False`.
     """
     gc_collect = collect if collect_gc else nop
     time_formatter = TimeFormatter(use_seconds, precision)
     input_formatter = InputFormatter(show_args, show_kwargs, display_level, sep)
     logger = Logger(stdout, file_path, logger_name)
-    ns_out = write_mutable if out is not None else nop
+    update_dict = update_timing_dict if out is not None else nop
 
     def decorator(fn):
         @wraps(fn)
@@ -75,7 +79,7 @@ def wrap(*args, **kwargs):
 
             elapsed = end - start
             fn_name = fn.__qualname__ if use_qualname else fn.__name__
-            ns_out(out, fn.__qualname__, elapsed)
+            update_dict(out, fn.__qualname__, elapsed, elapsed)
             logger(f'{input_formatter(fn_name, *args, **kwargs)} -> total time: {time_formatter(elapsed)}')
             if return_time:
                 return ret, elapsed

timed_decorator/utils.py

@@ -139,5 +139,6 @@ def synchronize_cuda(*args, **kwargs):
         torch.cuda.synchronize(device)
 
 
-def write_mutable(out: dict, key: str, value: int):
-    out[key] = out.get(key, 0) + value
+def update_timing_dict(out: dict, key: str, elapsed: int, own_time: int):
+    counts, elapsed_total, own_time_total = out.get(key, (0, 0, 0))
+    out[key] = [counts + 1, elapsed_total + elapsed, own_time_total + own_time]