diff --git a/.github/workflows/experimental.yml b/.github/workflows/experimental.yml index 2a2b6bbb3..d4f0d74e3 100644 --- a/.github/workflows/experimental.yml +++ b/.github/workflows/experimental.yml @@ -262,7 +262,25 @@ jobs: # runner alive, and a breach fails this step instead: # - GraalPy alone: a 2 GiB heap per process, read by every GraalPy # process, xdist workers included (GRAAL_PYTHON_VM_ARGS), and 3 workers, - # which leaves a CPU of the 4 to the JIT and the runner. + # which leaves a CPU of the 4 to the JIT and the runner. On the native + # standalone `--vm.Xmx` caps the Java heap alone, not thread stacks or + # JIT code (graalvm.org, Native Image, Memory Management), and a heap + # the GC cannot free raises OutOfMemoryError, which GraalPy turns into + # MemoryError (graalpython runtime/exception/ExceptionUtils.java:313-316, + # at graal-25.4.4). + # - #1753: a worker's live heap grows with its tests. Job 116172356218's + # three workers reached 2.2-2.6 GB RSS in 16 minutes; four tests raised + # MemoryError, then gw1 raised one in pytest's own failure report, + # which ends the session (exit 3) with 7.9 GB still free. Locally + # (25.4.4, -n 0) the heap after a full GC rose from 199M to 1738M over + # 11% of tests/const and tests/corekit, so no heap the 12G holds for 3 + # workers lasts the tier. `-XX:+ExitOnOutOfMemoryError` ends that + # worker instead, xdist reports the test it ran as crashed and starts a + # fresh one. `--max-worker-restart=30` allows 30 restarts in all, where + # three heaps that last 16 minutes need about 21 in 110; xdist's default + # is 4 a worker, 12 at -n 3. + # Five corekit files at `--vm.Xmx450m -n 1`: exit 3 after 28 passed + # without the flag; with it, 3 workers replaced and the run finished. # - `timeout` sends SIGINT at 110 minutes, under the 120-minute cap, so # pytest still writes the junit XML, and exits 124; SIGKILL 3 minutes on. # - `prlimit --fsize`: no file over 2 GiB. @@ -280,21 +298,24 @@ jobs: # way the tests run the one argv, in the scope or not. # `tests-status` holds the exit status, the scope and the probe's error, # the seconds the tests took, the kernel's OOM kills while they ran - # (/proc/vmstat `oom_kill`) and the MemoryError count, for `Containment - # summary`. + # (/proc/vmstat `oom_kill`), the MemoryError count (`-w`, so Java's + # `OutOfMemoryError` and the flag are not counted) and the workers that + # crashed, by xdist's `[gwN] node down:` lines (under `-q` it prints no + # `replacing crashed worker`, xdist/dsession.py:78-80 at v3.8.0), for + # `Containment summary`. - name: Run unit tests id: tests if: ${{ steps.install.outcome == 'success' }} continue-on-error: true timeout-minutes: 120 env: - GRAAL_PYTHON_VM_ARGS: ${{ startsWith(matrix.python-version, 'graalpy') && '--vm.Xmx2g' || '' }} + GRAAL_PYTHON_VM_ARGS: ${{ startsWith(matrix.python-version, 'graalpy') && '--vm.Xmx2g --vm.XX:+ExitOnOutOfMemoryError' || '' }} WORKERS: ${{ startsWith(matrix.python-version, 'graalpy') && '3' || 'auto' }} run: | tail -n +1 -F "$RUNNER_TEMP/resource-monitor.log" 2>/dev/null & monitor=$! trap 'kill "$monitor" 2>/dev/null || true' EXIT - set -- -q -n "$WORKERS" --dist load \ + set -- -q -n "$WORKERS" --dist load --max-worker-restart=30 \ --durations=30 --durations-min=1.0 --junitxml="$RUNNER_TEMP/junit.xml" \ --ignore=tests/integration \ --ignore-glob='*_runtime.py' \ @@ -328,10 +349,11 @@ jobs: set -e elapsed=$((SECONDS - started)) after=$(oom_kills) - memory_errors=$(grep -c MemoryError "$RUNNER_TEMP/pytest.log" || true) - printf 'exit=%s\nscope=%s\nprobe=%s\nelapsed=%s\noom_kills=%s\nmemory_errors=%s\n' \ + memory_errors=$(grep -cw MemoryError "$RUNNER_TEMP/pytest.log" || true) + crashed_workers=$(grep -c '\] node down: ' "$RUNNER_TEMP/pytest.log" || true) + printf 'exit=%s\nscope=%s\nprobe=%s\nelapsed=%s\noom_kills=%s\nmemory_errors=%s\ncrashed_workers=%s\n' \ "$status" "$scope" "$probe" "$elapsed" "$(( ${after:-0} - ${before:-0} ))" "$memory_errors" \ - > "$RUNNER_TEMP/tests-status" + "$crashed_workers" > "$RUNNER_TEMP/tests-status" exit "$status" # #1740: after a failed, timed-out or cancelled tests step too. A lost @@ -382,12 +404,12 @@ jobs: # tests, ahead of `Experimental summary`, whose script stays the KTLO # summary's (tests/project/test_ktlo_legs_stay_green_1672.py) and which # still reports a failed `tests` step as it reports any. Each cause gets a - # warning of its own: no 12G scope, an OOM kill, a MemoryError, and a - # timeout -- exit 124, or 137 with no OOM kill after 110 minutes, which is - # `--kill-after` ending a teardown that SIGINT did not. An OOM kill of - # pytest itself also exits 137, so the OOM count and the time tell them - # apart. Nothing here fails: a missing or partial status is reported as - # what it is. + # warning of its own: no 12G scope, an OOM kill, a MemoryError, a worker + # xdist replaced (#1753), and a timeout -- exit 124, or 137 with no OOM + # kill after 110 minutes, which is `--kill-after` ending a teardown that + # SIGINT did not. An OOM kill of pytest itself also exits 137, so the OOM + # count and the time tell them apart. Nothing here fails: a missing or + # partial status is reported as what it is. - name: Containment summary if: ${{ !cancelled() }} continue-on-error: true @@ -411,7 +433,7 @@ jobs: echo "- ${LEG}: ${1}; non-blocking, so this job still succeeds." >> "$GITHUB_STEP_SUMMARY" } code=$(value exit) scope=$(value scope) elapsed=$(value elapsed) - oom=$(value oom_kills) errors=$(value memory_errors) + oom=$(value oom_kills) errors=$(value memory_errors) crashed=$(value crashed_workers) if [ "$scope" = none ]; then warn "No memory cap" "The probe, sudo -n systemd-run --scope with the tests' flags, failed ($(value probe)), so the tests ran without the 12G scope." fi @@ -426,7 +448,10 @@ jobs: if [ "$errors" -gt 0 ] 2>/dev/null; then warn "tests raised MemoryError" "${errors} MemoryError line(s) in the pytest output, exit ${code}, scope ${scope}; ${last}." fi - echo "$LEG: tests exited ${code} after ${elapsed} s, scope ${scope}, ${oom} OOM kill(s), ${errors} MemoryError line(s); ${last}." + if [ "$crashed" -gt 0 ] 2>/dev/null; then + warn "tests lost an xdist worker" "${crashed} xdist worker(s) went down, each failing the test it ran, and xdist replaces up to 30; exit ${code}, scope ${scope}; ${last}." + fi + echo "$LEG: tests exited ${code} after ${elapsed} s, scope ${scope}, ${oom} OOM kill(s), ${errors} MemoryError line(s), ${crashed:-0} worker(s) down; ${last}." # #1660: an experimental leg's report, as unit-tests.yml `test`'s `KTLO # summary` is a KTLO leg's, and for the same reasons. diff --git a/docs/source/contributing/workflows.rst b/docs/source/contributing/workflows.rst index d33fc5fc1..42b60deb2 100644 --- a/docs/source/contributing/workflows.rst +++ b/docs/source/contributing/workflows.rst @@ -799,9 +799,16 @@ so ``Run unit tests`` holds the tests to what leaves the runner alive, and a bre fails the step, which ``Containment summary`` and ``Experimental summary`` report as warnings: -* GraalPy alone gets ``GRAAL_PYTHON_VM_ARGS=--vm.Xmx2g``, a 2 GiB heap for every - GraalPy process, xdist workers included, and ``-n 3``, a CPU of the runner's 4 left - to the JIT and the runner; 3.14t keeps ``-n auto``. +* GraalPy alone gets ``GRAAL_PYTHON_VM_ARGS=--vm.Xmx2g --vm.XX:+ExitOnOutOfMemoryError``, + a 2 GiB heap for every GraalPy process, xdist workers included, and ``-n 3``, a CPU + of the runner's 4 left to the JIT and the runner; 3.14t keeps ``-n auto``. A + worker's live heap grows with the tests it runs (`#1753 + `__): in job 116172356218 all + three reached 2.2-2.6 GB RSS in 16 minutes, and a ``MemoryError`` in pytest's own + failure report ended the session, exit 3, with 7.9 GB free. So a worker whose heap + is spent exits, xdist fails the test it ran as crashed and starts another, and + ``--max-worker-restart=30`` allows 30 restarts in all, where three 16-minute heaps need + about 21 in 110 minutes; xdist's default is 4 a worker, 12 at ``-n 3``. * ``timeout --signal=INT --kill-after=3m 110m`` ends pytest under the step's 120-minute cap, so it still writes the junit XML, and exits 124; ``prlimit --fsize=2147483648`` caps any file at 2 GiB. @@ -817,10 +824,11 @@ warnings: The step writes ``$RUNNER_TEMP/tests-status``: the exit status, the scope and the probe's error, the seconds the tests took, the OOM kills while they ran -(``/proc/vmstat``) and the ``MemoryError`` lines in their output. From it and the -monitor's last sample, ``Containment summary`` warns ``No memory cap``, ``tests lost a -process to the OOM killer``, ``tests timed out at 110 minutes`` or ``tests raised -MemoryError``, each a warning of its own. A timeout is exit 124, or 137 with no OOM kill +(``/proc/vmstat``), the ``MemoryError`` lines in their output and xdist's ``node +down`` lines. From it and the monitor's last sample, ``Containment summary`` warns +``No memory cap``, ``tests lost a process to the OOM killer``, ``tests timed out at 110 +minutes``, ``tests raised MemoryError`` or ``tests lost an xdist worker``, each a +warning of its own. A timeout is exit 124, or 137 with no OOM kill after 110 minutes: ``--kill-after``'s SIGKILL to a teardown SIGINT did not end, where an OOM kill of pytest exits 137 too. ``Experimental summary``, the job's last step and the KTLO summary's script, still warns of every failed step, ``tests`` included. The 2 GiB, diff --git a/tests/project/test_graalpy_worker_heap_1753.py b/tests/project/test_graalpy_worker_heap_1753.py new file mode 100644 index 000000000..dcb6d5976 --- /dev/null +++ b/tests/project/test_graalpy_worker_heap_1753.py @@ -0,0 +1,139 @@ +# -*- coding: utf-8 -*- +"""#1753: a GraalPy xdist worker whose heap is spent exits, and xdist replaces it. + +Under #1740's 2 GiB heap a GraalPy worker's live heap grows with the tests it +runs, until a ``MemoryError`` lands in pytest's own failure report and ends the +session, exit 3 (job 116172356218, 16 minutes in, at ``34 failed, 569 passed``). +So every GraalPy process gets ``-XX:+ExitOnOutOfMemoryError`` with its heap, and +pytest ``--max-worker-restart=30``: the worker exits, xdist fails the test it ran +as crashed and starts another, and the tier goes on to its end or its timeout. +``Run unit tests`` counts xdist's ``[gwN] node down:`` lines, and ``Containment +summary`` warns of them. + +""" + +from __future__ import annotations + +import os +import pathlib +import shutil +import sys +import tempfile +import unittest + +from tests.project.test_python_matrix_tiers_1633 import legs, workflow_commands +from tests.project.test_python_versions_1660 import ROOT, prose +from tests.project.test_resource_monitor_1740 import (BASH, DEFAULT, EXPERIMENTAL, SUMMARY, TESTS, by_impl, sh, + step) + +#: What every GraalPy process reads: #1740's 2 GiB heap, and an exit where it is spent. +GRAAL_VM_ARGS = '--vm.Xmx2g --vm.XX:+ExitOnOutOfMemoryError' +#: About 7 replacements a worker in 110 minutes, at a heap that lasts 16; xdist's default is 4 a worker. +RESTARTS = '--max-worker-restart=30' +#: xdist's line for a worker that went down with an error, which ``-q`` still prints. +NODE_DOWN = '[gw0] node down: Not properly terminated' + + +class TestTheWorkersAreReplaced(unittest.TestCase): + + def test_graalpy_exits_on_a_spent_heap(self) -> None: + env = step(TESTS)['env'] + versions = [leg['python-version'] for leg in legs(*EXPERIMENTAL)] + self.assertTrue(any(version.startswith('graalpy') for version in versions), versions) + for version in versions: + with self.subTest(version=version): + self.assertEqual(by_impl(env['GRAAL_PYTHON_VM_ARGS'], version), + GRAAL_VM_ARGS if version.startswith('graalpy') else '') + + def test_xdist_may_replace_30_workers(self) -> None: + script = step(TESTS)['run'] + self.assertIn(f'set -- -q -n "$WORKERS" --dist load {RESTARTS} \\\n', script) + self.assertEqual(script.count('--max-worker-restart'), 1) + + def test_the_docs_say_it(self) -> None: + page = prose(ROOT / 'docs' / 'source' / 'contributing' / 'workflows.rst') + for phrase in (f'``GRAAL_PYTHON_VM_ARGS={GRAAL_VM_ARGS}``', f'``{RESTARTS}``', '#1753', + '``tests lost an xdist worker``'): + with self.subTest(phrase=phrase): + self.assertIn(phrase, page) + + +@unittest.skipUnless(sys.platform.startswith('linux') and all(map(shutil.which, ('bash', 'timeout', 'prlimit'))), + 'the tests step runs coreutils timeout and util-linux prlimit, as on the Ubuntu runners') +class TestTheCrashesAreCounted(unittest.TestCase): + """The tests step and ``Containment summary``, with ``sudo`` and ``python`` stubbed on ``PATH``.""" + + def setUp(self) -> None: + tmp = tempfile.TemporaryDirectory(prefix='pcapkit-1753-') # pylint: disable=consider-using-with + self.addCleanup(tmp.cleanup) + self.tmp = pathlib.Path(tmp.name) + self.temp = self.tmp / 'temp' + self.temp.mkdir() + self.bindir = self.tmp / 'bin' + self.bindir.mkdir() + (self.temp / 'resource-monitor.log').write_text('', encoding='utf-8') + self.vmstat = self.tmp / 'vmstat' + self.vmstat.write_text('oom_kill 0\n', encoding='utf-8') + self.env = dict(os.environ, RUNNER_TEMP=str(self.temp), GITHUB_WORKSPACE=str(ROOT), WORKERS='3', + GRAAL_PYTHON_VM_ARGS=GRAAL_VM_ARGS, + LEG='Python graalpy-25.4 (experimental, non-blocking)', + GITHUB_STEP_SUMMARY=str(self.tmp / 'summary.md'), + PATH=str(self.bindir) + os.pathsep + os.environ.get('PATH', '')) + # No scope: the probe fails, so the tests run the same argv uncapped. + self.stub('sudo', 'exit 1\n') + + def stub(self, name: 'str', body: 'str') -> 'None': + path = self.bindir / name + path.write_text('#!/bin/sh\n' + body, encoding='utf-8') + path.chmod(0o755) + + def status(self, pytest: 'str') -> 'dict[str, str]': + self.stub('python', pytest) + self.assertEqual(shutil.which('sudo', path=self.env['PATH']), str(self.bindir / 'sudo')) + result = sh(step(TESTS)['run'].replace('/proc/vmstat', str(self.vmstat)), self.env, DEFAULT) + self.assertEqual(result.returncode, 1, result.stderr) + text = (self.temp / 'tests-status').read_text(encoding='utf-8') + return dict(line.split('=', 1) for line in text.splitlines()) + + def test_the_heap_and_the_restarts_reach_pytest(self) -> None: + status = self.status(f'printf "%s\\n" "$@" > {self.tmp / "argv"}\necho "heap $GRAAL_PYTHON_VM_ARGS"\nexit 1\n') + argv = (self.tmp / 'argv').read_text(encoding='utf-8').splitlines() + self.assertEqual(argv[:8], ['-m', 'pytest', '-q', '-n', '3', '--dist', 'load', RESTARTS]) + self.assertEqual(status['crashed_workers'], '0') + + def test_every_worker_that_went_down_is_counted(self) -> None: + # As job 116172356218's progress line runs into it, and on a line of its own. + status = self.status(f'echo "..F.{NODE_DOWN}"\necho "[gw2] node down: Not properly terminated"\n' + 'echo "replacing crashed worker gw2"\nexit 1\n') + self.assertEqual(status['crashed_workers'], '2') + self.assertEqual(status['memory_errors'], '0') + + def test_a_java_out_of_memory_line_is_no_memory_error(self) -> None: + """``-w``: the flag, and Java's ``OutOfMemoryError``, are not Python's ``MemoryError``.""" + status = self.status('echo "heap $GRAAL_PYTHON_VM_ARGS"\necho "java.lang.OutOfMemoryError: Java heap space"\n' + 'echo "E MemoryError"\necho "MemoryError: out of memory"\nexit 1\n') + self.assertEqual(status['memory_errors'], '2') + + def test_the_summary_warns_of_the_lost_workers(self) -> None: + (self.temp / 'tests-status').write_text( + 'exit=1\nscope=12G\nprobe=\nelapsed=6000\noom_kills=0\nmemory_errors=0\ncrashed_workers=7\n', + encoding='utf-8') + result = sh(step(SUMMARY)['run'], self.env, BASH) + self.assertEqual(result.returncode, 0, result.stderr) + self.assertEqual(workflow_commands(result.stdout), [ + '::warning title=tests lost an xdist worker on Python graalpy-25.4 (experimental%2C non-blocking)::7 ' + 'xdist worker(s) went down, each failing the test it ran, and xdist replaces up to 30; exit 1, scope 12G; ' + 'no resource-monitor sample. Experimental legs never block (#1660), so this job still succeeds.']) + self.assertIn('7 worker(s) down', result.stdout) + + def test_a_status_without_the_count_warns_of_nothing_new(self) -> None: + """A ``tests-status`` from before #1753, or a partial one, is no crash.""" + (self.temp / 'tests-status').write_text('exit=1\nscope=12G\noom_kills=0\nmemory_errors=0\n', encoding='utf-8') + result = sh(step(SUMMARY)['run'], self.env, BASH) + self.assertEqual(result.returncode, 0, result.stderr) + self.assertEqual(workflow_commands(result.stdout), []) + self.assertIn('0 worker(s) down', result.stdout) + + +if __name__ == '__main__': + unittest.main() diff --git a/tests/project/test_resource_monitor_1740.py b/tests/project/test_resource_monitor_1740.py index ae858cf85..2198185f0 100644 --- a/tests/project/test_resource_monitor_1740.py +++ b/tests/project/test_resource_monitor_1740.py @@ -194,8 +194,9 @@ def test_the_stop_step_passes_on_a_leg_the_monitor_never_started(self) -> None: self.assertEqual(stop.stdout, 'The resource monitor did not start on this leg.\n') -#: Round 2's containment, as the issue's research sized it (estimates, until a run shows them). -HEAP, GRAAL_WORKERS, SCOPE_MEMORY = '--vm.Xmx2g', '3', '12G' +#: Round 2's containment, as the issue's research sized it (estimates, until a run shows them); +#: #1753 adds the exit on a spent heap, which tests/project/test_graalpy_worker_heap_1753.py pins. +HEAP, GRAAL_WORKERS, SCOPE_MEMORY = '--vm.Xmx2g --vm.XX:+ExitOnOutOfMemoryError', '3', '12G' FSIZE = 2 * 1024 ** 3 #: Round 3: the probe is the scope itself, every flag included, under a throwaway unit. PROBE = 'if probe=$(scoped "pcapkit-probe-$$.scope" true 2>&1); then' @@ -364,7 +365,8 @@ def test_the_scope_runs_the_tests_under_the_timeout_and_fsize_cap(self) -> None: self.assertEqual(workflow_commands(result.stdout), []) status = self.status() self.assertRegex(status.pop('elapsed'), r'^\d+$') - self.assertEqual(status, {'exit': '1', 'scope': '12G', 'probe': '', 'oom_kills': '0', 'memory_errors': '0'}) + self.assertEqual(status, {'exit': '1', 'scope': '12G', 'probe': '', 'oom_kills': '0', 'memory_errors': '0', + 'crashed_workers': '0'}) def test_without_a_scope_the_tests_run_uncapped_with_a_warning(self) -> None: self.stub('sudo', 'echo "sudo: a password is required" >&2\nexit 1\n') diff --git a/tests/project/test_sweeps_on_latest_only_1732.py b/tests/project/test_sweeps_on_latest_only_1732.py index 0508a0adb..a87c480c6 100644 --- a/tests/project/test_sweeps_on_latest_only_1732.py +++ b/tests/project/test_sweeps_on_latest_only_1732.py @@ -172,6 +172,8 @@ def test_every_other_leg_runs_the_rest(self) -> None: if is_experimental(leg): # #1740: the experimental step's own worker count, 3 on GraalPy and `auto` on the rest. want[want.index('-n') + 1] = step_env(leg, EXPERIMENTAL)['WORKERS'] + # #1753: and its replacements for crashed workers, after `--dist load`. + want.insert(want.index('--dist') + 2, '--max-worker-restart=30') with self.subTest(python=version): self.assertNotIn('coverage', argv) self.assertEqual(argv[:2], ['-m', 'pytest'])