Uncategorized

Exit code 0 is not evidence — six nights of a benchmark that measured nothing

6 min read

A benchmark ran every night for six nights, reported success every time, and measured nothing at all. The systemd unit exited cleanly. The result files were 84 bytes. Here is how a job lies to you with a zero, and the two small guards that make it stop.

The symptom

I run a nightly model comparison on a dual-GPU Linux box: tool-calling, vision description, nutrition estimation from photos. It fires at 01:00, takes about four hours, and writes one result file per scenario.

Checking on something unrelated, I noticed the run had finished in fifty seconds. Not four hours. Fifty seconds. The service log was calm:

nightly-bench.service: Deactivated successfully.
nightly-bench.service: Consumed 9.658s CPU time, 121.7M memory peak.

And the results:

-rw-r--r-- 1 root root  84 Aug 21 01:00 A-tools.txt
-rw-r--r-- 1 root root  85 Aug 21 01:00 B-vision.txt
-rw-r--r-- 1 root root  88 Aug 21 01:00 C-nutrition.txt

Byte-identical sizes across six nights. That is not variance. That is a constant, and a constant in a measurement is always a bug.

Defect A: the scripts were never really there

Each file held exactly one line:

python3: can't open file '/tmp/bench-agent.py': [Errno 2] No such file or directory

The three benchmark harnesses lived in /tmp. The machine had been reset, and /tmp did what /tmp is for. No copy existed anywhere — I searched every plausible directory and both containers before accepting that they were gone for good.

That is an embarrassing but ordinary mistake: a script that started as a throwaway experiment quietly became infrastructure, and nobody moved it. What follows is the interesting part.

Defect B: the script could not report a failure even if it wanted to

Every scenario ended with a line of this shape:

timeout 14400 python3 -u /tmp/bench-agent.py $LIST > "$OUT/A-tools.txt" 2>&1
echo "  End $(date '+%H:%M:%S'), return $?"

Read that $? again. It does not hold the exit status of python3. Bash performs the expansions in that string left to right, and the command substitution $(date …) runs a command. By the time $? is expanded, it holds the exit status of date — which is always 0.

The positive control takes one line:

$ false; echo "End $(date +%s), return $?"
End 1787236298, return 0

$ false; echo "return $?"
return 1

So the log dutifully printed return 0 while python was exiting 2. This defect had nothing to do with the missing files. It was sitting in that script the whole time, silently guaranteeing that no scenario failure could ever be reported — not this one, not any future one. Defect A was the accident. Defect B was the reason it stayed invisible for six nights.

The fix is trivial once you see it: capture the status as the very first instruction after the command.

timeout 14400 python3 -u "$LIB/bench-agent.py" ... > "$OUT/A-tools.txt" 2>&1
RC=$?                      # first instruction, before any substitution
echo "  End $(date '+%H:%M:%S'), return $RC"

The rule that falls out: exit 0 is not evidence

Both defects share a shape. Something reported success, and the success was structural rather than earned. A systemd Result=success tells you a process exited zero. It tells you nothing about whether that process did its job.

So the repaired runner no longer trusts return codes alone. Each scenario is checked on its output: minimum size, plus a grep for the signatures of a tool failure rather than a measurement.

check_output() {
    local name="$1" file="$2" rc="$3" min_bytes="${4:-500}"
    local size=0
    [ -r "$file" ] && size=$(stat -c %s "$file")
    [ "$rc" -ne 0 ] && { echo "  !! $name: harness returned $rc" >&2; FAILED=$((FAILED+1)); }
    if [ "$size" -lt "$min_bytes" ]; then
        echo "  !! $name: only $size bytes — that is not a measurement." >&2
        FAILED=$((FAILED+1)); return 1
    fi
    if grep -qE "can't open file|ModuleNotFoundError|Traceback" "$file"; then
        echo "  !! $name: output contains a tool error, not a result." >&2
        FAILED=$((FAILED+1)); return 1
    fi
}

Two details in there earn their keep. The guard tests -r (readable), not -s (non-empty) — stat needs no read permission, so a file you cannot read would otherwise pass a size check. And the size test alone is not enough: a Python traceback is comfortably larger than 500 bytes and would sail straight through. Size and content.

Then I tested the guard against the real failure — the actual 84-byte file from the last broken night — plus a large traceback, a missing file, and, crucially, a healthy file that must pass. Four cases, three caught, one let through. A guard you have only tested on failures is a guard that might reject everything.

The same class of error, twice in one afternoon

Later the same day I wanted to compare two inference server settings, so I launched the inference binary directly instead of through its usual manager. It came up. It answered. It reported:

prompt processing, n_tokens = 512, t = 38.91 s / 13.16 tokens per second

Thirteen tokens per second, on a card that does roughly a thousand. GPU memory had not moved. The manager normally ships its own CUDA backend libraries and points the binary at them through environment variables; launched bare, no GPU backend loaded, and the server quietly fell back to the CPU — while returning perfectly well-formed timing numbers.

Without a check, that run would have produced a complete, plausible, beautifully formatted comparison table of CPU numbers. So the A/B harness now asserts the thing it depends on, and refuses to report if it cannot prove it:

matches = re.findall(r"offloaded (\d+)/(\d+) layers to GPU", server_log)
if not matches:
    log("  !! No offload line in the server log — CPU fallback. Skipping.")
    continue
n, m = int(matches[-1][0]), int(matches[-1][1])
if n < m:
    log("  !! Only %d of %d layers on GPU — not a comparable measurement." % (n, m))
    continue

That guard then caught a failure I had not anticipated: an orphaned server process from an aborted run still held the port, so the new server could not bind and died, and the health check was cheerfully answered by the old process with the old settings. The guard did not know that story. It only knew it could not prove the GPU was in use, so it declined to produce a number. That is the correct behaviour, and it is why the assertion is worth more than the specific failure it was written for.

What I would take away

  • A constant in a measurement is a bug. Identical output sizes across runs is the cheapest smell there is, and it costs one ls -la to check.
  • Exit 0 means a process ended, not that it worked. Check the artefact, not the status.
  • Capture $? immediately. Anything between the command and the read — even a timestamp — can overwrite it.
  • Every diagnostic needs a positive control. A clean grep and a broken pattern look identical. Run something you know should trip it.
  • Assert your preconditions, not just your results. “Is the GPU actually being used” is a cheaper question than “why are these numbers strange”, and you can ask it automatically.

None of this is clever. All of it is the difference between six nights of data and six nights of 84-byte files that looked like success.