fix: CI leg timeout margin now accounts for measured pre-pytest overhead (#1784)

.github/workflows/tests.yml

@@ -99,10 +99,29 @@ jobs:
     # raised a third time: the growth (873s -> 1176.55s -> 1773.10s) has tracked
     # each cap raise closely enough that raising it again is not expected to
     # hold either, and #1660's own issue text argues against repeating that fix
-    # for however long the trend continues. The next recurrence, if the
-    # diagnostic can now actually fire, is what settles whether this is a real
-    # hang or something else growing the suite's own reported runtime.
-    timeout-minutes: 30
+    # for however long the trend continues (this was true when this cap was
+    # last left at 30; #1784 below raises it a third time anyway, but for a
+    # different, now-measured reason -- see that comment). The next
+    # recurrence, if the diagnostic can now actually fire, is what settles
+    # whether this is a real hang or something else growing the suite's own
+    # reported runtime.
+    #
+    # #1784: this 30-minute figure was clearing OBSERVED_WORST_CASE_SUITE_MINUTES
+    # (`tests/test_pytest_leg_timeout_1658.py`) by only ~26.9s, and that whole
+    # margin was computed against pytest's own self-reported runtime alone --
+    # `timeout-minutes` counts from JOB start, so checkout/setup-python/the
+    # Windows Defender exclusion step/`pip install`, none of which pytest's own
+    # clock ever sees, were silently eating into it. Measured directly from the
+    # GitHub Actions API for the six jobs already cited above and in
+    # `tests/posthang_diagnostics_1660.py`, that pre-pytest overhead ran 26-43s
+    # -- already comparable to, and at its worst exceeding, the entire 26.9s
+    # margin the arithmetic assumed was free. Raised by 2 minutes specifically
+    # to cover that now-measured, largely fixed overhead (not to chase the
+    # suite's own separate, unexplained runtime growth the paragraph above
+    # already argues against re-raising for) -- see
+    # `tests/test_pytest_leg_timeout_1658.py`'s own `PRE_PYTEST_OVERHEAD_SECONDS`
+    # for the six measured values this raise is sized against.
+    timeout-minutes: 32
     # #1246: the `os` x `python-version` product below is the full 3x4 release matrix,
     # unconditionally -- so `full_matrix: true` restores full coverage by excluding
     # nothing, rather than needing a second, separately-maintained matrix to drift out

changelog.d/1784.fixed.md

@@ -0,0 +1,10 @@
+- The CI leg-timeout margin tests (`tests/test_pytest_leg_timeout_1658.py`,
+  `tests/test_posthang_diagnostics_1660.py`) now subtract measured pre-pytest
+  overhead (checkout, setup-python, the Windows Defender exclusion step,
+  `pip install`) from the job's margin, instead of comparing the
+  `timeout-minutes` cap only against pytest's own self-reported runtime.
+  That overhead, measured from the GitHub Actions API at 26-43s across the
+  six CI jobs these tests already cite, was already comparable to the
+  entire ~27s margin the old arithmetic assumed was free. The `pytest`
+  job's own `timeout-minutes` cap is raised 30 -> 32 minutes to restore a
+  real margin once the overhead is accounted for (#1784).

tests/posthang_diagnostics_1660.py

@@ -148,31 +148,40 @@ def pytest_sessionfinish(session, exitstatus):
 #: `tests/test_pytest_leg_timeout_1658.py`) is pytest's OWN self-reported
 #: elapsed time -- i.e. measured from close to this same `pytest_configure`
 #: to `pytest_sessionfinish` -- so the ~26.9s gap between that figure and the
-#: job's 1800s cap is the TOTAL slack left over for everything pytest's own
+#: (then-)1800s cap was the TOTAL slack left over for everything pytest's own
 #: clock does not cover: checkout/setup/install BEFORE pytest starts, and
-#: teardown/cancellation-handling AFTER it finishes, combined. How that ~27s
-#: splits between the two halves is NOT measured. This constant therefore
-#: carries a real, unquantified risk this diagnostic accepts rather than
-#: hides: if checkout+setup+install alone take longer than
-#: `1800 - CONTROLLER_DUMP_AFTER_SECONDS` seconds, this timer fires AFTER
-#: the job's own cap has already killed the process, reproducing -- for the
-#: controller specifically -- the exact "diagnostic mathematically incapable
-#: of firing" failure #1660's own original 60s choice suffered for the
-#: worker-side timer. Set close to OBSERVED_WORST_CASE_SUITE_MINUTES*60
-#: (only +7s, deliberately smaller than POST_SESSION_DUMP_AFTER_SECONDS's
-#: own +15s) specifically to leave as much of that ~27s of total slack as
-#: possible for the unmeasured pre-pytest half, at the cost of a smaller
-#: buffer above a normal green run's own worst-case duration (so a stray
-#: controller dump on an ordinary run is a somewhat more real possibility
-#: here than on the worker-side timer -- the same class of accepted
-#: tradeoff POST_SESSION_DUMP_AFTER_SECONDS's own comment already names for
-#: itself). Hand-maintained, same as POST_SESSION_DUMP_AFTER_SECONDS above
-#: and for the same reason: not read from a live CI measurement, and
+#: teardown/cancellation-handling AFTER it finishes, combined. #1784 measured
+#: the pre-pytest half directly from the GitHub Actions API (job start to the
+#: "Run tests" step's own start) across the six jobs already cited in
+#: `tests/test_pytest_leg_timeout_1658.py`'s own `PRE_PYTEST_OVERHEAD_SECONDS`:
+#: 26-43s -- already comparable to, and at its worst exceeding, that entire
+#: ~27s of assumed-free slack. That finding is what raised the job's own cap
+#: (30 -> 32 minutes, `.github/workflows/tests.yml`); the post-finish
+#: teardown/cancellation-handling half remains unmeasured. This constant
+#: therefore still carries a real, if smaller and now partly quantified,
+#: risk: if checkout+setup+install alone take longer than
+#: `cap_seconds - CONTROLLER_DUMP_AFTER_SECONDS` (checked by
+#: `test_controller_dump_delay_fits_inside_the_jobs_own_margin`, which now
+#: subtracts the measured overhead from the cap rather than comparing
+#: against the bare cap), this timer fires AFTER the job's own cap has
+#: already killed the process, reproducing -- for the controller
+#: specifically -- the exact "diagnostic mathematically incapable of firing"
+#: failure #1660's own original 60s choice suffered for the worker-side
+#: timer. Set close to OBSERVED_WORST_CASE_SUITE_MINUTES*60 (only +7s,
+#: deliberately smaller than POST_SESSION_DUMP_AFTER_SECONDS's own +15s)
+#: specifically to leave as much of the job's own slack as possible for the
+#: pre-pytest half, at the cost of a smaller buffer above a normal green
+#: run's own worst-case duration (so a stray controller dump on an ordinary
+#: run is a somewhat more real possibility here than on the worker-side
+#: timer -- the same class of accepted tradeoff
+#: POST_SESSION_DUMP_AFTER_SECONDS's own comment already names for itself).
+#: Hand-maintained, same as POST_SESSION_DUMP_AFTER_SECONDS above and for
+#: the same reason: not read from a live CI measurement on every run, and
 #: `test_controller_dump_delay_fits_inside_the_jobs_own_margin` in
 #: `tests/test_posthang_diagnostics_1660.py` only catches this value going
-#: stale against whatever the two constants it is derived from currently
-#: say -- it cannot measure, and does not claim to measure, the real
-#: pre-pytest overhead this constant is silent about.
+#: stale against whatever the constants it is derived from currently say --
+#: it cannot measure, and does not claim to measure, the post-finish half of
+#: the overhead this constant is still silent about.
 CONTROLLER_DUMP_AFTER_SECONDS = 1780
 
 

tests/test_posthang_diagnostics_1660.py

@@ -9,6 +9,7 @@
 
 from test_pytest_leg_timeout_1658 import (  # noqa: E402
     OBSERVED_WORST_CASE_SUITE_MINUTES,
+    PRE_PYTEST_OVERHEAD_SECONDS,
     needs_yaml,
     _pytest_job,
 )
@@ -138,13 +139,21 @@ def test_controller_dump_delay_fits_inside_the_jobs_own_margin():
             phd.CONTROLLER_DUMP_AFTER_SECONDS, worst_case_seconds
         )
     )
