diff --git a/AUTHORS.md b/AUTHORS.md index 05748d1..9c74333 100644 --- a/AUTHORS.md +++ b/AUTHORS.md @@ -10,9 +10,10 @@ ## Contributors -- [Jan Freyberg](https://github.com/janfreyberg) - [Alkatar21](https://github.com/alkatar21) - [D.C. Hess](https://github.com/dchess) +- [Jan Freyberg](https://github.com/janfreyberg) - [Mischa Lisovyi](https://github.com/mlisovyi) +- [Matthew Price](https://github.com/pricemg) -See the [changelog](https://github.com/realpython/codetiming/blob/master/CHANGELOG.md) for more details. \ No newline at end of file +See the [changelog](https://github.com/realpython/codetiming/blob/master/CHANGELOG.md) for more details. diff --git a/CHANGELOG.md b/CHANGELOG.md index aab8eca..fcc5098 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,10 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/), ## [Unreleased] +### Added + +- `inital_text` parameter which, when present, will use logger to log that timer has been started (by [Matthew Price](https://github.com/pricemg) in [#47]) + ## [1.3.2] - 2022-10-07 ### Added @@ -40,7 +44,7 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/), ### Changed -- `Timer.timers` changed from regular to `dict` to a custom dictionary supporting basic statistics for named timers ([#23]). +- `Timer.timers` changed from regular `dict` to a custom dictionary supporting basic statistics for named timers ([#23]). ## [1.1.0] - 2020-01-15 @@ -81,3 +85,4 @@ Initial version of `codetiming`. Version 1.0.0 corresponds to the code in the tu [#35]: https://github.com/realpython/codetiming/pull/35 [#38]: https://github.com/realpython/codetiming/pull/38 [#46]: https://github.com/realpython/codetiming/pull/46 +[#47]: https://github.com/realpython/codetiming/pull/47 diff --git a/README.md b/README.md index 8e87f74..9f765a1 100644 --- a/README.md +++ b/README.md @@ -55,7 +55,8 @@ You can use `codetiming.Timer` in several different ways: `Timer` accepts the following arguments when it's created. All arguments are optional: - **`name`:** An optional name for your timer -- **`text`:** The text shown when your timer ends. It should contain a `{}` placeholder that will be filled by the elapsed time in seconds (default: `"Elapsed time: {:.4f} seconds"`) +- **`text`:** The text that's shown when your timer ends. It should contain a `{}` placeholder that will be filled by the elapsed time in seconds (default: `"Elapsed time: {:.4f} seconds"`) +- **`initial_text`:** Show text when your timer starts. You may provide the string to be logged or `True` to show the default text `"Timer {name} started"` (default: `False`) - **`logger`:** A function/callable that takes a string argument and will report the elapsed time when the logger is stopped (default: `print()`) You can turn off explicit reporting of the elapsed time by setting `logger=None`. @@ -81,13 +82,21 @@ t = Timer(text=lambda secs: f"{secs / 86400:.0f} days") This allows you to use third-party libraries like [`humanfriendly`](https://pypi.org/project/humanfriendly/) to do the text formatting: -``` +```python from humanfriendly import format_timespan t1 = Timer(text=format_timespan) t2 = Timer(text=lambda secs: f"Elapsed time: {format_timespan(secs)}") ``` +You may include a text that should be logged when the timer starts by setting `initial_text`: + +```python +t = Timer(initial_text="And so it begins ...") +``` + +You can also set `initial_text=True` to use a default initial text. + ## Capturing the Elapsed Time @@ -109,7 +118,7 @@ elapsed_time = t.last Named timers are made available in the class dictionary `Timer.timers`. The elapsed time will accumulate if the same name or same timer is used several times. Consider the following example: -```python +```pycon >>> import logging >>> from codetiming import Timer @@ -133,7 +142,7 @@ The example shows how you can redirect the timer output to the logging module. N You can also get simple statistics about your named timers. Continuing from the example above: -```python +```pycon >>> Timer.timers.max("example") 3.5836678670002584 diff --git a/codetiming/_timer.py b/codetiming/_timer.py index 94b426d..4b218af 100644 --- a/codetiming/_timer.py +++ b/codetiming/_timer.py @@ -27,6 +27,7 @@ class Timer(ContextDecorator): _start_time: Optional[float] = field(default=None, init=False, repr=False) name: Optional[str] = None text: Union[str, Callable[[float], str]] = "Elapsed time: {:0.4f} seconds" + initial_text: Union[bool, str] = False logger: Optional[Callable[[str], None]] = print last: float = field(default=math.nan, init=False, repr=False) @@ -35,6 +36,16 @@ def start(self) -> None: if self._start_time is not None: raise TimerError("Timer is running. Use .stop() to stop it") + # Log initial text when timer starts + if self.logger and self.initial_text: + if isinstance(self.initial_text, str): + initial_text = self.initial_text.format(name=self.name) + elif self.name: + initial_text = "Timer {name} started".format(name=self.name) + else: + initial_text = "Timer started" + self.logger(initial_text) + self._start_time = time.perf_counter() def stop(self) -> float: diff --git a/tests/test_codetiming.py b/tests/test_codetiming.py index fb1c054..c9502c8 100644 --- a/tests/test_codetiming.py +++ b/tests/test_codetiming.py @@ -14,39 +14,57 @@ from codetiming import Timer, TimerError # -# Test functions +# Constants, functions, and classes used by tests # TIME_PREFIX = "Wasted time:" TIME_MESSAGE = f"{TIME_PREFIX} {{:.4f}} seconds" RE_TIME_MESSAGE = re.compile(TIME_PREFIX + r" 0\.\d{4} seconds") +RE_TIME_MESSAGE_INITIAL_TEXT_TRUE = re.compile( + f"Timer started\n{TIME_PREFIX}" + r" 0\.\d{4} seconds" +) +RE_TIME_MESSAGE_INITIAL_TEXT_CUSTOM = re.compile( + f"Starting the party\n{TIME_PREFIX}" + r" 0\.\d{4} seconds" +) def waste_time(num=1000): - """Just waste a little bit of time""" + """Just waste a little bit of time.""" sum(n**2 for n in range(num)) @Timer(text=TIME_MESSAGE) def decorated_timewaste(num=1000): - """Just waste a little bit of time""" + """Just waste a little bit of time.""" + sum(n**2 for n in range(num)) + + +@Timer(text=TIME_MESSAGE, initial_text=True) +def decorated_timewaste_initial_text_true(num=1000): + """Just waste a little bit of time.""" + sum(n**2 for n in range(num)) + + +@Timer(text=TIME_MESSAGE, initial_text="Starting the party") +def decorated_timewaste_initial_text_custom(num=1000): + """Just waste a little bit of time.""" sum(n**2 for n in range(num)) @Timer(name="accumulator", text=TIME_MESSAGE) def accumulated_timewaste(num=1000): - """Just waste a little bit of time""" + """Just waste a little bit of time.""" sum(n**2 for n in range(num)) class CustomLogger: - """Simple class used to test custom logging capabilities in Timer""" + """Simple class used to test custom logging capabilities in Timer.""" def __init__(self): - """Store log messages in the .messages attribute""" + """Store log messages in the .messages attribute.""" self.messages = "" def __call__(self, message): - """Add a log message to the .messages attribute""" + """Add a log message to the .messages attribute.""" self.messages += message @@ -54,8 +72,9 @@ def __call__(self, message): # Tests # def test_timer_as_decorator(capsys): - """Test that decorated function prints timing information""" + """Test that decorated function prints timing information.""" decorated_timewaste() + stdout, stderr = capsys.readouterr() assert RE_TIME_MESSAGE.match(stdout) assert stdout.count("\n") == 1 @@ -63,9 +82,10 @@ def test_timer_as_decorator(capsys): def test_timer_as_context_manager(capsys): - """Test that timed context prints timing information""" + """Test that timed context prints timing information.""" with Timer(text=TIME_MESSAGE): waste_time() + stdout, stderr = capsys.readouterr() assert RE_TIME_MESSAGE.match(stdout) assert stdout.count("\n") == 1 @@ -73,11 +93,12 @@ def test_timer_as_context_manager(capsys): def test_explicit_timer(capsys): - """Test that timed section prints timing information""" + """Test that timed section prints timing information.""" t = Timer(text=TIME_MESSAGE) t.start() waste_time() t.stop() + stdout, stderr = capsys.readouterr() assert RE_TIME_MESSAGE.match(stdout) assert stdout.count("\n") == 1 @@ -85,14 +106,14 @@ def test_explicit_timer(capsys): def test_error_if_timer_not_running(): - """Test that timer raises error if it is stopped before started""" + """Test that timer raises error if it is stopped before started.""" t = Timer(text=TIME_MESSAGE) with pytest.raises(TimerError): t.stop() def test_access_timer_object_in_context(capsys): - """Test that we can access the timer object inside a context""" + """Test that we can access the timer object inside a context.""" with Timer(text=TIME_MESSAGE) as t: assert isinstance(t, Timer) assert t.text.startswith(TIME_PREFIX) @@ -100,7 +121,7 @@ def test_access_timer_object_in_context(capsys): def test_custom_logger(): - """Test that we can use a custom logger""" + """Test that we can use a custom logger.""" logger = CustomLogger() with Timer(text=TIME_MESSAGE, logger=logger): waste_time() @@ -108,7 +129,7 @@ def test_custom_logger(): def test_timer_without_text(capsys): - """Test that timer with logger=None does not print anything""" + """Test that timer with logger=None does not print anything.""" with Timer(logger=None): waste_time() @@ -118,7 +139,7 @@ def test_timer_without_text(capsys): def test_accumulated_decorator(capsys): - """Test that decorated timer can accumulate""" + """Test that decorated timer can accumulate.""" accumulated_timewaste() accumulated_timewaste() @@ -131,7 +152,7 @@ def test_accumulated_decorator(capsys): def test_accumulated_context_manager(capsys): - """Test that context manager timer can accumulate""" + """Test that context manager timer can accumulate.""" t = Timer(name="accumulator", text=TIME_MESSAGE) with t: waste_time() @@ -147,7 +168,7 @@ def test_accumulated_context_manager(capsys): def test_accumulated_explicit_timer(capsys): - """Test that explicit timer can accumulate""" + """Test that explicit timer can accumulate.""" t = Timer(name="accumulated_explicit_timer", text=TIME_MESSAGE) total = 0 t.start() @@ -167,7 +188,7 @@ def test_accumulated_explicit_timer(capsys): def test_error_if_restarting_running_timer(): - """Test that restarting a running timer raises an error""" + """Test that restarting a running timer raises an error.""" t = Timer(text=TIME_MESSAGE) t.start() with pytest.raises(TimerError): @@ -175,13 +196,13 @@ def test_error_if_restarting_running_timer(): def test_last_starts_as_nan(): - """Test that .last attribute is initialized as nan""" + """Test that .last attribute is initialized as nan.""" t = Timer() assert math.isnan(t.last) def test_timer_sets_last(): - """Test that .last attribute is properly set""" + """Test that .last attribute is properly set.""" with Timer() as t: time.sleep(0.02) @@ -189,46 +210,50 @@ def test_timer_sets_last(): def test_using_name_in_text_without_explicit_timer(capsys): - """Test that the name of the timer can be referenced in the text""" + """Test that the name of the timer can be referenced in the text.""" name = "NamedTimer" with Timer(name=name, text="{name}: {:.2f}"): waste_time() stdout, stderr = capsys.readouterr() assert re.match(f"{name}: " + r"0\.\d{2}", stdout) + assert stderr == "" def test_using_name_in_text_with_explicit_timer(capsys): - """Test that the name of the timer and the seconds attribute can be referenced in the text""" + """Test that timer name and seconds attribute can be referenced in the text.""" name = "NamedTimer" with Timer(name=name, text="{name}: {seconds:.2f}"): waste_time() stdout, stderr = capsys.readouterr() assert re.match(f"{name}: " + r"0\.\d{2}", stdout.strip()) + assert stderr == "" def test_using_minutes_attribute_in_text(capsys): - """Test that timer can report its duration in minutes""" + """Test that timer can report its duration in minutes.""" with Timer(text="{minutes:.1f} minutes"): waste_time() stdout, stderr = capsys.readouterr() assert stdout.strip() == "0.0 minutes" + assert stderr == "" def test_using_milliseconds_attribute_in_text(capsys): - """Test that timer can report its duration in milliseconds""" + """Test that timer can report its duration in milliseconds.""" with Timer(text="{milliseconds:.0f} {seconds:.3f}"): waste_time() stdout, stderr = capsys.readouterr() milliseconds, _, seconds = stdout.partition(" ") assert int(milliseconds) == round(float(seconds) * 1000) + assert stderr == "" def test_text_formatting_function(capsys): - """Test that text can be formatted by a separate function""" + """Test that text can be formatted by a separate function.""" def format_text(seconds): """Function that returns a formatted text""" @@ -243,10 +268,10 @@ def format_text(seconds): def test_text_formatting_class(capsys): - """Test that text can be formatted by a separate class""" + """Test that text can be formatted by a separate class.""" class TextFormatter: - """Class that behaves like a formatted text""" + """Class that behaves like a formatted text.""" def __init__(self, seconds): """Initialize with number of seconds""" @@ -263,20 +288,9 @@ def __str__(self): assert stdout.strip() == "Class: 1" assert not stderr.strip() - def format_text(seconds): - """Callable that returns a formatted text""" - return f"Callable: {seconds + 1:.0f}" - - with Timer(text=format_text): - waste_time() - - stdout, stderr = capsys.readouterr() - assert stdout.strip() == "Callable: 1" - assert not stderr.strip() - def test_timers_cleared(): - """Test that timers can be cleared""" + """Test that timers can be cleared.""" with Timer(name="timer_to_be_cleared"): waste_time() @@ -286,7 +300,7 @@ def test_timers_cleared(): def test_running_cleared_timers(): - """Test that timers can still be run after they're cleared""" + """Test that timers can still be run after they're cleared.""" t = Timer(name="timer_to_be_cleared") Timer.timers.clear() @@ -299,7 +313,7 @@ def test_running_cleared_timers(): def test_timers_stats(): - """Test that we can get basic statistics from timers""" + """Test that we can get basic statistics from timers.""" name = "timer_with_stats" t = Timer(name=name) for num in range(5, 10): @@ -315,7 +329,7 @@ def test_timers_stats(): def test_stats_missing_timers(): - """Test that getting statistics from non-existent timers raises exception""" + """Test that getting statistics from non-existent timers raises exception.""" with pytest.raises(KeyError): Timer.timers.count("non_existent_timer") @@ -324,6 +338,102 @@ def test_stats_missing_timers(): def test_setting_timers_exception(): - """Test that setting .timers items raises exception""" + """Test that setting .timers items raises exception.""" with pytest.raises(TypeError): Timer.timers["set_timer"] = 1.23 + + +def test_timer_as_decorator_with_initial_text_true(capsys): + """Test that decorated function prints at start with default initial text.""" + decorated_timewaste_initial_text_true() + + stdout, stderr = capsys.readouterr() + assert RE_TIME_MESSAGE_INITIAL_TEXT_TRUE.match(stdout) + assert stdout.count("\n") == 2 + assert stderr == "" + + +def test_timer_as_context_manager_with_initial_text_true(capsys): + """Test that timed context prints at start with default initial text.""" + with Timer(text=TIME_MESSAGE, initial_text=True): + waste_time() + + stdout, stderr = capsys.readouterr() + assert RE_TIME_MESSAGE_INITIAL_TEXT_TRUE.match(stdout) + assert stdout.count("\n") == 2 + assert stderr == "" + + +def test_explicit_timer_with_initial_text_true(capsys): + """Test that timed section prints at start with default initial text.""" + t = Timer(text=TIME_MESSAGE, initial_text=True) + t.start() + waste_time() + t.stop() + + stdout, stderr = capsys.readouterr() + assert RE_TIME_MESSAGE_INITIAL_TEXT_TRUE.match(stdout) + assert stdout.count("\n") == 2 + assert stderr == "" + + +def test_timer_as_decorator_with_initial_text_custom(capsys): + """Test that decorated function prints at start with custom initial text.""" + decorated_timewaste_initial_text_custom() + + stdout, stderr = capsys.readouterr() + assert RE_TIME_MESSAGE_INITIAL_TEXT_CUSTOM.match(stdout) + assert stdout.count("\n") == 2 + assert stderr == "" + + +def test_timer_as_context_manager_with_initial_text_custom(capsys): + """Test that timed context prints at start with custom initial text.""" + with Timer(text=TIME_MESSAGE, initial_text="Starting the party"): + waste_time() + + stdout, stderr = capsys.readouterr() + assert RE_TIME_MESSAGE_INITIAL_TEXT_CUSTOM.match(stdout) + assert stdout.count("\n") == 2 + assert stderr == "" + + +def test_explicit_timer_with_initial_text_custom(capsys): + """Test that timed section prints at start with custom initial text.""" + t = Timer(text=TIME_MESSAGE, initial_text="Starting the party") + t.start() + waste_time() + t.stop() + + stdout, stderr = capsys.readouterr() + assert RE_TIME_MESSAGE_INITIAL_TEXT_CUSTOM.match(stdout) + assert stdout.count("\n") == 2 + assert stderr == "" + + +def test_explicit_timer_with_initial_text_true_with_name(capsys): + """Test with default initial text referencing timer name.""" + t = Timer(name="named", text=TIME_MESSAGE, initial_text=True) + t.start() + waste_time() + t.stop() + + stdout, stderr = capsys.readouterr() + assert re.match( + f"Timer named started\n{TIME_PREFIX}" + r" 0\.\d{4} seconds", stdout + ) + assert stdout.count("\n") == 2 + assert stderr == "" + + +def test_explicit_timer_with_initial_text_with_name(capsys): + """Test with custom initial text referencing timer name.""" + t = Timer(name="the party", text=TIME_MESSAGE, initial_text="Starting {name}") + t.start() + waste_time() + t.stop() + + stdout, stderr = capsys.readouterr() + assert RE_TIME_MESSAGE_INITIAL_TEXT_CUSTOM.match(stdout) + assert stdout.count("\n") == 2 + assert stderr == ""