[core][test] Bound two unbounded waits that turn a test failure into a CI timeout - #65109
Conversation
There was a problem hiding this comment.
Code Review
This pull request introduces default timeouts when running driver scripts as separate processes and when reaping killed Ray processes, preventing unbounded waits that can cause CI test suites to hang. The reviewer identified a potential issue where calling proc.communicate() without a timeout after proc.kill() could still block indefinitely if the process is in an uninterruptible sleep state (D state), and suggested adding a timeout to these fallback calls.
CI status on
|
…a CI timeout ## Why are these changes needed? `//python/ray/tests:test_generators` and `//python/ray/dag:tests/experimental/test_compiled_graphs` are the two worst offenders in the RocksDB GCS premerge job. Both are reported as TIMEOUT/FLAKY at the *target* level, consuming the full Bazel budget on every attempt, even though the underlying failure is a single test case. Comparing premerge #70949, which ran the redis and rocksdb jobs on the same commit, the suite totals are effectively identical (29,427s redis vs 29,644s rocksdb, +0.7%), so there is no general backend latency tax. The damage is concentrated: target redis rocksdb ratio //python/ray/dag:.../test_compiled_graphs 1193.6s 3600.2s 3.02 FLAKY //python/ray/tests:test_generators 416.7s 915.1s 2.20 TIMEOUT Everything else is <=1.5x. And it is not a timing-margin problem: the retry of the same rocksdb shard passed test_generators in 343.7s, i.e. faster than redis. The distribution is bimodal, which points at a wedge rather than a slowdown. Reading the timeout dumps, both targets wedge on an unbounded wait that has nothing to do with the assertion under test: 1. `Node._kill_process_type` waits with `timeout=None` whenever the caller passes `wait=True`, which `Cluster.remove_node` always does. SIGKILL cannot reap a process parked in uninterruptible sleep, and a process blocked in the fsync that the RocksDB GCS issues on every write is exactly that. So `ray_start_cluster` teardown blocks forever. In the failing test_generators attempt, pytest-timeout fired at 180s and teardown then absorbed the remaining ~700s until Bazel killed the target at 900s -- twice, because of `--flaky_test_attempts=2`. One test-case failure cost 30 minutes of CI and was reported as TIMEOUT instead of a clean FAILED-then-retry. 2. `run_string_as_driver` / `run_string_as_driver_stdout_stderr` call `proc.communicate()` with no timeout, so a driver that hangs during shutdown blocks the test forever. That is precisely what test_compiled_graphs::test_async_shutdown does, and it is the point where that target's timeout dump lands. Neither wait is load-bearing: nothing depends on waiting *forever*, only on waiting long enough. ## What this changes - `Node._kill_process_type`: bound the post-SIGKILL wait at 30s even when `wait=True`, and log the pid and process type when it expires. Reaping is normally instantaneous, so this is inert in the healthy case; when it does expire, `Cluster.remove_node`'s existing `any_processes_alive()` assertion now reports a real error in seconds instead of hanging. - `run_string_as_driver` and `run_string_as_driver_stdout_stderr`: add a `timeout` parameter defaulting to 300s. On expiry, kill the driver, log whatever it produced, and re-raise `TimeoutExpired`. 300s is well above the 180s pytest-timeout that already governs almost every caller, so no existing blocking driver should be affected. Pass `timeout=None` to restore the old behaviour. This makes the failures bounded and attributable. It deliberately does not attempt to fix the underlying test-case flake, which is still under investigation and has not been reproduced outside CI (48/48 local runs of the four `test_dynamic_generator_reconstruction_nondeterministic` variants passed under both backends, with rocksdb showing no slowdown: median 68.9s vs 70.2s for the in-memory GCS). ## Related issue number Follow-up to ray-project#64702 (REP-64). Not a duplicate: no open PR touches these two waits. ## Checks - [x] I've signed off every commit (DCO). - [x] I've made sure the tests are passing. Tested locally: - `test_dynamic_generator_reconstruction_nondeterministic[None-False]` and `[None-True]` under `TEST_GCS_ROCKSDB=1`: 2 passed in 136.9s - `test_output.py -k test_disable_driver_logs_breakpoint`: 1 passed - direct exercise of all three `run_string_as_driver*` paths, including the new timeout path (kills the driver and raises `TimeoutExpired`) - `pre-commit run` clean on all three changed files AI assistance (GitHub Copilot CLI) was used for the CI log analysis and to draft these changes; every line was reviewed by me. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Signed-off-by: Santosh Jha <santosh.m.jha@gmail.com>
- run_string_as_driver / run_string_as_driver_stdout_stderr: bound the post-SIGKILL communicate() and fall back to the output captured before the first timeout. Also neutralize Popen.__exit__'s unbounded wait() when the driver survives SIGKILL, which would otherwise re-introduce the exact hang this change removes. - node.py: when a killed process is not reaped within the timeout, keep it in all_processes so live_processes / any_processes_alive still report it and teardown assertions such as Cluster.remove_node's actually fail. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Signed-off-by: Santosh Jha <santosh.m.jha@gmail.com>
kill_all_processes kills raylet and GCS explicitly and then iterates the remaining keys, so keeping unreaped processes in all_processes made those types pay KILLED_PROCESS_REAP_TIMEOUT_SECONDS twice. Track unreaped types and skip them on subsequent kill attempts; they stay in all_processes so liveness checks still report them. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Signed-off-by: Santosh Jha <santosh.m.jha@gmail.com>
580a1ce to
4adfa05
Compare
|
Rebased onto Final result of the previous run (#51110): The only hard failure was |
ray._common.utils.decode calls bytes.decode with strict error handling. A driver killed mid-write can leave a truncated multi-byte sequence, so building the log message would raise UnicodeDecodeError and mask the TimeoutExpired the caller needs to see. Decode with errors="replace" on that path only. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Signed-off-by: Santosh Jha <santosh.m.jha@gmail.com>
signal.SIGKILL is POSIX-only and these helpers also run in the Windows CI jobs, where referencing it would raise AttributeError before returncode was set, leaving Popen.__exit__ to wait unbounded again. Record a plain synthetic return code instead and drop the signal import. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Signed-off-by: Santosh Jha <santosh.m.jha@gmail.com>
There was a problem hiding this comment.
Cursor Bugbot has reviewed your changes using default effort and found 1 potential issue.
Reviewed by Cursor Bugbot for commit 97aca2d. Configure here.
Keeping an unreaped process in all_processes broke two invariants: the entry could never be removed, so start_gcs_server's 'not in all_processes' assert would fail on restart, and once the process finally died dead_processes() counted it, making remaining_processes_alive() report a failure for a process that was killed on purpose. Track them in a separate _unreaped_processes map instead. all_processes now behaves exactly as before, live_processes() additionally reports any unreaped process while it is running so teardown assertions still fire, and the explicit no-double-kill guard is no longer needed since the entry is gone from all_processes. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Signed-off-by: Santosh Jha <santosh.m.jha@gmail.com>
Code review follow-ups: - _kill_process_type and kill_all_processes document wait=True as "will not return until the process has exited". That is no longer strictly true, so say what happens when the reap times out. - Iterate a snapshot of _unreaped_processes in live_processes, which runs without removal_lock while _kill_process_impl can add a key under it. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Signed-off-by: Santosh Jha <santosh.m.jha@gmail.com>
Head branch was pushed to by a user without write access
CI triage for premerge #71139Two finished failures, neither caused by this PR. 1.
At 266s of a 300s budget on an unrelated PR, the target is at ~89% of budget on a good day, so any runner noise tips it over. The 618s figure is just Evidence it is not this PR:
I have deliberately not re-sized the target here: 2. AI assistance was used for this investigation. |
…a CI timeout (ray-project#65109) ## Why are these changes needed? `//python/ray/tests:test_generators` and `//python/ray/dag:tests/experimental/test_compiled_graphs` are the two worst offenders in the RocksDB GCS premerge job. Both are reported as TIMEOUT/FLAKY at the *target* level, consuming the full Bazel budget on every attempt, even though the underlying failure is a single test case. Comparing premerge [#70949](https://buildkite.com/ray-project/premerge/builds/70949), which ran the redis and rocksdb jobs on the same commit, the suite totals are effectively identical (**29,427s** redis vs **29,644s** rocksdb, +0.7%), so there is no general backend latency tax. The damage is concentrated: | target | redis | rocksdb | ratio | | |---|---|---|---|---| | `//python/ray/dag:.../test_compiled_graphs` | 1193.6s | 3600.2s | 3.02× | FLAKY | | `//python/ray/tests:test_generators` | 416.7s | 915.1s | 2.20× | TIMEOUT | | `//python/ray/tests:test_multi_node_3` | 162.1s | 207.9s | 1.28× | passing | Everything else is ≤1.5×. And it is not a timing-margin problem: the retry of the same rocksdb shard passed `test_generators` in **343.7s**, i.e. *faster* than redis. The distribution is bimodal, which points at a wedge rather than a slowdown. Reading the timeout dumps, both targets wedge on an unbounded wait that has nothing to do with the assertion under test: 1. `Node._kill_process_type` waits with `timeout=None` whenever the caller passes `wait=True`, which `Cluster.remove_node` always does. `SIGKILL` cannot reap a process parked in uninterruptible sleep, and a process blocked in the `fsync` that the RocksDB GCS issues on every write is exactly that. So `ray_start_cluster` teardown blocks forever. In the failing `test_generators` attempt, pytest-timeout fired at 180s and teardown then absorbed the remaining ~700s until Bazel killed the target at 900s — twice, because of `--flaky_test_attempts=2`. One test-case failure cost **30 minutes of CI** and was reported as TIMEOUT instead of a clean FAILED-then-retry. 2. `run_string_as_driver` / `run_string_as_driver_stdout_stderr` call `proc.communicate()` with no timeout, so a driver that hangs during shutdown blocks the test forever. That is precisely what `test_compiled_graphs::test_async_shutdown` does, and it is the point where that target's timeout dump lands. Neither wait is load-bearing: nothing depends on waiting *forever*, only on waiting long enough. ## What this changes - **`Node._kill_process_type`**: bound the post-SIGKILL wait at 30s even when `wait=True`, and log the pid and process type when it expires. Reaping is normally instantaneous, so this is inert in the healthy case; when it does expire, `Cluster.remove_node`'s existing `any_processes_alive()` assertion now reports a real error in seconds instead of hanging. - **`run_string_as_driver` / `run_string_as_driver_stdout_stderr`**: add a `timeout` parameter defaulting to 300s. On expiry, kill the driver, log whatever it produced, and re-raise `TimeoutExpired`. 300s is well above the 180s pytest-timeout that already governs almost every caller, so no existing blocking driver should be affected. Pass `timeout=None` to restore the old behaviour. This makes the failures **bounded and attributable**. It deliberately does not attempt to fix the underlying test-case flake, which is still under investigation and has not been reproduced outside CI — 48/48 local runs of the four `test_dynamic_generator_reconstruction_nondeterministic` variants passed under both backends, with rocksdb showing no slowdown (median **68.9s** vs **70.2s** for the in-memory GCS). ## Related issue number Follow-up to ray-project#64702 (REP-64). Not a duplicate — I checked open PRs and none touch these two waits. ## Checks - [x] I've signed off every commit (DCO). - [x] I've made sure the tests are passing. Tested locally: - `test_dynamic_generator_reconstruction_nondeterministic[None-False]` and `[None-True]` under `TEST_GCS_ROCKSDB=1`: **2 passed in 136.9s** - `test_output.py -k test_disable_driver_logs_breakpoint`: **1 passed** - direct exercise of all three `run_string_as_driver*` paths, including the new timeout path (kills the driver and raises `TimeoutExpired`) - `pre-commit run` clean on all three changed files AI assistance (GitHub Copilot CLI) was used for the CI log analysis and to draft these changes; every line was reviewed by me. --------- Signed-off-by: Santosh Jha <santosh.m.jha@gmail.com> Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Co-authored-by: Rueian <rueiancsie@gmail.com>
…a CI timeout (ray-project#65109) ## Why are these changes needed? `//python/ray/tests:test_generators` and `//python/ray/dag:tests/experimental/test_compiled_graphs` are the two worst offenders in the RocksDB GCS premerge job. Both are reported as TIMEOUT/FLAKY at the *target* level, consuming the full Bazel budget on every attempt, even though the underlying failure is a single test case. Comparing premerge [#70949](https://buildkite.com/ray-project/premerge/builds/70949), which ran the redis and rocksdb jobs on the same commit, the suite totals are effectively identical (**29,427s** redis vs **29,644s** rocksdb, +0.7%), so there is no general backend latency tax. The damage is concentrated: | target | redis | rocksdb | ratio | | |---|---|---|---|---| | `//python/ray/dag:.../test_compiled_graphs` | 1193.6s | 3600.2s | 3.02× | FLAKY | | `//python/ray/tests:test_generators` | 416.7s | 915.1s | 2.20× | TIMEOUT | | `//python/ray/tests:test_multi_node_3` | 162.1s | 207.9s | 1.28× | passing | Everything else is ≤1.5×. And it is not a timing-margin problem: the retry of the same rocksdb shard passed `test_generators` in **343.7s**, i.e. *faster* than redis. The distribution is bimodal, which points at a wedge rather than a slowdown. Reading the timeout dumps, both targets wedge on an unbounded wait that has nothing to do with the assertion under test: 1. `Node._kill_process_type` waits with `timeout=None` whenever the caller passes `wait=True`, which `Cluster.remove_node` always does. `SIGKILL` cannot reap a process parked in uninterruptible sleep, and a process blocked in the `fsync` that the RocksDB GCS issues on every write is exactly that. So `ray_start_cluster` teardown blocks forever. In the failing `test_generators` attempt, pytest-timeout fired at 180s and teardown then absorbed the remaining ~700s until Bazel killed the target at 900s — twice, because of `--flaky_test_attempts=2`. One test-case failure cost **30 minutes of CI** and was reported as TIMEOUT instead of a clean FAILED-then-retry. 2. `run_string_as_driver` / `run_string_as_driver_stdout_stderr` call `proc.communicate()` with no timeout, so a driver that hangs during shutdown blocks the test forever. That is precisely what `test_compiled_graphs::test_async_shutdown` does, and it is the point where that target's timeout dump lands. Neither wait is load-bearing: nothing depends on waiting *forever*, only on waiting long enough. ## What this changes - **`Node._kill_process_type`**: bound the post-SIGKILL wait at 30s even when `wait=True`, and log the pid and process type when it expires. Reaping is normally instantaneous, so this is inert in the healthy case; when it does expire, `Cluster.remove_node`'s existing `any_processes_alive()` assertion now reports a real error in seconds instead of hanging. - **`run_string_as_driver` / `run_string_as_driver_stdout_stderr`**: add a `timeout` parameter defaulting to 300s. On expiry, kill the driver, log whatever it produced, and re-raise `TimeoutExpired`. 300s is well above the 180s pytest-timeout that already governs almost every caller, so no existing blocking driver should be affected. Pass `timeout=None` to restore the old behaviour. This makes the failures **bounded and attributable**. It deliberately does not attempt to fix the underlying test-case flake, which is still under investigation and has not been reproduced outside CI — 48/48 local runs of the four `test_dynamic_generator_reconstruction_nondeterministic` variants passed under both backends, with rocksdb showing no slowdown (median **68.9s** vs **70.2s** for the in-memory GCS). ## Related issue number Follow-up to ray-project#64702 (REP-64). Not a duplicate — I checked open PRs and none touch these two waits. ## Checks - [x] I've signed off every commit (DCO). - [x] I've made sure the tests are passing. Tested locally: - `test_dynamic_generator_reconstruction_nondeterministic[None-False]` and `[None-True]` under `TEST_GCS_ROCKSDB=1`: **2 passed in 136.9s** - `test_output.py -k test_disable_driver_logs_breakpoint`: **1 passed** - direct exercise of all three `run_string_as_driver*` paths, including the new timeout path (kills the driver and raises `TimeoutExpired`) - `pre-commit run` clean on all three changed files AI assistance (GitHub Copilot CLI) was used for the CI log analysis and to draft these changes; every line was reviewed by me. --------- Signed-off-by: Santosh Jha <santosh.m.jha@gmail.com> Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Co-authored-by: Rueian <rueiancsie@gmail.com>

Why are these changes needed?
//python/ray/tests:test_generatorsand//python/ray/dag:tests/experimental/test_compiled_graphsare the two worst offenders in the RocksDB GCS premerge job. Both are reported as TIMEOUT/FLAKY at the target level, consuming the full Bazel budget on every attempt, even though the underlying failure is a single test case.Comparing premerge #70949, which ran the redis and rocksdb jobs on the same commit, the suite totals are effectively identical (29,427s redis vs 29,644s rocksdb, +0.7%), so there is no general backend latency tax. The damage is concentrated:
//python/ray/dag:.../test_compiled_graphs//python/ray/tests:test_generators//python/ray/tests:test_multi_node_3Everything else is ≤1.5×. And it is not a timing-margin problem: the retry of the same rocksdb shard passed
test_generatorsin 343.7s, i.e. faster than redis. The distribution is bimodal, which points at a wedge rather than a slowdown.Reading the timeout dumps, both targets wedge on an unbounded wait that has nothing to do with the assertion under test:
Node._kill_process_typewaits withtimeout=Nonewhenever the caller passeswait=True, whichCluster.remove_nodealways does.SIGKILLcannot reap a process parked in uninterruptible sleep, and a process blocked in thefsyncthat the RocksDB GCS issues on every write is exactly that. Soray_start_clusterteardown blocks forever. In the failingtest_generatorsattempt, pytest-timeout fired at 180s and teardown then absorbed the remaining ~700s until Bazel killed the target at 900s — twice, because of--flaky_test_attempts=2. One test-case failure cost 30 minutes of CI and was reported as TIMEOUT instead of a clean FAILED-then-retry.run_string_as_driver/run_string_as_driver_stdout_stderrcallproc.communicate()with no timeout, so a driver that hangs during shutdown blocks the test forever. That is precisely whattest_compiled_graphs::test_async_shutdowndoes, and it is the point where that target's timeout dump lands.Neither wait is load-bearing: nothing depends on waiting forever, only on waiting long enough.
What this changes
Node._kill_process_type: bound the post-SIGKILL wait at 30s even whenwait=True, and log the pid and process type when it expires. Reaping is normally instantaneous, so this is inert in the healthy case; when it does expire,Cluster.remove_node's existingany_processes_alive()assertion now reports a real error in seconds instead of hanging.run_string_as_driver/run_string_as_driver_stdout_stderr: add atimeoutparameter defaulting to 300s. On expiry, kill the driver, log whatever it produced, and re-raiseTimeoutExpired. 300s is well above the 180s pytest-timeout that already governs almost every caller, so no existing blocking driver should be affected. Passtimeout=Noneto restore the old behaviour.This makes the failures bounded and attributable. It deliberately does not attempt to fix the underlying test-case flake, which is still under investigation and has not been reproduced outside CI — 48/48 local runs of the four
test_dynamic_generator_reconstruction_nondeterministicvariants passed under both backends, with rocksdb showing no slowdown (median 68.9s vs 70.2s for the in-memory GCS).Related issue number
Follow-up to #64702 (REP-64). Not a duplicate — I checked open PRs and none touch these two waits.
Checks
Tested locally:
test_dynamic_generator_reconstruction_nondeterministic[None-False]and[None-True]underTEST_GCS_ROCKSDB=1: 2 passed in 136.9stest_output.py -k test_disable_driver_logs_breakpoint: 1 passedrun_string_as_driver*paths, including the new timeout path (kills the driver and raisesTimeoutExpired)pre-commit runclean on all three changed filesAI assistance (GitHub Copilot CLI) was used for the CI log analysis and to draft these changes; every line was reviewed by me.