From 04d8b8750b98bf23449cdba9eb63cb5e31340ab4 Mon Sep 17 00:00:00 2001 From: HH-MWB <50187675+HH-MWB@users.noreply.github.com> Date: Mon, 9 Mar 2026 19:13:41 -0400 Subject: [PATCH 1/3] fix: invoke on_start before recording start timestamps --- timerun.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/timerun.py b/timerun.py index 41e98f7..976982d 100644 --- a/timerun.py +++ b/timerun.py @@ -202,16 +202,16 @@ def __enter__(self) -> Measurement: # Create measurement with a deep copy of timer metadata. measurement = Measurement(metadata=deepcopy(self._metadata)) + # Notify caller timing started (wall_time/cpu_time still None). + if self._on_start is not None: + self._on_start(measurement) + # Ensure thread-local stack exists and record start timestamps. self._local.stack = getattr(self._local, "stack", deque()) self._local.stack.append( (measurement, perf_counter_ns(), process_time_ns()), ) - # Notify caller timing started (wall_time/cpu_time still None). - if self._on_start is not None: - self._on_start(measurement) - return measurement def __exit__( From bf716ed16c7613c2a00a8bbf9a19353e97dc4ee6 Mon Sep 17 00:00:00 2001 From: HH-MWB <50187675+HH-MWB@users.noreply.github.com> Date: Mon, 9 Mar 2026 21:38:50 -0400 Subject: [PATCH 2/3] refactor: reword block-timing CPU-bound scenario and simplify test steps --- CONTRIBUTING.md | 3 +- features/block_timing.feature | 5 +- features/steps/block_timing_steps.py | 85 +++++++++---------------- features/steps/common_steps.py | 69 +++++++++++++++----- features/steps/function_timing_steps.py | 35 +++++----- features/steps/measurement_steps.py | 4 +- features/steps/utils.py | 50 --------------- 7 files changed, 106 insertions(+), 145 deletions(-) delete mode 100644 features/steps/utils.py diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index 9c84051..fc7ba91 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -112,7 +112,6 @@ timerun/ │ ├── environment.py # Optional: hooks (before/after scenario, etc.) │ └── steps/ # Step definitions (flat; all .py files loaded) │ ├── __init__.py -│ ├── utils.py # Shared constants and helpers (no step decorators) │ ├── common_steps.py # Shared steps used by multiple features │ └── *_steps.py # Feature-specific step files ├── pyproject.toml # Project metadata and config @@ -128,7 +127,7 @@ timerun/ ``` - **`timerun.py`** — The only library module; keep it a single file by design. -- **`features/`** — All executable specs; no separate unit test directory. Layout follows [behave](https://behave.readthedocs.io/) convention: step definitions live under `features/steps/` (flat; subdirectories are not searched). Shared logic lives in `features/steps/utils.py`; shared steps (e.g. metadata, wall-time buffer, exception propagation) in `common_steps.py`. Run behave from the project root so `from features.steps.utils import ...` works. +- **`features/`** — All executable specs; no separate unit test directory. Layout follows [behave](https://behave.readthedocs.io/) convention: step definitions live under `features/steps/` (flat; subdirectories are not searched). Shared steps (e.g. metadata, wall-time buffer, exception propagation) live in `common_steps.py`. Run behave from the project root. ## Pull Request Process diff --git a/features/block_timing.feature b/features/block_timing.feature index d887d42..085d5df 100644 --- a/features/block_timing.feature +++ b/features/block_timing.feature @@ -18,12 +18,11 @@ Feature: Block timing Then the measurement's wall time duration is within the configured buffer of 10,000,000 nanoseconds And the measurement's CPU time duration is within the configured buffer of 0 nanoseconds - Scenario: CPU-bound block with `with` yields wall and CPU time close together + Scenario: CPU-bound block with `with` yields meaningful wall and CPU time Given a CPU-bound operation that runs for around 10,000,000 nanoseconds When I measure the operation using `with` - Then the measurement's wall time duration is within the configured buffer of 10,000,000 nanoseconds + Then the measurement's wall time duration is at least 10,000,000 nanoseconds And the measurement's CPU time duration is within the configured buffer of 10,000,000 nanoseconds - And the measurement's CPU time is close to wall time # --- One Timer, multiple blocks or threads --- diff --git a/features/steps/block_timing_steps.py b/features/steps/block_timing_steps.py index cbbd03d..3b52451 100644 --- a/features/steps/block_timing_steps.py +++ b/features/steps/block_timing_steps.py @@ -3,19 +3,13 @@ from __future__ import annotations import asyncio +import time from concurrent.futures import ThreadPoolExecutor from typing import TYPE_CHECKING from behave import given, then, when import timerun -from features.steps.utils import ( - BUFFER_NS, - assert_metadata_key_equals, - assert_wall_time_within_buffer, - sleep_wall_at_least, - spin_wall_at_least, -) if TYPE_CHECKING: from behave.runner import Context @@ -72,11 +66,13 @@ def step_given_callback_records_invocations( callback_kind: str, ) -> None: """Store list and callback that records the measurement passed to it.""" + # List and callback that appends each measurement. invocations: list[timerun.Measurement] = [] def record_invocation(m: timerun.Measurement) -> None: invocations.append(m) + # Store on context for When/Then. setattr(context, f"{callback_kind}_invocations", invocations) setattr(context, f"{callback_kind}_callback", record_invocation) @@ -88,10 +84,16 @@ def record_invocation(m: timerun.Measurement) -> None: def step_measure_operation_using_with(context: Context) -> None: """Measure with Timer(); sleep or spin per operation_kind.""" with timerun.Timer() as context.measurement: - if getattr(context, "operation_kind", "blocking") == "CPU-bound": - spin_wall_at_least(context.operation_duration_ns) + if context.operation_kind == "CPU-bound": + # Spin until duration elapsed. + start = time.process_time_ns() + while ( + time.process_time_ns() - start < context.operation_duration_ns + ): + pass else: - sleep_wall_at_least(context.operation_duration_ns) + # Sleep for duration. + time.sleep(context.operation_duration_ns / 1e9) @when("I measure the async operation using `async with`") @@ -121,7 +123,7 @@ def step_measure_blocks_from_threads( # Worker: enter timer, sleep, return measurement. def run() -> timerun.Measurement: with cm as m: - sleep_wall_at_least(context.thread_sleep_ns) + time.sleep(context.thread_sleep_ns / 1e9) return m # Run thread_count workers and collect measurements. @@ -135,11 +137,13 @@ def step_measure_two_sequential_blocks(context: Context) -> None: """Measure two sequential blocks.""" cm = timerun.Timer() + # First block. with cm as context.first_measurement: - sleep_wall_at_least(context.first_block_ns) + time.sleep(context.first_block_ns / 1e9) + # Second block. with cm as context.second_measurement: - sleep_wall_at_least(context.second_block_ns) + time.sleep(context.second_block_ns / 1e9) @when("I measure nested blocks with the same Timer instance") @@ -148,10 +152,10 @@ def step_measure_nested_blocks(context: Context) -> None: cm = timerun.Timer() with cm as context.outer_measurement: - sleep_wall_at_least(context.outer_block_ns) + time.sleep(context.outer_block_ns / 1e9) with cm as context.inner_measurement: - sleep_wall_at_least(context.inner_block_ns) + time.sleep(context.inner_block_ns / 1e9) @when("I measure a code block with that metadata") @@ -216,36 +220,22 @@ def step_exit_without_enter(context: Context) -> None: # --- Then --- -@then("the measurement's CPU time is close to wall time") -def step_cpu_close_to_wall(context: Context) -> None: - """Assert CPU close to wall time.""" - # Required context validation. - assert context.measurement.wall_time is not None - assert context.measurement.cpu_time is not None - - # Duration in [wall - BUFFER_NS, wall]. - wall = context.measurement.wall_time.duration - cpu = context.measurement.cpu_time.duration - min_cpu = max(0, wall - BUFFER_NS) - assert min_cpu <= cpu <= wall, ( - f"CPU {cpu} not in [wall-BUFFER_NS, wall] = [{min_cpu}, {wall}]" - ) - - @then( - "the {which} measurement's wall time duration is within the configured " - "buffer of {expected_ns:n} nanoseconds", + "the measurement's wall time duration is at least {expected_ns:n} " + "nanoseconds", ) -def step_which_measurement_wall_within_buffer( +def step_measurement_wall_time_at_least( context: Context, - which: str, expected_ns: int, ) -> None: - """Assert which measurement wall time in buffer.""" - assert_wall_time_within_buffer( - getattr(context, f"{which}_measurement"), - expected_ns, - BUFFER_NS, + """Assert wall time >= expected; used for CPU-bound scenario.""" + # Require wall_time and get duration. + assert context.measurement.wall_time is not None + duration = context.measurement.wall_time.duration + + # Duration must be at least expected. + assert duration >= expected_ns, ( + f"wall time {duration} < expected {expected_ns}" ) @@ -265,21 +255,6 @@ def step_outer_wall_at_least_inner(context: Context) -> None: assert outer_d >= inner_d, f"outer {outer_d} < inner {inner_d}" -@then('the {which} measurement\'s metadata key "{key}" is "{value}"') -def step_measurement_metadata_key( - context: Context, - which: str, - key: str, - value: str, -) -> None: - """Assert which measurement metadata[key] is value.""" - assert_metadata_key_equals( - getattr(context, f"{which}_measurement"), - key, - value, - ) - - @then('the second measurement\'s metadata does not contain key "{key}"') def step_second_measurement_metadata_no_key( context: Context, diff --git a/features/steps/common_steps.py b/features/steps/common_steps.py index 6c0055d..f73350c 100644 --- a/features/steps/common_steps.py +++ b/features/steps/common_steps.py @@ -1,7 +1,8 @@ -"""Shared step definitions used by multiple features. +"""Step definitions shared by more than one feature. -Steps here use consistent wording and semantics across features -(exception assertions, error messages, measurement metadata, wall time buffer). +Rule: a step belongs here only if its Gherkin text is used in multiple feature +files (e.g. block_timing.feature and function_timing.feature). Steps used by +a single feature live in that feature's step file (e.g. block_timing_steps.py). """ from __future__ import annotations @@ -11,16 +12,21 @@ from behave import given, then -from features.steps.utils import ( - BUFFER_NS, - CPU_LOWER_SLACK_NS, - assert_metadata_key_equals, - assert_wall_time_within_buffer, -) - if TYPE_CHECKING: from behave.runner import Context +# Buffer: expected_ns <= duration <= expected_ns + BUFFER_NS (10 ms). +BUFFER_NS = 10_000_000 + +# --- Helpers --- + + +def _measurement(context: Context, which: str | None) -> object: + """Resolve measurement from context.""" + if which is None: + return context.measurement + return getattr(context, f"{which}_measurement") + # --- Given --- @@ -49,14 +55,20 @@ def step_exception_raised(context: Context, exception_type: str) -> None: @then('the error message is "{message}"') def step_error_message_is(context: Context, message: str) -> None: """Assert exception message.""" + # Required: an exception was stored by the When step. assert hasattr(context, "exception"), "Expected an exception to be raised" + + # Message must match. assert str(context.exception) == message @then("an exception was propagated to the caller") def step_exception_propagated(context: Context) -> None: """Assert ValueError was caught.""" + # Required: an exception was stored. assert hasattr(context, "exception") + + # Must be ValueError. assert isinstance(context.exception, ValueError) @@ -64,9 +76,28 @@ def step_exception_propagated(context: Context) -> None: "the measurement's wall time duration is within the configured buffer of " "{expected_ns:n} nanoseconds", ) -def step_wall_time_within_buffer(context: Context, expected_ns: int) -> None: - """Assert wall time in buffer.""" - assert_wall_time_within_buffer(context.measurement, expected_ns, BUFFER_NS) +@then( + "the {which} measurement's wall time duration is within the configured " + "buffer of {expected_ns:n} nanoseconds", +) +def step_wall_time_within_buffer( + context: Context, + expected_ns: int, + which: str | None = None, +) -> None: + """Assert wall time in buffer (default or first/second/outer/inner).""" + measurement = _measurement(context, which) + + # Resolve duration and buffer bound. + assert measurement.wall_time is not None + duration = measurement.wall_time.duration + max_ns = expected_ns + BUFFER_NS + + # Duration must lie in [expected_ns, expected_ns + buffer]. + assert expected_ns <= duration <= max_ns, ( + f"wall time {duration} not in [{expected_ns}, {max_ns}] " + f"(buffer={BUFFER_NS})" + ) @then( @@ -75,9 +106,12 @@ def step_wall_time_within_buffer(context: Context, expected_ns: int) -> None: ) def step_cpu_time_within_buffer(context: Context, expected_ns: int) -> None: """Assert CPU time in buffer.""" + # Resolve duration and buffer bounds. assert context.measurement.cpu_time is not None + + # Duration must lie in [min_ns, max_ns]. duration = context.measurement.cpu_time.duration - min_ns = max(0, expected_ns - CPU_LOWER_SLACK_NS) + min_ns = max(0, expected_ns - 1_000_000) max_ns = expected_ns + BUFFER_NS assert min_ns <= duration <= max_ns, ( f"CPU time {duration} not in [{min_ns}, {max_ns}] (buffer={BUFFER_NS})" @@ -85,10 +119,13 @@ def step_cpu_time_within_buffer(context: Context, expected_ns: int) -> None: @then('the measurement\'s metadata key "{key}" is "{value}"') +@then('the {which} measurement\'s metadata key "{key}" is "{value}"') def step_measurement_metadata_key_is( context: Context, key: str, value: str, + which: str | None = None, ) -> None: - """Assert metadata[key] is value.""" - assert_metadata_key_equals(context.measurement, key, value) + """Assert metadata[key] is value (default or first/second/outer/inner).""" + measurement = _measurement(context, which) + assert measurement.metadata[key] == value diff --git a/features/steps/function_timing_steps.py b/features/steps/function_timing_steps.py index a5d6605..52fdc15 100644 --- a/features/steps/function_timing_steps.py +++ b/features/steps/function_timing_steps.py @@ -3,15 +3,13 @@ from __future__ import annotations import asyncio +import time from concurrent.futures import ThreadPoolExecutor from typing import TYPE_CHECKING from behave import given, then, when import timerun -from features.steps.utils import ( - sleep_wall_at_least, -) if TYPE_CHECKING: from behave.runner import Context @@ -63,7 +61,7 @@ def step_given_gen( def step_when_call_decorated_func(context: Context) -> None: """Decorate function with Timer(), run it.""" if context.func_kind == "async": - + # Define async function, run it, store function and measurement. @timerun.Timer() async def async_func() -> None: await asyncio.sleep(context.func_duration_ns / 1e9) @@ -72,10 +70,10 @@ async def async_func() -> None: context.decorated_function = async_func context.measurement = async_func.measurements[-1] else: - + # Define sync function, run it, store function and measurement. @timerun.Timer() def sync_func() -> None: - sleep_wall_at_least(context.func_duration_ns) + time.sleep(context.func_duration_ns / 1e9) sync_func() context.decorated_function = sync_func @@ -86,8 +84,9 @@ def sync_func() -> None: def step_when_consume_gen(context: Context) -> None: # noqa: C901 """Decorate generator with Timer(), consume fully.""" per_sleep = context.gen_duration_ns // context.gen_count - if context.gen_kind == "async": + if context.gen_kind == "async": + # Define async gen and runner; consume; store func and measurement. @timerun.Timer() async def async_gen() -> object: for i in range(context.gen_count): @@ -102,11 +101,11 @@ async def run() -> None: context.decorated_function = async_gen context.measurement = async_gen.measurements[-1] else: - + # Define sync generator; consume; store function and measurement. @timerun.Timer() def sync_gen() -> object: for i in range(context.gen_count): - sleep_wall_at_least(per_sleep) + time.sleep(per_sleep / 1e9) yield i for _ in sync_gen(): @@ -132,15 +131,18 @@ def f() -> None: def step_when_call_raising(context: Context) -> None: """Call raising function under Timer(); catch exception.""" + # Define raising function. @timerun.Timer() def raising() -> None: raise ValueError - # Call, catch exception for Then to assert; store function and measurement. + # Call and catch exception for Then to assert. try: raising() except ValueError as e: context.exception = e + + # Store function and measurement for Then. context.decorated_function = raising context.measurement = raising.measurements[-1] @@ -157,11 +159,12 @@ def step_when_call_three_times(context: Context, times: int) -> None: @timerun.Timer(maxlen=context.func_maxlen) def sync_func() -> None: - sleep_wall_at_least(context.func_duration_ns) + time.sleep(context.func_duration_ns / 1e9) - # Call times times; only last maxlen measurements kept. + # Call N times; only last maxlen measurements kept. for _ in range(times): sync_func() + context.decorated_function = sync_func @@ -173,17 +176,18 @@ def step_when_call_from_threads(context: Context, thread_count: int) -> None: @timerun.Timer() def sync_func() -> None: - sleep_wall_at_least(context.func_duration_ns) + time.sleep(context.func_duration_ns / 1e9) - # Worker: call the timed function once. def run() -> None: sync_func() - # Run thread_count workers concurrently; store function and count for Then. + # Run thread_count workers concurrently. with ThreadPoolExecutor(max_workers=thread_count) as ex: futures = [ex.submit(run) for _ in range(thread_count)] for f in futures: f.result() + + # Store for Then. context.decorated_function = sync_func context.thread_count = thread_count @@ -196,7 +200,6 @@ def run() -> None: def step_then_measurements_count(context: Context, n: int) -> None: """Assert measurements count is n.""" func = context.decorated_function - assert hasattr(func, "measurements") assert len(func.measurements) == n, ( f"expected {n} measurements, got {len(func.measurements)}" ) diff --git a/features/steps/measurement_steps.py b/features/steps/measurement_steps.py index a6e4298..11fe008 100644 --- a/features/steps/measurement_steps.py +++ b/features/steps/measurement_steps.py @@ -70,6 +70,4 @@ def step_measurement_time_duration( @then("the measurement's metadata is an empty dict") def step_measurement_metadata_empty_dict(context: Context) -> None: """Assert metadata is empty dict.""" - metadata = context.measurement.metadata - assert isinstance(metadata, dict) - assert not metadata + assert context.measurement.metadata == {} diff --git a/features/steps/utils.py b/features/steps/utils.py deleted file mode 100644 index 90f4aa9..0000000 --- a/features/steps/utils.py +++ /dev/null @@ -1,50 +0,0 @@ -"""Shared utilities for step definitions. - -Constants and helpers for block_timing_steps and function_timing_steps -to avoid duplication and keep assertions consistent. -""" - -import time - -# Buffer: expected_ns <= duration <= expected_ns + BUFFER_NS. -# Covers sleep/scheduling jitter so tests don't flake. -BUFFER_NS = 10_000_000 # 10 ms - -# CPU can be slightly below wall time (scheduling); allow 1 ms undershoot. -CPU_LOWER_SLACK_NS = 1_000_000 - - -def sleep_wall_at_least(nanoseconds: int) -> None: - """Sleep at least nanoseconds (wall).""" - time.sleep(nanoseconds / 1e9) - - -def spin_wall_at_least(nanoseconds: int) -> None: - """Busy-loop at least nanoseconds (wall).""" - start = time.perf_counter_ns() - while time.perf_counter_ns() - start < nanoseconds: - pass - - -def assert_wall_time_within_buffer( - measurement: object, - expected_ns: int, - buffer_ns: int = BUFFER_NS, -) -> None: - """Assert wall time in buffer.""" - assert measurement.wall_time is not None - duration = measurement.wall_time.duration - max_ns = expected_ns + buffer_ns - assert expected_ns <= duration <= max_ns, ( - f"wall time {duration} not in [{expected_ns}, {max_ns}] " - f"(buffer={buffer_ns})" - ) - - -def assert_metadata_key_equals( - measurement: object, - key: str, - value: str, -) -> None: - """Assert metadata[key] equals value.""" - assert measurement.metadata[key] == value From e08ef17c21883864ddd6c6540d800e8070355ea5 Mon Sep 17 00:00:00 2001 From: HH-MWB <50187675+HH-MWB@users.noreply.github.com> Date: Mon, 9 Mar 2026 22:01:03 -0400 Subject: [PATCH 3/3] docs: add prerequisites, update fork URL, and fix recipe wording --- CONTRIBUTING.md | 4 +++- docs/recipes/analyze-results.md | 2 +- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index fc7ba91..fee5922 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -32,6 +32,8 @@ This project adheres to the [Contributor Covenant Code of Conduct](https://www.c ### Prerequisites - **Python 3.10+** +- **pip** (usually bundled with Python) +- **Make** - **Git** ### One-time setup @@ -39,7 +41,7 @@ This project adheres to the [Contributor Covenant Code of Conduct](https://www.c 1. Fork the repository on GitHub, then clone your fork and go into the project directory: ```bash - git clone https://github.com/HH-MWB/timerun.git + git clone https://github.com/YOUR_USERNAME/timerun.git cd timerun ``` diff --git a/docs/recipes/analyze-results.md b/docs/recipes/analyze-results.md index 76e65e0..46c1525 100644 --- a/docs/recipes/analyze-results.md +++ b/docs/recipes/analyze-results.md @@ -8,7 +8,7 @@ Two common ways to get a list of measurements: -1. **From a decorated function** — use the timer’s `measurements` deque when you run the same function many times (e.g. benchmarks or repeated calls): +1. **From a decorated function** — use the wrapped callable’s `measurements` deque when you run the same function many times (e.g. benchmarks or repeated calls): ```python from timerun import Timer