diff --git a/.github/ISSUE_TEMPLATE/bug_report.yml b/.github/ISSUE_TEMPLATE/bug_report.yml index e14b20e..6552b72 100644 --- a/.github/ISSUE_TEMPLATE/bug_report.yml +++ b/.github/ISSUE_TEMPLATE/bug_report.yml @@ -23,7 +23,7 @@ body: id: version attributes: label: executiontimer version - placeholder: "1.1.0" + placeholder: "1.1.1" validations: required: true diff --git a/CHANGELOG.md b/CHANGELOG.md index c523e3b..7836544 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,23 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +## [1.1.1] - 2026-10-01 + +### Documentation + +- The threads section of the concurrency guide was wrong for free-threaded Python 3.14. + There, a new thread starts in a copy of the context that started it, so its sections + nest under the section that was open at that moment. A thread pool reuses its workers, + so each worker keeps the section it started under: work submitted later from another + section was reported under the first one. The guide said pool work is always reported at + the top level, and that free-threaded builds nest thread work correctly with no extra + work. Neither was true on every build. The guide now explains the difference and shows + how to get the same report on every build: run each call in + `contextvars.copy_context().run` to nest it under the current section, or in + `contextvars.Context().run` to keep it at the top level. Behaviour is unchanged. +- Tests cover how threads and reused pool workers nest on each kind of build, and both + recipes. The guide's examples assert their results on every build. + ## [1.1.0] - 2026-09-30 ### Changed @@ -206,7 +223,8 @@ First public release on PyPI. `py.typed` marker so type checkers use the inline annotations. - `__version__` attribute on the package. -[Unreleased]: https://github.com/seba2390/ExecutionTimer/compare/v1.1.0...HEAD +[Unreleased]: https://github.com/seba2390/ExecutionTimer/compare/v1.1.1...HEAD +[1.1.1]: https://github.com/seba2390/ExecutionTimer/compare/v1.1.0...v1.1.1 [1.1.0]: https://github.com/seba2390/ExecutionTimer/compare/v1.0.3...v1.1.0 [1.0.3]: https://github.com/seba2390/ExecutionTimer/compare/v1.0.2...v1.0.3 [1.0.2]: https://github.com/seba2390/ExecutionTimer/compare/v1.0.1...v1.0.2 diff --git a/docs/guide/concurrency.md b/docs/guide/concurrency.md index 100a15a..505157b 100644 --- a/docs/guide/concurrency.md +++ b/docs/guide/concurrency.md @@ -57,11 +57,33 @@ the same. ## Threads -New threads do **not** inherit the active stack. Sections recorded in a thread appear at the -top level of the report, and their time is added to the total alongside the section that -started the thread: +Whether a new thread starts inside the section that started it depends on the Python build: + +- **Regular builds**, including Python 3.14, start each new thread with an empty stack. + Sections recorded in the thread appear at the top level of the report, and their time + is added to the total alongside the section that started the thread. +- **Free-threaded builds of Python 3.14** start each new thread with a copy of the context + of the code that called {meth}`~threading.Thread.start`. Sections recorded in the thread + nest under the section that was open at that moment. + +Python's `-X thread_inherit_context` option switches between the two on any 3.14 build, +and `sys.flags.thread_inherit_context` reports which one is in effect. + +### Thread pools + +The difference matters most for thread pools, because a pool reuses its threads. +{class}`~concurrent.futures.ThreadPoolExecutor` starts a worker thread when work is +submitted and keeps it for later work. On a free-threaded build, the worker keeps the +stack it started with for as long as it lives, so work submitted later, from a different +section or from none, still nests under the section that was open when the worker started. +On a regular build, the same work is recorded at the top level. + +To get the same report on every build, pick the context for each call yourself. To nest +thread work under the current section, run each call in a fresh copy of the current +context from {func}`contextvars.copy_context`: ```python +import contextvars from concurrent.futures import ThreadPoolExecutor from execution_timer import clear_execution_timings @@ -74,28 +96,38 @@ def download(n: int) -> int: return n -with TimerContext("batch"), ThreadPoolExecutor() as pool: - list(pool.map(download, range(4))) # recorded as ("download",), not ("batch", "download") +with ThreadPoolExecutor(max_workers=2) as pool: + with TimerContext("batch"): + futures = [pool.submit(contextvars.copy_context().run, download, n) for n in range(4)] + results = [future.result() for future in futures] + with TimerContext("retry"): + pool.submit(contextvars.copy_context().run, download, 0).result() + +timings = get_execution_timings() +assert ("batch", "download") in timings +assert ("retry", "download") in timings +assert ("download",) not in timings ``` -To nest thread work under the current section, run it in a copy of the current context -with {func}`contextvars.copy_context`, or use {func}`asyncio.to_thread`, which does that for -you: +Copy the context for every call rather than once per section: a context can't be entered +by two threads at the same time. {func}`asyncio.to_thread` copies the context for you. -```python -import contextvars +To keep thread work at the top level on every build, run each call in a new, empty +{class}`~contextvars.Context` instead: +```python clear_execution_timings() -with TimerContext("batch"), ThreadPoolExecutor() as pool: - context = contextvars.copy_context() - pool.submit(context.run, download, 1).result() +with ThreadPoolExecutor(max_workers=2) as pool, TimerContext("batch"): + pool.submit(contextvars.Context().run, download, 1).result() -assert ("batch", "download") in get_execution_timings() +timings = get_execution_timings() +assert ("download",) in timings +assert ("batch", "download") not in timings ``` -On free-threaded builds of Python 3.14, new threads inherit the context by default, so -thread sections nest without extra work. +The same works for a plain thread: pass `target=contextvars.copy_context().run` or +`target=contextvars.Context().run`, followed by the function and its arguments in `args`. ## Overlapping calls add up diff --git a/src/execution_timer/__init__.py b/src/execution_timer/__init__.py index fd68f1b..221517b 100644 --- a/src/execution_timer/__init__.py +++ b/src/execution_timer/__init__.py @@ -18,7 +18,7 @@ save_execution_timings_json, ) -__version__ = "1.1.0" +__version__ = "1.1.1" __all__ = [ "DEFAULT_CATEGORY", diff --git a/tests/execution_timer_test.py b/tests/execution_timer_test.py index 14cca80..085a78d 100644 --- a/tests/execution_timer_test.py +++ b/tests/execution_timer_test.py @@ -2,10 +2,12 @@ import asyncio import builtins +import contextvars import functools import inspect import json import logging +import sys import threading import time import warnings @@ -38,6 +40,10 @@ P = ParamSpec("P") R = TypeVar("R") +# New threads start in a copy of the starting thread's context. The default on free-threaded +# Python 3.14; the flag does not exist before 3.14. +THREADS_INHERIT_CONTEXT = bool(getattr(sys.flags, "thread_inherit_context", False)) + @pytest.fixture(autouse=True) def reset_timer() -> Iterator[None]: @@ -590,6 +596,47 @@ def worker(root: str, child: str) -> None: assert ("t0", "c1") not in timings assert ("t1", "c0") not in timings + def test_new_thread_nests_under_the_starting_section_only_where_threads_inherit_context(self) -> None: + thread = threading.Thread(target=TimerContext("work")(lambda: None)) + with TimerContext("outer"): + thread.start() + thread.join() + + expected = ("outer", "work") if THREADS_INHERIT_CONTEXT else ("work",) + assert set(raw_timings()) == {("outer",), expected} + + def test_reused_pool_worker_keeps_the_section_it_started_in_where_threads_inherit_context(self) -> None: + """A pool worker inherits the context once, when it starts, and keeps it for later work.""" + work = TimerContext("work")(lambda: None) + with ThreadPoolExecutor(max_workers=1) as pool: + with TimerContext("phase_a"): + pool.submit(work).result() + with TimerContext("phase_b"): + pool.submit(work).result() + + # Where threads inherit context, phase_b's call is misfiled under phase_a. + expected = {("phase_a", "work")} if THREADS_INHERIT_CONTEXT else {("work",)} + assert set(raw_timings()) == {("phase_a",), ("phase_b",), *expected} + + def test_copying_the_context_per_call_nests_pool_work_on_every_build(self) -> None: + work = TimerContext("work")(lambda: None) + with ThreadPoolExecutor(max_workers=2) as pool: + with TimerContext("phase_a"): + futures = [pool.submit(contextvars.copy_context().run, work) for _ in range(4)] + _ = [future.result() for future in futures] + with TimerContext("phase_b"): + pool.submit(contextvars.copy_context().run, work).result() + pool.submit(contextvars.copy_context().run, work).result() + + assert set(raw_timings()) == {("phase_a",), ("phase_a", "work"), ("phase_b",), ("phase_b", "work"), ("work",)} + + def test_an_empty_context_per_call_keeps_pool_work_top_level_on_every_build(self) -> None: + work = TimerContext("work")(lambda: None) + with ThreadPoolExecutor(max_workers=1) as pool, TimerContext("outer"): + pool.submit(contextvars.Context().run, work).result() + + assert set(raw_timings()) == {("outer",), ("work",)} + class TestAsyncDecorator: def test_async_decorator_times_the_await_not_coroutine_creation(self) -> None: