From e9c55e12ee30a44c24c1a3703351f7f085ae60d8 Mon Sep 17 00:00:00 2001 From: Sebastian Yde Madsen <75695915+seba2390@users.noreply.github.com> Date: Thu, 1 Oct 2026 00:03:26 +0200 Subject: [PATCH] Release 1.1.1: document how thread nesting differs by Python build On free-threaded Python 3.14 a new thread starts in a copy of the context that started it. A thread pool starts workers lazily and reuses them, so each worker keeps the section it started under, and work submitted later from another section is reported under the first one. Regular builds report the same work at the top level. The concurrency guide said pool work is always top-level (a comment the docs test never asserted, and false on 3.14t) and that free-threaded builds nest thread work with no extra work. It now explains the difference and shows how to get the same report on every build: run each call in copy_context().run to nest it, or Context().run to keep it top-level. Both examples assert their results. New tests pin how plain threads and reused pool workers nest on each kind of build, and check both recipes. The library can't fix this itself: it can't tell an intentionally inherited context from a stale one. Behaviour is unchanged. Bump __version__ to 1.1.1 and update the bug template's placeholder. --- .github/ISSUE_TEMPLATE/bug_report.yml | 2 +- CHANGELOG.md | 20 ++++++++- docs/guide/concurrency.md | 64 ++++++++++++++++++++------- src/execution_timer/__init__.py | 2 +- tests/execution_timer_test.py | 47 ++++++++++++++++++++ 5 files changed, 116 insertions(+), 19 deletions(-) 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: