From 075005d3fe266b39e13ddea682290f85a2fc9cef Mon Sep 17 00:00:00 2001 From: hmasdev Date: Sun, 16 Nov 2025 00:56:55 +0900 Subject: [PATCH 1/5] Add stopwatch decorator and corresponding tests for execution time logging --- simple_typing_application/utils/stopwatch.py | 85 ++++++++++++++++++++ tests/utils/test_stopwatch.py | 71 ++++++++++++++++ 2 files changed, 156 insertions(+) create mode 100644 simple_typing_application/utils/stopwatch.py create mode 100644 tests/utils/test_stopwatch.py diff --git a/simple_typing_application/utils/stopwatch.py b/simple_typing_application/utils/stopwatch.py new file mode 100644 index 0000000..7b225f8 --- /dev/null +++ b/simple_typing_application/utils/stopwatch.py @@ -0,0 +1,85 @@ +import logging +import time +from functools import wraps, partial +from logging import Logger, getLogger +from typing import Callable, TypeVar, ParamSpec + +T = TypeVar("T") +P = ParamSpec("P") + +logger: Logger = getLogger(__name__) + + +def stopwatch_deco( + func: Callable[P, T] | None = None, + *, + level: int = logging.INFO, + prefix: str | None = None, + postfix: str = "", + logger: Logger = logger, +) -> Callable[P, T]: + """Decorator to measure the execution time of a function. + + Args: + func (Callable[P, T], optional): function to be decorated. Defaults to None. + *, + logger (Logger, optional): logger. Defaults to logger. + + Returns: + Callable[P, T]: decorated function. + + Note: + If func is None, return a decorator. Otherwise, return a wrapper. + """ # noqa + + # validation + if level not in { + logging.DEBUG, + logging.INFO, + logging.WARNING, + logging.ERROR, + logging.CRITICAL, + }: + raise ValueError( + f"Invalid log level: {level}. " + "Must be one of logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL.", # noqa + ) + + # if func is None, return a decorator + if func is None: + return partial( + stopwatch_deco, + logger=logger, + ) + + # preparation + if hasattr(func, "__name__"): + funcname = func.__name__ + else: + funcname = str(func) + + if prefix is None: + prefix = f"Execution time of {funcname}()" + + log_msg_fmt: str = f"{prefix}: {{elapsed_time:.6f}} seconds{postfix}" + + log_func = { + logging.DEBUG: logger.debug, + logging.INFO: logger.info, + logging.WARNING: logger.warning, + logging.ERROR: logger.error, + logging.CRITICAL: logger.critical, + }[level] + + # if func is not None, return a wrapper + @wraps(func) + def wrapped(*args: P.args, **kwargs: P.kwargs) -> T: + start_time = time.perf_counter() + try: + result = func(*args, **kwargs) + finally: + end_time = time.perf_counter() + log_func(log_msg_fmt.format(elapsed_time=end_time - start_time)) + return result + + return wrapped diff --git a/tests/utils/test_stopwatch.py b/tests/utils/test_stopwatch.py new file mode 100644 index 0000000..b27b433 --- /dev/null +++ b/tests/utils/test_stopwatch.py @@ -0,0 +1,71 @@ +import logging +import re + +import pytest + +from simple_typing_application.utils.stopwatch import stopwatch_deco + + +def _get_latest_record(caplog): + assert caplog.records, "Expected logger to emit at least one record" + return caplog.records[-1] + + +def test_stopwatch_logs_with_default_prefix(caplog): + """Decorator without args should log INFO with default prefix.""" + + caplog.set_level(logging.INFO, logger="simple_typing_application.utils.stopwatch") + + @stopwatch_deco + def add(a: int, b: int) -> int: + return a + b + + assert add(1, 2) == 3 + record = _get_latest_record(caplog) + assert record.levelno == logging.INFO + assert record.message.startswith("Execution time of add()") + assert record.message.endswith(" seconds") + assert re.match(r"Execution time of add\(\): \d+\.\d{6} seconds", record.message) + + +def test_stopwatch_logs_when_called_with_parentheses(caplog): + """Calling stopwatch_deco() triggers the func is None branch and still logs.""" + + caplog.set_level(logging.INFO, logger="simple_typing_application.utils.stopwatch") + + @stopwatch_deco() + def greet() -> str: + return "hello" + + assert greet() == "hello" + record = _get_latest_record(caplog) + assert "Execution time of greet()" in record.message + + +def test_stopwatch_custom_prefix_postfix_and_level(caplog): + """Manually decorating allows passing custom prefix/postfix/level and logger.""" + + custom_logger = logging.getLogger("tests.utils.stopwatch.custom") + caplog.set_level(logging.ERROR, logger=custom_logger.name) + + def sample() -> None: + return None + + wrapped = stopwatch_deco( + sample, + prefix="Run sample", + postfix=" !!!", + level=logging.ERROR, + logger=custom_logger, + ) + + wrapped() + record = _get_latest_record(caplog) + assert record.levelno == logging.ERROR + assert record.message.startswith("Run sample: ") + assert record.message.endswith(" seconds !!!") + + +def test_stopwatch_invalid_level_raises_value_error(): + with pytest.raises(ValueError): + stopwatch_deco(level=123) From 7fd353aeab325041e98e46c12907db4f7e25c40e Mon Sep 17 00:00:00 2001 From: hmasdev Date: Sun, 16 Nov 2025 01:22:56 +0900 Subject: [PATCH 2/5] Refactor stopwatch to use context manager and update tests for new functionality --- simple_typing_application/utils/stopwatch.py | 98 +++++++++++------ tests/utils/test_stopwatch.py | 107 ++++++++++++------- 2 files changed, 135 insertions(+), 70 deletions(-) diff --git a/simple_typing_application/utils/stopwatch.py b/simple_typing_application/utils/stopwatch.py index 7b225f8..2dee7f4 100644 --- a/simple_typing_application/utils/stopwatch.py +++ b/simple_typing_application/utils/stopwatch.py @@ -1,8 +1,9 @@ import logging import time +from contextlib import contextmanager from functools import wraps, partial from logging import Logger, getLogger -from typing import Callable, TypeVar, ParamSpec +from typing import Callable, Generator, TypeVar, ParamSpec T = TypeVar("T") P = ParamSpec("P") @@ -10,26 +11,24 @@ logger: Logger = getLogger(__name__) -def stopwatch_deco( - func: Callable[P, T] | None = None, - *, +@contextmanager +def stopwatch( level: int = logging.INFO, prefix: str | None = None, postfix: str = "", logger: Logger = logger, -) -> Callable[P, T]: - """Decorator to measure the execution time of a function. +) -> Generator[None, None, None]: + """Context manager to measure the execution time of a code block. Args: - func (Callable[P, T], optional): function to be decorated. Defaults to None. - *, + level (int, optional): log level. Defaults to logging.INFO. + Must be one of logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL. + prefix (str | None, optional): prefix of the log message. Defaults to None. + postfix (str, optional): postfix of the log message. Defaults to "". logger (Logger, optional): logger. Defaults to logger. - Returns: - Callable[P, T]: decorated function. - - Note: - If func is None, return a decorator. Otherwise, return a wrapper. + Yields: + None: None """ # noqa # validation @@ -45,21 +44,9 @@ def stopwatch_deco( "Must be one of logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL.", # noqa ) - # if func is None, return a decorator - if func is None: - return partial( - stopwatch_deco, - logger=logger, - ) - # preparation - if hasattr(func, "__name__"): - funcname = func.__name__ - else: - funcname = str(func) - if prefix is None: - prefix = f"Execution time of {funcname}()" + prefix = "Execution time" log_msg_fmt: str = f"{prefix}: {{elapsed_time:.6f}} seconds{postfix}" @@ -71,15 +58,64 @@ def stopwatch_deco( logging.CRITICAL: logger.critical, }[level] + # execution + start_time = time.perf_counter() + try: + yield + finally: + end_time = time.perf_counter() + log_func(log_msg_fmt.format(elapsed_time=end_time - start_time)) + + +def stopwatch_deco( + func: Callable[P, T] | None = None, + *, + level: int = logging.INFO, + prefix: str | None = None, + postfix: str = "", + logger: Logger = logger, +) -> Callable[P, T]: + """Decorator to measure the execution time of a function. + + Args: + func (Callable[P, T], optional): function to be decorated. Defaults to None. + *, + level (int, optional): log level. Defaults to logging.INFO. + Must be one of logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL. + prefix (str | None, optional): prefix of the log message. Defaults to None. + postfix (str, optional): postfix of the log message. Defaults to "". + logger (Logger, optional): logger. Defaults to logger. + + Returns: + Callable[P, T]: decorated function. + + Note: + If func is None, return a decorator. Otherwise, return a wrapper. + """ # noqa + + # if func is None, return a decorator + if func is None: + return partial( + stopwatch_deco, + level=level, + prefix=prefix, + postfix=postfix, + logger=logger, + ) + + if prefix is None: + prefix = f"Execution time of {getattr(func, '__name__', str(func))}" + # if func is not None, return a wrapper @wraps(func) def wrapped(*args: P.args, **kwargs: P.kwargs) -> T: - start_time = time.perf_counter() - try: + with stopwatch( + level=level, + prefix=prefix, + postfix=postfix, + logger=logger, + ): result = func(*args, **kwargs) - finally: - end_time = time.perf_counter() - log_func(log_msg_fmt.format(elapsed_time=end_time - start_time)) return result return wrapped diff --git a/tests/utils/test_stopwatch.py b/tests/utils/test_stopwatch.py index b27b433..1225879 100644 --- a/tests/utils/test_stopwatch.py +++ b/tests/utils/test_stopwatch.py @@ -3,69 +3,98 @@ import pytest -from simple_typing_application.utils.stopwatch import stopwatch_deco +from simple_typing_application.utils.stopwatch import stopwatch, stopwatch_deco -def _get_latest_record(caplog): - assert caplog.records, "Expected logger to emit at least one record" - return caplog.records[-1] +LOGGER_NAME = "simple_typing_application.utils.stopwatch" -def test_stopwatch_logs_with_default_prefix(caplog): - """Decorator without args should log INFO with default prefix.""" +def _latest_record(caplog): + assert caplog.records, "Expected stopwatch to emit a log record" + return caplog.records[-1] - caplog.set_level(logging.INFO, logger="simple_typing_application.utils.stopwatch") - @stopwatch_deco - def add(a: int, b: int) -> int: - return a + b +def test_stopwatch_context_manager_logs_default_prefix(caplog): + caplog.set_level(logging.INFO, logger=LOGGER_NAME) - assert add(1, 2) == 3 - record = _get_latest_record(caplog) + with stopwatch(): + sum(range(5)) + + record = _latest_record(caplog) assert record.levelno == logging.INFO - assert record.message.startswith("Execution time of add()") - assert record.message.endswith(" seconds") - assert re.match(r"Execution time of add\(\): \d+\.\d{6} seconds", record.message) + assert re.match(r"Execution time: \d+\.\d{6} seconds", record.message) -def test_stopwatch_logs_when_called_with_parentheses(caplog): - """Calling stopwatch_deco() triggers the func is None branch and still logs.""" +def test_stopwatch_context_manager_custom_prefix_postfix_and_level(caplog): + custom_logger = logging.getLogger("tests.utils.stopwatch.ctx") + caplog.set_level(logging.WARNING, logger=custom_logger.name) - caplog.set_level(logging.INFO, logger="simple_typing_application.utils.stopwatch") + with stopwatch( + level=logging.WARNING, + prefix="Block", + postfix=" !!!", + logger=custom_logger, + ): + sum(range(10)) - @stopwatch_deco() - def greet() -> str: - return "hello" + record = _latest_record(caplog) + assert record.levelno == logging.WARNING + assert record.message.startswith("Block: ") + assert record.message.endswith(" seconds !!!") - assert greet() == "hello" - record = _get_latest_record(caplog) - assert "Execution time of greet()" in record.message +def test_stopwatch_context_manager_invalid_level_raises_value_error(): + with pytest.raises(ValueError): + with stopwatch(level=123): + pass -def test_stopwatch_custom_prefix_postfix_and_level(caplog): - """Manually decorating allows passing custom prefix/postfix/level and logger.""" - custom_logger = logging.getLogger("tests.utils.stopwatch.custom") - caplog.set_level(logging.ERROR, logger=custom_logger.name) +def test_stopwatch_decorator_without_parentheses_uses_func_name_in_prefix(caplog): + caplog.set_level(logging.INFO, logger=LOGGER_NAME) - def sample() -> None: - return None + @stopwatch_deco + def greet(name: str) -> str: + return f"hello {name}" + + assert greet("world") == "hello world" + record = _latest_record(caplog) + assert record.levelno == logging.INFO + assert re.match(r"Execution time of greet: \d+\.\d{6} seconds", record.message) + + +def test_stopwatch_decorator_called_with_parentheses(caplog): + caplog.set_level(logging.INFO, logger=LOGGER_NAME) + + @stopwatch_deco() + def add(a: int, b: int) -> int: + return a + b - wrapped = stopwatch_deco( - sample, - prefix="Run sample", + assert add(1, 2) == 3 + record = _latest_record(caplog) + assert re.match(r"Execution time of add: \d+\.\d{6} seconds", record.message) + + +def test_stopwatch_decorator_custom_prefix_and_invalid_level(caplog): + caplog.set_level(logging.ERROR, logger=LOGGER_NAME) + + @stopwatch_deco( + prefix="Manual", postfix=" !!!", level=logging.ERROR, - logger=custom_logger, ) + def work() -> None: + return None + + work() - wrapped() - record = _get_latest_record(caplog) + record = _latest_record(caplog) assert record.levelno == logging.ERROR - assert record.message.startswith("Run sample: ") + assert record.message.startswith("Manual: ") assert record.message.endswith(" seconds !!!") + @stopwatch_deco(level=123) + def broken(): + return None -def test_stopwatch_invalid_level_raises_value_error(): with pytest.raises(ValueError): - stopwatch_deco(level=123) + broken() From dfdc3de1ad94ad8afdec587591a3b1201e288f9f Mon Sep 17 00:00:00 2001 From: hmasdev Date: Sun, 16 Nov 2025 01:29:32 +0900 Subject: [PATCH 3/5] Add stopwatch context for OpenAI agent invocation logging --- .../sentence_generator/openai_sentence_generator.py | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/simple_typing_application/sentence_generator/openai_sentence_generator.py b/simple_typing_application/sentence_generator/openai_sentence_generator.py index 73b9d99..3a251e6 100644 --- a/simple_typing_application/sentence_generator/openai_sentence_generator.py +++ b/simple_typing_application/sentence_generator/openai_sentence_generator.py @@ -97,11 +97,12 @@ async def generate( "content": self._user_prompt, }, ] - self._logger.debug(f'agent input messages: {messages}') - ret: dict[str, Any] = await self._agent.ainvoke( - {"messages": messages}, # type: ignore - ) - self._logger.debug(f'agent response: {ret}') + self._logger.debug(f"agent input messages: {messages}") + with stopwatch(level=DEBUG, logger=self._logger, prefix="OpenAI agent invocation"): + ret: dict[str, Any] = await self._agent.ainvoke( + {"messages": messages}, + ) # type: ignore + self._logger.debug(f"agent response: {ret}") # store to memory output = cast(_OutputSchema, ret["structured_response"]) From eb6a927a294fd45d29f2a8755c329c0ed67e43cd Mon Sep 17 00:00:00 2001 From: hmasdev Date: Sun, 16 Nov 2025 01:32:02 +0900 Subject: [PATCH 4/5] Specify reasoning effort parameter for OpenAI agent based on model type --- .../sentence_generator/openai_sentence_generator.py | 7 ++----- 1 file changed, 2 insertions(+), 5 deletions(-) diff --git a/simple_typing_application/sentence_generator/openai_sentence_generator.py b/simple_typing_application/sentence_generator/openai_sentence_generator.py index 3a251e6..3cea03a 100644 --- a/simple_typing_application/sentence_generator/openai_sentence_generator.py +++ b/simple_typing_application/sentence_generator/openai_sentence_generator.py @@ -52,11 +52,8 @@ def __init__( model=model, temperature=temperature, max_retries=max_retry, - api_key=( - (lambda: openai_api_key) - if isinstance(openai_api_key, str) - else openai_api_key - ), + api_key=((lambda: openai_api_key) if isinstance(openai_api_key, str) else openai_api_key), + reasoning_effort="minimal" if model.startswith("gpt-5") else None, seed=seed, ) self._agent = create_agent( From 27bf5a4edd167ceb997c23bc1105a38e398f4212 Mon Sep 17 00:00:00 2001 From: hmasdev Date: Sun, 16 Nov 2025 01:41:27 +0900 Subject: [PATCH 5/5] Add DEBUG level logging import for enhanced logging capabilities --- .../sentence_generator/openai_sentence_generator.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/simple_typing_application/sentence_generator/openai_sentence_generator.py b/simple_typing_application/sentence_generator/openai_sentence_generator.py index 3cea03a..e110b33 100644 --- a/simple_typing_application/sentence_generator/openai_sentence_generator.py +++ b/simple_typing_application/sentence_generator/openai_sentence_generator.py @@ -1,6 +1,6 @@ from __future__ import annotations from datetime import datetime as dt -from logging import getLogger, Logger +from logging import DEBUG, Logger, getLogger from typing import Any, Callable, cast from langchain.agents import create_agent @@ -12,6 +12,7 @@ from .utils import split_hiraganas_alphabets_symbols, splitted_hiraganas_alphabets_symbols_to_typing_target # noqa from ..utils.japanese_string_utils import delete_space_between_hiraganas from ..utils.rerun import rerun_deco +from ..utils.stopwatch import stopwatch class _OutputSchema(BaseModel):