diff --git a/.github/workflows/tests.yml b/.github/workflows/tests.yml index 9f459f2d..56eac0b7 100644 --- a/.github/workflows/tests.yml +++ b/.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 diff --git a/changelog.d/1784.fixed.md b/changelog.d/1784.fixed.md new file mode 100644 index 00000000..76335657 --- /dev/null +++ b/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). diff --git a/tests/posthang_diagnostics_1660.py b/tests/posthang_diagnostics_1660.py index cef415aa..43dd3b4e 100644 --- a/tests/posthang_diagnostics_1660.py +++ b/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 diff --git a/tests/test_posthang_diagnostics_1660.py b/tests/test_posthang_diagnostics_1660.py index 2ce4634a..535a2db0 100644 --- a/tests/test_posthang_diagnostics_1660.py +++ b/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, ) ) diff --git a/tests/test_pytest_leg_timeout_1658.py b/tests/test_pytest_leg_timeout_1658.py index 2372321f..4c11af9a 100644 --- a/tests/test_pytest_leg_timeout_1658.py +++ b/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/`, 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,11 +146,17 @@ 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. @@ -129,13 +164,16 @@ def test_the_pytest_job_cap_clears_the_observed_worst_case_with_margin(): 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 ) )