Timeouts and Tools That Never Return

Part II · Module 23 · Chapter 23.8 · Timeouts and Tools That Never Return

1. The Unbounded Call

cp = subprocess.run(cmd, cwd=run_dir)

That line waits for the tool. Not for an hour, not until something gives up — for as long as the tool takes, which for a hung simulation is until somebody notices.

In a sweep it is worse than it looks, because the loop is sequential:

RUNS = [("axi_smoke", 180), ("axi_reset", 240), ("axi_hang", None), ("axi_burst", 300)]

elapsed = 0
for test, seconds in RUNS:
    if seconds is None:
        print(f"{test:<11} started — never returns")
        print(f"{'':11}  and the {len(RUNS) - RUNS.index((test, seconds)) - 1} "
              f"tests after it never start")
        break
    elapsed += seconds
    print(f"{test:<11} finished after {seconds}s (total {elapsed}s)")

axi_smoke   finished after 180s (total 180s)
axi_reset   finished after 240s (total 420s)
axi_hang    started — never returns
             and the 1 tests after it never start

One hung test does not cost one result. It costs every result after it, plus the licence the hung tool is still holding, plus the compute slot. A nightly reporting nothing is usually one unbounded call away from reporting almost everything.

2. timeout= and TimeoutExpired

import sys
import time

print("UVM_INFO starting", flush=True)
time.sleep(float(sys.argv[1]))
print("TEST DONE", flush=True)

import subprocess
import sys

try:
    subprocess.run([sys.executable, "hang.py", "30"], timeout=0.5,
                   capture_output=True, text=True)
    print("finished normally")
except subprocess.TimeoutExpired as exc:
    print("raised  :", type(exc).__name__)
    print("timeout :", exc.timeout)
    print("cmd     :", [a.split("/")[-1] for a in exc.cmd])

raised  : TimeoutExpired
timeout : 0.5
cmd     : ['python3', 'hang.py', '30']

That is the canonical annotation:

try:
    subprocess.run(cmd, cwd=run_dir, timeout=3600)
except subprocess.TimeoutExpired:
    status = "TIMEOUT"

timeout= is a number of seconds. If the child has not finished by then, subprocess.run kills it and raises TimeoutExpired, which carries the command and the limit that was exceeded.

The killing is the part worth confirming, because a timeout that raises and leaves the tool running would be worse than none:

import sys
import time

print("UVM_INFO starting", flush=True)
time.sleep(float(sys.argv[1]))

import subprocess
import sys
import time

start = time.monotonic()
try:
    subprocess.run([sys.executable, "hang.py", "30"], timeout=0.5,
                   stdout=subprocess.DEVNULL)
except subprocess.TimeoutExpired:
    pass
waited = time.monotonic() - start

print("the child was told to sleep for :", 30, "seconds")
print("the timeout was                 :", 0.5, "seconds")
print("the call returned promptly      :", waited < 10)
print("not after the full sleep        :", waited < 25)

the child was told to sleep for : 30 seconds
the timeout was                 : 0.5 seconds
the call returned promptly      : True
not after the full sleep        : True

The booleans rather than the duration are deliberate: a measured time would differ on every machine, and the fact being established is structural — the call came back on the timeout, not on the child's own schedule.

3. Popen.wait(timeout=) Does Not Kill

Chapter 23.6's streaming loop uses Popen, and adding a timeout there behaves differently:

import sys
import time

print("UVM_INFO starting", flush=True)
time.sleep(float(sys.argv[1]))

import subprocess
import sys

proc = subprocess.Popen([sys.executable, "hang.py", "30"], stdout=subprocess.DEVNULL)

try:
    proc.wait(timeout=0.5)
except subprocess.TimeoutExpired:
    print("wait() raised")
    print("  is the child still running? :", proc.poll() is None)
    proc.kill()
    proc.wait()
    print("  after kill() and wait()     :", proc.poll() is not None)
    print("  returncode                  :", proc.returncode)
    print("  negative means a signal     :", proc.returncode < 0)

wait() raised
  is the child still running? : True
  after kill() and wait()     : True
  returncode                  : -9
  negative means a signal     : True

wait(timeout=) reports that the wait expired. It does not kill anything. proc.poll() is None immediately after, which Chapter 23.6 Section 3 established means still running.

