Skip to content

Commit

Permalink
Merge pull request #4 from ancestor-mithril/dev
Browse files Browse the repository at this point in the history
Added new facility for registering timed decorators and using the same decorator throughout the codebase.
* Updated tests and documentation.
* Maintaining the documentation in only 1 place. Removed the parameter documentation from `nested_timer` and added a redirection to `timer`. 

The new facility allows for creating a complicated timer which is also able to accumulate elapsed times from all the measured functions. It can be easily manipulated to create code statistics using client code.
  • Loading branch information
ancestor-mithril authored May 1, 2024
2 parents 31ee721 + 3a52dee commit 7ced90b
Show file tree
Hide file tree
Showing 4 changed files with 206 additions and 26 deletions.
101 changes: 101 additions & 0 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -32,6 +32,8 @@ fibonacci(10000)
# fibonacci() -> total time: 1114100ns
```

For more advanced usage, consider registering a timed decorator and using it afterward through your codebase. See [Registering a timed decorator](#registering-a-timed-decorator).

### Documentation

1. `timed`
Expand All @@ -52,6 +54,15 @@ fibonacci(10000)

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).

3. `create_timed_decorator` registers a timed decorator with a given name.
* `name` (`str`): The name of the timed decorator which will be instantiated using the provided arguments. Use this name for retrieving the timed decorator with `timed_decorator.builder.get_timed_decorator`.
* `nested` (`bool`): If `True`, uses the `timed_decorator.nested_timed.nested_timed` as decorator, otherwise uses `timed_decorator.simple_timed.timed`. Default: `False`.
* Also receives all the other arguments accepted by `timed` and `nested_timed`.

4. `get_timed_decorator` wraps the decorated function and lazily measures its elapsed time using the registered timed decorator. The timer can be registered after the function definition, but must be registered before the first function call.
* `name` (`str`): The name of the timed decorator registered using `timed_decorator.builder.create_timed_decorator`.


### Examples

Simple usage.
Expand Down Expand Up @@ -436,3 +447,93 @@ Prints:
batched_euclidean_distance(CpuTensor[10000, 800], CpuTensor[12000, 800]) -> total time: 685659400ns
batched_euclidean_distance(CudaTensor[10000, 800], CudaTensor[12000, 800]) -> total time: 260411900ns
```


### Registering a timed decorator

```py
from time import sleep

from timed_decorator.builder import create_timed_decorator, get_timed_decorator


@get_timed_decorator("MyCustomTimer")
def main():
@get_timed_decorator("MyCustomTimer")
def function_1():
sleep(0.1)

@get_timed_decorator("MyCustomTimer")
def nested_function():
@get_timed_decorator("MyCustomTimer")
def function_2():
sleep(0.2)

@get_timed_decorator("MyCustomTimer")
def function_3():
sleep(0.3)

function_2()
function_2()
function_3()

nested_function()
function_1()
nested_function()
function_1()


if __name__ == '__main__':
my_measurements = {}
create_timed_decorator("MyCustomTimer",
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()
print()

# Now I can do stuff with my measurements.
functions = sorted(my_measurements.keys(), reverse=True)

for i in range(len(functions)):
fn_1 = functions[i]
print(f'Function {fn_1}:')
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
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_3:
* took 42.85% from main.<locals>.nested_function
* took 37.49% from main
Function main.<locals>.nested_function.<locals>.function_2:
* took 57.11% from main.<locals>.nested_function
* took 49.96% from main
Function main.<locals>.nested_function:
* took 87.48% from main
Function main.<locals>.function_1:
* took 12.51% from main
Function main:
```
16 changes: 16 additions & 0 deletions tests/test_usage.py
Original file line number Diff line number Diff line change
Expand Up @@ -5,6 +5,7 @@
from time import sleep

from tests.functions import fibonacci, recursive_fibonacci
from timed_decorator.builder import create_timed_decorator, get_timed_decorator
from timed_decorator.nested_timed import nested_timed
from timed_decorator.simple_timed import timed
from timed_decorator.utils import build_decorated_fn
Expand Down Expand Up @@ -141,6 +142,21 @@ def fn(x):
self.assertIsInstance(elapsed, int)
self.assertGreater(elapsed / 1e+9, seconds)

def test_create_timed_decorator(self):
create_timed_decorator('same name')
self.assertRaises(KeyError, create_timed_decorator, 'same name')
create_timed_decorator('other name')

get_timed_decorator('same name')(fibonacci)(10000)
get_timed_decorator('other name')(fibonacci)(10000)
fn = get_timed_decorator('no name')(fibonacci) # Does not raise error if not called
self.assertRaises(KeyError, fn, 10000)

# Defer instantiation
fn = get_timed_decorator('lazy name')(fibonacci)
create_timed_decorator('lazy name')
fn(10000)