-    assert phd.CONTROLLER_DUMP_AFTER_SECONDS < cap_seconds, (
+    # #1784: the controller's own clock starts at `pytest_configure` (process
+    # start), which is already PRE_PYTEST_OVERHEAD_SECONDS into the job's own
+    # wall clock -- checkout/setup-python/install all run first, as separate
+    # steps `pytest_configure` never sees. So the real ceiling this timer must
+    # clear is `cap_seconds - PRE_PYTEST_OVERHEAD_SECONDS`, not the bare cap.
+    assert (
+        phd.CONTROLLER_DUMP_AFTER_SECONDS < cap_seconds - PRE_PYTEST_OVERHEAD_SECONDS
+    ), (
         "posthang_diagnostics_1660.CONTROLLER_DUMP_AFTER_SECONDS ({!r}s) is not "
-        "less than the job's own timeout-minutes cap ({:.1f}s) -- the "
-        "controller's own watchdog would be killed by the job's cap before it "
-        "ever gets a chance to dump a stack, exactly the #1660 recurrence this "
-        "module exists to explain".format(
-            phd.CONTROLLER_DUMP_AFTER_SECONDS, cap_seconds
+        "less than the job's own timeout-minutes cap ({:.1f}s) minus the "
+        "measured pre-pytest overhead ({!r}s, #1784) -- the controller's own "
+        "watchdog would be killed by the job's cap before it ever gets a "
+        "chance to dump a stack, exactly the #1660 recurrence this module "
+        "exists to explain".format(
+            phd.CONTROLLER_DUMP_AFTER_SECONDS, cap_seconds, PRE_PYTEST_OVERHEAD_SECONDS
         )
     )
 
@@ -185,13 +194,26 @@ def test_dump_delay_fits_inside_the_jobs_own_margin():
     assert isinstance(cap_minutes, int), "timeout-minutes is not an int: {!r}".format(
         cap_minutes
     )
-    margin_seconds = (cap_minutes * 60) - (OBSERVED_WORST_CASE_SUITE_MINUTES * 60)
+    # #1784: subtract the measured pre-pytest overhead too -- pytest's own
+    # summary line never sees checkout/setup-python/install, which all run
+    # before it, so the job's real margin over pytest's own reported worst
+    # case is smaller than the bare cap-minus-runtime subtraction below used
+    # to assume.
+    margin_seconds = (
+        (cap_minutes * 60)
+        - (OBSERVED_WORST_CASE_SUITE_MINUTES * 60)
+        - PRE_PYTEST_OVERHEAD_SECONDS
+    )
     assert phd.POST_SESSION_DUMP_AFTER_SECONDS < margin_seconds, (
         "posthang_diagnostics_1660.POST_SESSION_DUMP_AFTER_SECONDS ({!r}s) is not "
         "less than the job's own margin over the observed worst-case suite "
-        "runtime ({:.1f}s) -- the diagnostic would be killed by the job's own "
-        "timeout-minutes cap before it ever gets a chance to dump a stack, "
-        "exactly the #1660 recurrence this module exists to explain".format(
-            phd.POST_SESSION_DUMP_AFTER_SECONDS, margin_seconds
+        "runtime, once the measured pre-pytest overhead ({!r}s, #1784) is also "
+        "subtracted ({:.1f}s) -- the diagnostic would be killed by the job's "
+        "own timeout-minutes cap before it ever gets a chance to dump a "
+        "stack, exactly the #1660 recurrence this module exists to "
+        "explain".format(
+            phd.POST_SESSION_DUMP_AFTER_SECONDS,
+            PRE_PYTEST_OVERHEAD_SECONDS,
+            margin_seconds,
         )
     )

tests/test_pytest_leg_timeout_1658.py

@@ -40,6 +40,17 @@
 to promise, and a reader should not take this paragraph's older framing at face
 value: there is no multi-minute buffer here anymore.
 
+UPDATE (#1784): that ~27s figure was itself an overstatement of the true margin --
+it compared the job's `timeout-minutes` cap only against pytest's OWN self-reported
+runtime, but the cap counts from JOB start, and checkout/setup-python/the Windows
+Defender exclusion step/`pip install` all run, as separate steps, before pytest
+ever starts. Measured directly from the GitHub Actions API for the six jobs already
+cited in this file, that pre-pytest overhead ran 26-43s -- already comparable to,
+and at its worst exceeding, the entire ~27s this file used to treat as free margin.
+`PRE_PYTEST_OVERHEAD_SECONDS` below is that measurement; the margin test now
+subtracts it, and the job's own cap was raised (30 -> 32 minutes) to keep a real,
+if still thin, margin once it is subtracted.
+
 Python 3.9 compatible.
 """
 
@@ -61,6 +72,24 @@
 #: number has now grown twice, unexplained, and may again.
 OBSERVED_WORST_CASE_SUITE_MINUTES = 1773.10 / 60.0
 
+#: #1784: the margin below used to treat OBSERVED_WORST_CASE_SUITE_MINUTES as
+#: the whole job, but `timeout-minutes` counts from JOB start, and
+#: checkout/setup-python/the Windows Defender exclusion step/`pip install`
+#: all run as separate steps BEFORE "Run tests" ever invokes pytest -- none
+#: of that time is in pytest's own "in Xs" summary line. Measured directly
+#: via the GitHub Actions API (`gh api repos/.../actions/jobs/<id>`, each
+#: job's own `started_at` to its "Run tests" step's own `started_at`) for the
+#: exact six job IDs already cited in this file and in
+#: `tests/posthang_diagnostics_1660.py`:
+#:   105401634166 -> 43s   105406249723 -> 29s   105410692355 -> 33s
+#:   105421966394 -> 28s   105427076121 -> 26s   105442284149 -> 29s
+#: 43s is the largest of the six and is what the margin below now subtracts.
+#: This is real, measured overhead for this leg -- not another
+#: hand-maintained guess alongside the constant above -- but six samples is
+#: not a guarantee: a seventh occurrence outside this range needs this
+#: constant updated by hand, the same way the constant above already is.
+PRE_PYTEST_OVERHEAD_SECONDS = 43
+
 try:
     import yaml
 except ImportError:  # pragma: no cover - exercised by the guard test below
@@ -117,25 +146,34 @@ def test_the_pytest_job_cap_clears_the_observed_worst_case_with_margin():
     again, from 1176.55s to 1773.10s, on a cap already raised from 20 to 30
     minutes: the growth (~596.55s) tracks the cap raise (~600s) closely enough
     that a flat multi-minute floor is not a bound this suite's own growth trend
-    respects. Requiring `margin >= 3` against the corrected constant above would
-    fail outright (margin is ~0.45 minutes) and the honest fix is not to keep
-    raising `timeout-minutes` to chase an unexplained trend (#1660's own issue
-    text argues against exactly that repeat) -- it is a real, if much smaller,
-    floor: some positive margin must survive, and
+    respects. Requiring `margin >= 3` against `OBSERVED_WORST_CASE_SUITE_MINUTES`
+    alone (the only "corrected constant" that existed at the time this paragraph
+    was written) would fail outright (margin was ~0.45 minutes) and the honest
+    fix is not to keep raising `timeout-minutes` to chase an unexplained trend
+    (#1660's own issue text argues against exactly that repeat) -- it is a
+    real, if much smaller, floor: some positive margin must survive. #1784
+    later added a second corrected term, `PRE_PYTEST_OVERHEAD_SECONDS`, and
+    raised the cap to keep that same floor positive (~1.73 minutes now, against
+    the current 32-minute cap) -- the ~0.45-minute figure above describes the
+    margin at the moment #1660 was fixed, not the margin this test currently
+    asserts; do not carry it forward as the live number. And
     `test_posthang_diagnostics_1660.test_dump_delay_fits_inside_the_jobs_own_margin`
     is the test that ties this same margin to what the (now-fixed) faulthandler
     diagnostic actually needs to get a chance to fire before the cap does.
     """
     job = _pytest_job()
     cap = job.get("timeout-minutes")
     assert isinstance(cap, int), "timeout-minutes is not an int: {!r}".format(cap)
-    margin = cap - OBSERVED_WORST_CASE_SUITE_MINUTES
+    margin = (
+        cap * 60 - OBSERVED_WORST_CASE_SUITE_MINUTES * 60 - PRE_PYTEST_OVERHEAD_SECONDS
+    ) / 60.0
     assert margin > 0, (
         "the pytest job's timeout-minutes ({!r}) leaves NO margin over the "
         "observed worst-case suite runtime of {:.2f} minutes (job "
-        "#105442284149, commit c201a8a0, 1773.10s) -- the job would already be "
-        "cancelled before the suite's own summary line could even print, which "
-        "is worse than #1658 and #1660's prior two occurrences combined".format(
-            cap, OBSERVED_WORST_CASE_SUITE_MINUTES
+        "#105442284149, commit c201a8a0, 1773.10s) once the measured "
+        "pre-pytest overhead ({!r}s, #1784) is also subtracted -- the job "
+        "would already be cancelled before or shortly after the suite's own "
+        "summary line could even print".format(
+            cap, OBSERVED_WORST_CASE_SUITE_MINUTES, PRE_PYTEST_OVERHEAD_SECONDS
         )
     )