That is a genuinely dangerous default if you do not know it. A streaming loop that catches TimeoutExpired and moves on leaves the tool running — holding a licence, writing to a log nobody is reading, and now with nothing watching it at all, because the script that started it has gone on to the next test. It is worse than no timeout, because at least an unbounded run is still waiting.

The fix is the three lines above, and the wait() after the kill() is not optional: kill() sends the signal and returns immediately, and wait() is what collects the child and fills in returncode.

The -9 is Chapter 23.4 Section 5's negative return code — SIGKILL, because that is what kill() sends.

4. What the Exception Carries

import sys
import time

print("UVM_INFO starting", flush=True)
print("UVM_INFO elaborated 1842 instances", flush=True)
time.sleep(float(sys.argv[1]))

import subprocess
import sys

for kwargs, label in (({"text": True}, "text=True only          "),
                      ({"text": True, "capture_output": True}, "text=True + capture     "),
                      ({"capture_output": True}, "capture only            ")):
    try:
        subprocess.run([sys.executable, "hang.py", "30"], timeout=0.5, **kwargs)
    except subprocess.TimeoutExpired as exc:
        print(f"{label} output is {type(exc.output).__name__:<9} {exc.output!r}")

UVM_INFO starting
UVM_INFO elaborated 1842 instances
text=True only           output is NoneType  None
text=True + capture      output is bytes     b'UVM_INFO starting\nUVM_INFO elaborated 1842 instances\n'
capture only             output is bytes     b'UVM_INFO starting\nUVM_INFO elaborated 1842 instances\n'

The two bare UVM_INFO lines at the top are the first case's child writing to the inherited terminal, because that case does not capture — Chapter 23.1 Section 3 again. Two things in the table itself, and the second is a trap.

The partial output survives. Whatever the tool had produced before the timeout is on the exception, which matters because it is the evidence for where it hung — Chapter 20.12 Section 4's last-activity question.

exc.output is bytes even with text=True. subprocess.run returning normally gives a str under text=True; TimeoutExpired does not. So this fails:

import sys
import time

print("UVM_INFO starting", flush=True)
print("UVM_INFO elaborated 1842 instances", flush=True)
time.sleep(float(sys.argv[1]))

import subprocess
import sys

try:
    subprocess.run([sys.executable, "hang.py", "30"], timeout=0.4,
                   capture_output=True, text=True)
except subprocess.TimeoutExpired as exc:
    try:
        last = [line for line in exc.output.splitlines() if line.startswith("UVM_INFO")]
        print("worked:", last)
    except TypeError as inner:
        print("TypeError:", inner)
        decoded = exc.output.decode("utf-8", errors="replace")
        last = [line for line in decoded.splitlines() if line.startswith("UVM_INFO")]
        print("after decoding:", last[-1])

TypeError: startswith first arg must be bytes or a tuple of bytes, not str
after decoding: UVM_INFO elaborated 1842 instances

A str comparison against bytes raises, and it raises only on the runs that timed out — which are precisely the ones nobody exercised while writing the handler. The fix is one decode, with errors="replace" for Chapter 23.5 Section 6's reason.

The cleanest escape is the one this module already recommends: send the tool's output to a log file rather than capturing it, and the partial log is on disk with no decoding question at all.

5. A Timeout Is Not a Failure

OUTCOMES = [
    ("axi_smoke", 0, None, "the tool ran and passed"),
    ("axi_reset", 1, None, "the tool ran and reported errors"),
    ("axi_hang", None, "timeout", "the tool never finished"),
    ("axi_build", 2, None, "the tool could not compile the design"),
]


def classify(rc, timed_out):
    if timed_out:
        return "NO_FINISH"
    if rc == 0:
        return "PASS"
    if rc == 2:
        return "COMPILE_ERROR"
    return "FAIL"


print(f"{'test':<11} {'status':<14} where it sends somebody")
for test, rc, timed_out, _ in OUTCOMES:
    status = classify(rc, timed_out)
    where = {"PASS": "nowhere",
             "FAIL": "the design or the testbench",
             "COMPILE_ERROR": "the RTL or the filelist",
             "NO_FINISH": "the testbench's end condition, or the timeout itself"}[status]
    print(f"{test:<11} {status:<14} {where}")

test        status         where it sends somebody
axi_smoke   PASS           nowhere
axi_reset   FAIL           the design or the testbench
axi_hang    NO_FINISH      the testbench's end condition, or the timeout itself
axi_build   COMPILE_ERROR  the RTL or the filelist

