Files
Model-Optimizer/tests/_test_utils/examples/run_command.py
T
Keval MorabiaandClaude Opus 5 6a2ae5a25b Fix the llm_eval timeout: reachable MMLU mirror + no pipe deadlock (#2270)
### What does this PR do?

Type of change: Bug fix

`tests/examples/llm_eval/test_llm_eval.py::test_qwen3_eval_fp8` has been
failing with `Failed: Timeout (>900.0s) from pytest-timeout` on
unrelated branches (runs 33027056246 and the one for `ad83a428`, while
the 2026-08-24 nightly passed). It is not the test being slow — it is
the harness deadlocking, and the deadlock also destroys the diagnostics
that would explain the underlying kill.

**Mechanism.** The traceback shows `self = <Popen: returncode: -9 args:
['scripts/huggingface_example.sh', ...]>` while still blocked in
`stdout.read()`. The launcher was SIGKILLed (nothing in pytest sends
SIGKILL — pytest-timeout raises in the main thread, and the test's
`finally` `pkill` sends SIGTERM and only runs afterwards — so an OOM
kill is the likely source). But `subprocess.run(..., stdout=PIPE,
stderr=STDOUT)` waits for **EOF on the pipe**, not for the process, and
a surviving grandchild (the TRT-LLM serve/build worker) still holds the
write end. EOF never arrives, so the test blocks until the 900 s alarm.
Because the pipe is never drained, **every line of child output is
discarded**, which is why the CI log says nothing about what the script
was doing when it died.

Reduced to a self-contained reproducer:

```python
script = "sleep 300 & echo 'launcher output'; sleep 0.3; kill -9 $$"
subprocess.run(["bash", "-c", script], stdout=PIPE, stderr=STDOUT, text=True, timeout=20)
# -> TimeoutExpired: still blocked in communicate() after 20.0s, output lost
```

**Fix.** `_run_capturing` now starts the command in its own session,
drains its output on a reader thread (so logs stream as they arrive
instead of being buffered until the end), waits on the *process*, and
kills the process group if descendants still hold the pipe after a 30 s
grace period. A killed launcher now fails in seconds with its logs
intact instead of silently burning the test's whole timeout.

This does not fix whatever kills the script; it makes it diagnosable.
Worth noting separately: `test_qwen3_eval_fp8` took **749.10 s against
its 900 s mark** on the last green nightly, so it is fragile regardless
and may want its work trimmed or its budget raised once the logs show
where the time goes.

### Usage

```python
# unchanged public API
run_example_command(cmd_parts, example_path="llm_eval")
```

### Testing

Verified against the reproducer above and on the normal paths:

| scenario | before | after |
| --- | --- | --- |
| launcher SIGKILLed, survivor holds the pipe | blocks indefinitely (900
s in CI) | `rc=-9` in 3.5 s, `'launcher output'` captured |
| the surviving descendant | keeps running | killed with the process
group (stopped ticking, 20 -> 20 bytes) |
| normal exit | ok | `rc=0`, stdout and stderr interleaved in order |
| non-zero exit | ok | `rc=3`, output captured |

The example-test suites that use this helper run through the same code
path; `tests/examples/megatron_bridge` (16 passed, 1 skipped) exercised
it on nemo:26.08 in the branch this was extracted from.

### Before your PR is "*Ready for review*"

- Is this change backward compatible?: ✅ — `_run_capturing` keeps its
`(returncode, output)` contract; only the buffering strategy changed.
- If you copied code from any other sources or added a new PIP
dependency, did you follow guidance in `CONTRIBUTING.md`: N/A
- Did you write any new necessary tests?: ❌ — this is test
infrastructure; the scenario needs a process that outlives a SIGKILLed
parent, which is awkward to assert in CI. Verified manually with the
reproducer above.
- Did you update
[Changelog](https://github.com/NVIDIA/Model-Optimizer/blob/main/CHANGELOG.rst)?:
N/A — test-infrastructure fix.
- Did you get Claude approval on this PR?: ❌

🤖 Generated with [Claude Code](https://claude.com/claude-code)


<!-- This is an auto-generated comment: release notes by coderabbit.ai
-->
## Summary by CodeRabbit

* **Bug Fixes**
* Improved command execution reliability with real-time output capture.
* Ensured lingering child processes are cleaned up after commands exit
or are interrupted.
  * Added warnings when forced cleanup may truncate output.
  * Prevented hangs when descendant processes keep output streams open.

* **Documentation**
* Updated MMLU setup instructions to use the Hugging Face dataset
repository.
  * Improved Windows instructions by explicitly using `curl.exe`.

* **Examples**
* Improved MMLU downloads with retries, separate timeouts, resume
support, and automatic temporary-file cleanup.
<!-- end of auto-generated comment: release notes by coderabbit.ai -->

---

### Update: the second half of the failure

With the streaming fix in place, the next CI run showed the *actual*
cause, which the old code had been hiding. That run blocked in
`process.wait()` with `<Popen: returncode: None ...>` — child alive and
working, not the previous dead-child pipe deadlock — and the now-visible
output was:

```
--2026-08-27 18:09:20--  (try: 4)  https://people.eecs.berkeley.edu/~hendrycks/data.tar
Connecting to people.eecs.berkeley.edu ...|128.32.139.28|:443... failed: Connection timed out.
Retrying.
--2026-08-27 18:11:40--  (try: 5)  ...
```

`huggingface_example.sh` downloads the MMLU tarball from
`people.eecs.berkeley.edu`, that host stopped answering around
2026-08-25, and wget's default retry policy (20 tries, ~2 min per
connect timeout) consumed the whole 900 s budget. Not runner-specific:
the URL also times out from a developer workstation, and the nightlies
flipped 08-24 ✅ / 08-25 ✅ / **08-26 ❌ / 08-27 ❌**, matching the outage.

So this PR now carries both halves of the same failure:

1. the harness no longer deadlocks and no longer swallows the logs
(`985809cc2d`), and
2. the MMLU data comes from HuggingFace's copy of the same tarball, with
bounded retries (`40f1d89154`).

The mirror is byte-for-byte the same dataset in the same layout the
script already expects — verified by running the exact download/extract
commands:

```
https://huggingface.co/datasets/cais/mmlu/resolve/main/data.tar  ->  HTTP 200, 166 MB
data/mmlu/{dev,test,val}/  ->  57 subject CSVs each, plus auxiliary_train/
```

`wget --timeout=20 --tries=3` plus an explicit error means the next
dataset-host outage fails in about a minute with "Could not download the
MMLU test data. Set MMLU_DATA_PATH to a local copy." instead of silently
eating a test's timeout. The same URL is updated in
`examples/llm_eval/README.md` so a manual run does not hit the dead host
either.

---------

Signed-off-by: Keval Morabia <28916987+kevalmorabia97@users.noreply.github.com>
Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-28 21:38:25 +05:30

179 lines
6.7 KiB
Python

# SPDX-FileCopyrightText: Copyright (c) 2023-2025 NVIDIA CORPORATION & AFFILIATES. All rights reserved.
# SPDX-License-Identifier: Apache-2.0
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
# http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.
"""Utility functions for running example commands reused in multiple example tests."""
import contextlib
import os
import signal
import subprocess
import threading
import time
import warnings
from pathlib import Path
from _test_utils.torch.distributed.utils import get_free_port
MODELOPT_ROOT = Path(__file__).parents[3]
# Substrings that identify a *transient* HuggingFace Hub / dataset access failure
_HF_TRANSIENT_MARKERS = (
"HfHubHTTPError",
"Too Many Requests",
"500 Server Error",
"502 Bad Gateway",
"503 Server Error",
"504 Server Error",
"Bad Gateway",
"Service Unavailable",
"Gateway Time-out",
"ConnectionError",
"ReadTimeout",
"ConnectTimeout",
"Max retries exceeded",
"NewConnectionError",
"Connection reset by peer",
"Connection aborted",
"Consistency check failed", # partial / interrupted HF download
"couldn't connect to 'https://huggingface.co'",
"Couldn't reach", # datasets: "Couldn't reach <repo> on the Hub"
"Temporary failure in name resolution", # transient DNS
"Name or service not known", # transient DNS
)
_HF_MAX_RETRIES = 1
_HF_RETRY_DELAY_S = 10
def extend_cmd_parts(cmd_parts: list[str], **kwargs):
for key, value in kwargs.items():
if value is not None:
cmd_parts.extend([f"--{key}", str(value)])
if kwargs.get("trust_remote_code", False):
cmd_parts.append("--trust_remote_code")
return cmd_parts
# Grace period for descendants to flush and close the inherited output pipe after the command exits,
# then a short bound on the post-SIGKILL drain (the fds close as the kernel tears the group down).
_ORPHAN_PIPE_TIMEOUT_S = 30
_KILLED_PIPE_TIMEOUT_S = 5
def _run_capturing(cmd_parts: list[str], cwd: Path, env: dict[str, str]) -> tuple[int, str]:
"""Run a command, streaming and capturing combined stdout/stderr to catch transient HF errors.
Drained by a reader thread rather than ``subprocess.run``, which waits for EOF: a descendant
outliving the command keeps the pipe open, hanging the read and discarding every log line.
"""
chunks: list[str] = []
process = subprocess.Popen(
cmd_parts,
cwd=cwd,
env=env,
stdout=subprocess.PIPE,
stderr=subprocess.STDOUT,
text=True,
start_new_session=True,
)
# start_new_session makes the child its own group leader, so the group id is its pid (read now:
# os.getpgid() stops resolving it once wait() reaps the child).
pgid = process.pid
def _kill_process_group():
with contextlib.suppress(ProcessLookupError, PermissionError):
if os.name == "posix":
os.killpg(pgid, signal.SIGKILL)
else: # no process groups; the command itself is the best we can reach
process.kill()
def _drain():
with contextlib.suppress(ValueError): # the stream is closed under us on the escape path
for line in process.stdout: # type: ignore[union-attr]
print(line, end="")
chunks.append(line)
reader = threading.Thread(target=_drain, daemon=True)
reader.start()
try:
if os.name == "posix":
# Wait *without* reaping: a reaped pid can be recycled, and pgid == the child's pid, so
# reaping before the kill below would risk signalling an unrelated group.
os.waitid(os.P_PID, process.pid, os.WEXITED | os.WNOWAIT)
else: # no process groups, so nothing to protect the pid for
process.wait()
except BaseException:
# Interrupted (most likely pytest-timeout) while the command runs: its own process group is
# not swept up with pytest's, so take the descendants down rather than leak them.
_kill_process_group()
with contextlib.suppress(Exception):
process.wait(timeout=_KILLED_PIPE_TIMEOUT_S) # reap: WNOWAIT left it waitable
raise
reader.join(_ORPHAN_PIPE_TIMEOUT_S)
if reader.is_alive():
warnings.warn(
f"{cmd_parts[0]} left descendants holding its output pipe open; killing the process "
"group. Output may be truncated."
)
_kill_process_group()
reader.join(_KILLED_PIPE_TIMEOUT_S)
returncode = process.wait()
with contextlib.suppress(Exception):
process.stdout.close() # type: ignore[union-attr]
return returncode, "".join(chunks)
def run_example_command(
cmd_parts: list[str],
example_path: str,
setup_free_port: bool = False,
env: dict[str, str] | None = None,
hf_max_retries: int = _HF_MAX_RETRIES,
hf_retry_delay_s: int = _HF_RETRY_DELAY_S,
) -> str | None:
"""Run an example command, retrying transient HuggingFace access errors."""
print(f"[{example_path}] Running command: {cmd_parts}")
env = env or os.environ.copy()
cwd = MODELOPT_ROOT / "examples" / example_path
for attempt in range(hf_max_retries + 1):
if setup_free_port:
env["MASTER_PORT"] = str(get_free_port()) # fresh port per attempt
returncode, output = _run_capturing(cmd_parts, cwd, env)
if returncode == 0:
return output
transient = any(marker in output for marker in _HF_TRANSIENT_MARKERS)
if not transient or attempt == hf_max_retries:
raise subprocess.CalledProcessError(returncode, cmd_parts)
warnings.warn(
f"[{example_path}] transient HuggingFace access error; retrying in "
f"{hf_retry_delay_s}s (attempt {attempt + 1}/{hf_max_retries})"
)
time.sleep(hf_retry_delay_s)
def run_hf_ptq_command(*, model: str, quant: str | None = None, vlm: bool = False, **kwargs):
kwargs.update({"model": model, "quant": quant})
kwargs.setdefault("tasks", "quant")
kwargs.setdefault("calib", 16)
cmd_parts = ["scripts/huggingface_example.sh", "--no-verbose"]
if vlm:
# VLM PTQ shares the hf_ptq entry point; --vlm runs the multimodal deploy smoke test.
cmd_parts.append("--vlm")
cmd_parts = extend_cmd_parts(cmd_parts, **kwargs)
run_example_command(cmd_parts, "hf_ptq")