if __name__ == '__main__':
unittest.main()
87 changes: 87 additions & 0 deletions timed_decorator/builder.py
Original file line number Diff line number Diff line change
@@ -0,0 +1,87 @@
from functools import wraps
from typing import Union

from .nested_timed import nested_timed
from .simple_timed import timed

_timed_decorators = {}


def create_timed_decorator(name: str,
nested: bool = False,
collect_gc: bool = True,
disable_gc: bool = False,
use_seconds: bool = False,
precision: int = 9,
show_args: bool = False,
show_kwargs: bool = False,
display_level: int = 1,
sep: str = ', ',
stdout: bool = True,
file_path: Union[str, None] = None,
logger_name: Union[str, None] = None,
return_time: bool = False,
out: dict = None,
use_qualname: bool = False):
"""
Registers a timed decorator with a given name. Once instantiated, the timed decorator can be retrieved with
:class:`timed_decorator.builder.get_timed_decorator` and used for measuring the runtime of decorated functions.
Args:
name (str): The name of the timed decorator which will be instantiated using the provided arguments. Use this
name for retrieving the timed decorator with :class:`timed_decorator.builder.get_timed_decorator`.
nested (bool): If `True`, uses the :class:`timed_decorator.nested_timed.nested_timed` as decorator, otherwise
uses :class:`timed_decorator.simple_timed.timed`. Default: `False`.
See Also:
:class:`timed_decorator.simple_timed.timed` for the remaining parameters' documentation.
"""
global _timed_decorators
if name in _timed_decorators:
raise KeyError(f'Timed decorator {name} already registered.')

decorator = nested_timed if nested else timed
_timed_decorators[name] = decorator(collect_gc=collect_gc,
disable_gc=disable_gc,
use_seconds=use_seconds,
precision=precision,
show_args=show_args,
show_kwargs=show_kwargs,
display_level=display_level,
sep=sep,
stdout=stdout,
file_path=file_path,
logger_name=logger_name,
return_time=return_time,
out=out,
use_qualname=use_qualname)


def _get_timed_decorator(name: str):
global _timed_decorators
if name not in _timed_decorators:
raise KeyError(f'Timed decorator {name} not registered. Please register it first using '
f'timed_decorator.builder.create_timed_decorator')

return _timed_decorators[name]


def get_timed_decorator(name: str):
"""
Wraps the decorated function and lazily measures its elapsed time using the registered timed decorator. The timer
can be registered after the function definition, but must be registered before the first function call.
Args:
name (str): The name of the timed decorator registered using
:class:`timed_decorator.builder.create_timed_decorator`.
"""
def decorator(fn):
@wraps(fn)
def wrap(*args, **kwargs):
return _get_timed_decorator(name)(fn)(*args, **kwargs)

return wrap

return decorator
28 changes: 2 additions & 26 deletions timed_decorator/nested_timed.py
Original file line number Diff line number Diff line change
Expand Up @@ -27,33 +27,9 @@ def nested_timed(collect_gc: bool = True,
"""
A nested timing decorator that measures the time elapsed during the function call and accounts for other decorators
further in the call stack.
It uses perf_counter_ns for measuring which includes time elapsed during sleep and is system-wide.
Args:
collect_gc (bool): If `True`, runs a full garbage collection before timing the wrapped function. Default:
`True`.
disable_gc (bool): If `True`, disabled garbage collection during function execution. Default: `False`.
use_seconds (bool): If `True`, displays the elapsed time in seconds. Default: `False`.
precision (int): Used in conjunction with `use_seconds`, represents the decimal points used for printing
seconds. Default: `9`.
show_args (bool): If `True`, displays the function arguments according to `display_level`. Useful when timing
function calls with arguments of different magnitude. Default: `False`.
show_kwargs (bool): If `True`, displays the keyword arguments according to `display_level`. Default: `False`.
display_level (int): The level of verbosity used when printing function arguments ad keyword arguments. If `0`,
prints the type of the parameters. If `1`, prints values for all primitive types, shapes for arrays,
tensors, dataframes and length for sequences. Otherwise, prints values for all parameters. Default: `1`.
sep (str): The separator used when printing function arguments and keyword arguments. Default: `', '`.
stdout (bool): If `True`, writes the elapsed time to stdout. Default: `True`.
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`.
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`.
use_qualname (bool): If `True`, uses the qualified name of the function when logging the elapsed time. Default:
`False`.
See Also:
:class:`timed_decorator.simple_timed.timed` for parameter documentation.
"""
gc_collect = collect if collect_gc else nop
time_formatter = TimeFormatter(use_seconds, precision)
Expand Down

0 comments on commit 7ced90b

Please sign in to comment.