Chapter 20.11 Section 2 argued that FAIL and NO_FINISH are different outcomes because they send people to different places. A timeout is the clearest NO_FINISH there is.

And it is the one a flow can state with certainty. Chapter 20.12 had to infer that a log with no end-of-simulation banner was a hang, and Section 5 of that chapter listed four other things that produce the same symptom. Here the parent imposed the limit, so it knows: the tool was running, the clock ran out, the parent killed it. No inference, no ambiguity.

That makes timeout= worth having even where you expect it never to fire — it converts one of Chapter 20.12's four indistinguishable cases into a fact.

import sys
import time

print("UVM_INFO starting", flush=True)
time.sleep(float(sys.argv[1]))

import subprocess
import sys


def run_bounded(cmd, timeout_s, log_path):
    """Always returns a record. A timeout is an outcome, not an exception."""
    try:
        cp = subprocess.run(cmd, timeout=timeout_s, stdout=subprocess.DEVNULL)
        return {"rc": cp.returncode, "timed_out": False,
                "status": "PASS" if cp.returncode == 0 else "FAIL",
                "log": log_path, "limit_s": timeout_s}
    except subprocess.TimeoutExpired:
        return {"rc": None, "timed_out": True, "status": "NO_FINISH",
                "reason": "TIMEOUT", "log": log_path, "limit_s": timeout_s}


print(run_bounded([sys.executable, "-c", "pass"], 10, "a.log"))
print(run_bounded([sys.executable, "hang.py", "30"], 0.4, "b.log"))

{'rc': 0, 'timed_out': False, 'status': 'PASS', 'log': 'a.log', 'limit_s': 10}
{'rc': None, 'timed_out': True, 'status': 'NO_FINISH', 'reason': 'TIMEOUT', 'log': 'b.log', 'limit_s': 0.4}

Three decisions in that record are worth copying.

status stays NO_FINISH and reason is TIMEOUT — Chapter 20.12 Section 7's shape, so a summary counting Chapter 20.11's four statuses needs no change when a new reason appears.

rc is None, because there was no exit status. The tool did not report anything; it was stopped. Recording -9 there would be the signal the parent sent, which says nothing about the tool.

limit_s is in the record. A NO_FINISH at 3600 seconds and one at 60 are different conversations, and the second is usually "the timeout is too short" rather than "the test hangs". Without the limit in the record nobody can tell.

6. Choosing the Number

The timeout is a policy value, and three rules make it a decision rather than a guess:

Base it on observed runtimes, with headroom. Chapter 21.1's runtime_s field is the data: a test that has taken 180 to 240 seconds for a month gets a limit well above its worst, not just above its average. A limit set at the mean fires on half the runs.

Per test, not per flow. A smoke test and a gate-level soak differ by two orders of magnitude, and one global limit is either useless for the first or ruinous for the second — Chapter 21.6's per-test override is exactly this.

Bound the sweep as well as the test. Four hundred tests at an hour each is an arithmetic problem no individual timeout solves.

DEFAULT_TIMEOUT_S = 3600
PER_TEST = {"axi_smoke": 600, "axi_soak": 28800}
OBSERVED = {"axi_smoke": 240, "axi_reset": 300, "axi_soak": 21000, "axi_new": None}


def timeout_for(test):
    return PER_TEST.get(test, DEFAULT_TIMEOUT_S)


print(f"{'test':<11} {'observed':>9} {'limit':>7} {'headroom':>9}")
for test in ["axi_smoke", "axi_reset", "axi_soak", "axi_new"]:
    limit = timeout_for(test)
    observed = OBSERVED[test]
    headroom = f"{limit / observed:.1f}x" if observed else "unknown"
    print(f"{test:<11} {str(observed):>9} {limit:>7} {headroom:>9}")

test         observed   limit  headroom
axi_smoke         240     600      2.5x
axi_reset         300    3600     12.0x
axi_soak        21000   28800      1.4x
axi_new          None    3600   unknown

Read the axi_soak row. 1.4× headroom on a six-hour test is tight, and a machine under load will trip it — producing a NO_FINISH that is a false alarm and costs six hours of compute. The axi_reset row is the opposite: 12× is generous, so a genuine hang burns an hour before anyone hears about it.

Neither is wrong, and the table is the point: the headroom is the number to look at, not the limit. A limit with no observed runtime behind it — axi_new — is a guess, and a new test is exactly where a hang is most likely.

7. The Partial Log Is the Evidence

import sys
import time

print("UVM_INFO @ 0: reporter [RNTST] Running test axi_hang...", flush=True)
print("UVM_INFO drv.sv(60) @ 141700: issuing write", flush=True)
print("UVM_INFO drv.sv(62) @ 141800: waiting for response", flush=True)
time.sleep(float(sys.argv[1]))
print("TEST DONE", flush=True)

import subprocess
import sys
from pathlib import Path

log_path = Path("sim.log")
timed_out = False

with open(log_path, "w", encoding="utf-8") as handle:
    try:
        subprocess.run([sys.executable, "hang.py", "30"], timeout=0.6,
                       stdout=handle, stderr=subprocess.STDOUT)
    except subprocess.TimeoutExpired:
        timed_out = True

lines = log_path.read_text(encoding="utf-8", errors="replace").strip().splitlines()
print("timed out    :", timed_out)
print("log lines    :", len(lines))
print("last activity:", lines[-1] if lines else "<empty>")
print("finished?    :", any("TEST DONE" in line for line in lines))

timed out    : True
log lines    : 3
last activity: UVM_INFO drv.sv(62) @ 141800: waiting for response
finished?    : False

The log survived the timeout, because it was going to a file rather than into the exception — Chapter 23.5's recommendation paying off a second time.

Three lines, ending with the driver waiting for a response, is exactly what a debugger needs: Chapter 20.12 Section 4's last activity, naming the component and the simulation time it stopped at. A NO_FINISH record pointing at that line is actionable; one that only says "timed out" is not.

The caution from Chapter 23.6 Section 5 applies here and is worth repeating: those are the last lines the tool flushed, not necessarily the last thing it did. A buffering tool killed at its limit loses whatever was still held, so the gap between the last logged line and the actual hang can be real. The example's flush=True is what makes the demonstration deterministic; a real tool may not be so helpful.

8. What a Timeout Cannot Reach

One honest limit. Killing a child does not kill processes that child started:

your script
   └── vcs            <- killed by timeout=
         └── simv     <- a grandchild; still running
               └── ...

EDA tools do this constantly — a wrapper script that launches the real binary, a compile driver that forks a C compiler, a simulator that spawns a waveform writer. subprocess.run(timeout=) kills the process it started, and anything that process started is unaffected and now has no parent watching it.

This is not demonstrated here deliberately: a correct demonstration would leave stray processes behind in the environment that verifies these examples, and a wrong one would leave them behind permanently.

The technique that does reach them is to put the child in its own process group and signal the group rather than the process — start_new_session=True on the call, then os.killpg with the child's process group id. Two cautions make it a deliberate choice rather than a default: it is POSIX-only, and signalling a group will reach everything in it, so getting the grouping wrong is a blunt instrument.

For most flows the pragmatic answer is different and worth stating plainly: the scheduler is better at this than your script is. LSF, SLURM and their equivalents track the whole process tree of a job and can terminate all of it, which is one of the things they exist for. A Python timeout is the inner bound that keeps a sweep moving; the scheduler's limit is the outer one that actually cleans up. A flow wants both, and Chapter 23.4 Section 5's SIGTERM is what the outer one looks like when it fires.

9. Predict, Run, Observe

import sys
import time

print("started", flush=True)
time.sleep(float(sys.argv[1]))
print("finished", flush=True)

import subprocess
import sys

# A
try:
    cp = subprocess.run([sys.executable, "hang.py", "0.01"], timeout=10,
                        capture_output=True, text=True)
    print("A:", cp.returncode, repr(cp.stdout.strip()))
except subprocess.TimeoutExpired:
    print("A: timed out")

# B
try:
    subprocess.run([sys.executable, "hang.py", "30"], timeout=0.4, capture_output=True)
except subprocess.TimeoutExpired as exc:
    print("B:", type(exc).__name__, exc.timeout)

# C
try:
    subprocess.run([sys.executable, "hang.py", "30"], timeout=0.4,
                   capture_output=True, text=True)
except subprocess.TimeoutExpired as exc:
    print("C:", type(exc.output).__name__)

# D
try:
    subprocess.run([sys.executable, "hang.py", "30"], timeout=0.4, text=True)
except subprocess.TimeoutExpired as exc:
    print("D:", exc.output)

# E
proc = subprocess.Popen([sys.executable, "hang.py", "30"], stdout=subprocess.DEVNULL)
try:
    proc.wait(timeout=0.4)
except subprocess.TimeoutExpired:
    print("E:", proc.poll() is None)
    proc.kill()
    proc.wait()

# F
print("F:", proc.returncode)

The verified output:

A: 0 'started\nfinished'
B: TimeoutExpired 0.4
C: bytes
started
D: None
E: True
F: -9

A — a tool that finishes inside the limit behaves exactly as before; timeout= costs nothing when it does not fire.

B — the exception carries the limit that was exceeded.

C — exc.output is bytes despite text=True. Section 4.

D — without capture_output, there is no output on the exception at all — and the stray started above it is where that output actually went: straight to the terminal, inherited, per Chapter 23.1 Section 3. Nothing was holding it, so there was nothing to attach.

E — after wait(timeout=) raises, the child is still running.

F — after kill() and wait(), the status is -9: killed by SIGKILL.

10. Exercises

Exercise 1 — the cost of one. For a sweep of your own, work out what one unbounded hung test costs in results, licence-hours and compute.

Exercise 2 — bound it. Add timeout= to a call and confirm TimeoutExpired names the limit.

Exercise 3 — the child dies. Confirm a timed-out subprocess.run returns on the timeout rather than on the child's own schedule.

Exercise 4 — Popen does not. Call wait(timeout=) on a hung child and check poll() immediately afterwards. Record what you find.

Exercise 5 — clean it up. Add kill() and wait() and confirm the status becomes negative. Name the signal.

Exercise 6 — why wait() after kill(). Say what is missing if you skip it.

Exercise 7 — the bytes trap. Call .splitlines() and .startswith("x") on exc.output with text=True. Record the exception and fix it with one decode.

Exercise 8 — when it appears. Say why that TypeError only shows up on timed-out runs.

Exercise 9 — not a failure. Write a classify where a timeout is NO_FINISH. For each status, say where it sends somebody.

Exercise 10 — certainty. Explain in two sentences why a timeout is the one NO_FINISH a flow can state without inference, and contrast it with Chapter 20.12's four causes.

Exercise 11 — the record. Produce a timeout record with rc of None, a reason and the limit. Say what each of the three buys a reader.

Exercise 12 — headroom. Build the headroom table for four of your own tests. Identify the tightest and say what a loaded machine would do to it.

Exercise 13 — nobody believes it. Describe what happens to a team's reading of NO_FINISH if three tests trip their limits every night.

Exercise 14 — the partial log. Time out a tool writing to a log file and recover its last activity. Say why capturing instead would have been worse.

Exercise 15 — grandchildren. Draw the process tree for a tool in your flow that launches another binary. Say which parts a timeout= reaches.

11. Summary

• An unbounded tool call waits as long as the tool takes, and in a sequential sweep one hung test costs every result after it.
• timeout= is seconds; subprocess.run kills the child and raises TimeoutExpired carrying the command and the limit.
• The call returns on the timeout, not on the child's schedule — the kill is part of what run does.
• Popen.wait(timeout=) does not kill anything. The child is still running when it raises, and a loop that catches and moves on leaves a tool running with nothing watching it.
• kill() then wait() — the second collects the child and fills in returncode, which will be negative.
• A with block around Popen waits for the child, which on a hung tool means forever; it is not a limit.
• The partial output survives on the exception, and exc.output is bytes even with text=True — so a str comparison raises on exactly the runs nobody tested.
• Writing the tool's output to a log file avoids the question entirely, and leaves the evidence on disk.
• A timeout is NO_FINISH, not FAIL — Chapter 20.11's distinction, and the two send people to different places.
• It is the one NO_FINISH a flow can state with certainty, because the parent imposed the limit rather than inferring it from a missing banner.
• Record status as NO_FINISH with reason of TIMEOUT, rc as None, and the limit itself — a NO_FINISH at 60 seconds and one at 3600 are different conversations.
• Choose the limit from observed runtimes with headroom, per test rather than per flow, and bound the sweep too.
• Look at the headroom, not the limit. A tight one on a long test produces false alarms; a generous one on a short test hides real hangs for an hour.
• A timeout that fires routinely stops being believed, and the night a real deadlock appears it is in the noise.
• Killing a child does not kill its grandchildren. Process groups reach them on POSIX, and the scheduler's own limit is the outer bound that actually cleans up.

The next chapter is about the failures that happen before any of this — when there is no child to time out because the tool never started.