The benchmark said it was waiting. Once.

· 14 min read
Contents

At 12:36 on 25 October the proxy learned to see the A9's benchmark between two of its jobs. At 12:58 it learned to see the benchmark waiting behind the proxy's own engine. At 13:14 it learned that the benchmark mentions the waiting exactly once. At 13:59 it learned that once means once for the whole queue, not once per job. Four commits on a feature branch in 83 minutes, and each one found somewhere else the benchmark could be. Four more review passes went over them before any of it shipped, as v0.3.1, at 15:16.

The rule they serve is mine, from the day before: nothing on the A9's benchmark side gets stopped or paused. The proxy may only refuse, with a 423 that says the GPU is busy (why 423 and not 503). The A9 is a 128 GB Strix Halo box that runs a file-based job queue for days at a time (the queue, and every way it went quiet): a runner in Python, a directory per job state, and an events.jsonl with one line per state change. The proxy answers for the A9 and the 3090 box alike and starts its own llama.cpp engines on them when a request needs one (how it switches).

Between two jobs, nothing was there#

Until 12:36, "something else owns the GPU" meant one of six things the proxy's agent on the box could see: a benchmark systemd unit, a GPU owner file held by someone else, a llama-server outside the proxy's own engine units, a Strata container, a listener on the bench's port 8099, or the engine port in use while none of the proxy's engines runs. While a benchmark job runs its server, that's enough. Between two jobs, none of them is there.

A request for an a9-* model in that moment would find the GPU free, start the proxy's engine and get its answer. The runner's next gpu job would then find a llama-server it didn't start, log a gpu-wait and wait: until the proxy's idle stop, fifteen minutes after the last request, or for good under steady traffic. A paused benchmark, courtesy of the one program whose rule about it was not to pause it.

The rule I set that day reads the queue's own directories. Any job in running/, of any lane, means the GPU is taken: the runner never runs a download and a gpu job together, so a download in running/ is already holding the next gpu job back. So do the two minutes after running/ last changed (jobGap = 2 * time.Minute), which cover the space between one job leaving it and the next arriving:

for _, e := range entries {
	p := filepath.Join(running, e.Name())
	if fi, err := os.Stat(p); strings.HasSuffix(e.Name(), ".job") && err == nil && fi.Mode().IsRegular() { // follows a symlink; a FIFO would block the read
		busy = append(busy, "bench job "+e.Name()+" ("+jobLane(p)+" lane) is in "+running)
	}
}
now := time.Now
if a.Now != nil {
	now = a.Now
}
// A time in the future (a clock stepped back, touch -d) says nothing about the gap: ignored.
if age := now().Sub(info.ModTime()); len(busy) == 0 && age >= 0 && age < jobGap {
	busy = append(busy, fmt.Sprintf("bench job queue %s changed %s ago (the runner may start its next job)", running, age.Round(time.Second)))
}

queue/ doesn't count at all. On the A9 it is refilled on purpose: a seed script puts finished jobs back, and the runner skips each one, without touching running/, once its lane is free and its DONE_IF says it's done. Jobs whose REQUIRES line is still false can sit there for days as well. That day queue/ held 223 job files, 191 of them gpu jobs, and 220 of the 223 were finished runs put back on purpose. A rule that read "anything queued means busy" would have closed the A9 to the proxy for good, and looked careful the whole time.

Two minutes has evidence behind it. The runner reaps a finished job and starts the next one in the same pass of its loop, and it moves a job into running/ before it starts the job's process. The first review pass counted the transitions in the A9's event log, reading it without touching anything: of 278 times one job finished and the next one started, 268 took two minutes or less, 228 of them inside the same second. The other ten come back in a moment.

A waiting benchmark leaves running/ alone#

The same review pass found where the benchmark goes when the proxy's engine is the one in the way. The runner checks for a GPU process it didn't start before it moves a gpu job. When it finds one, it leaves the job where it is and tries again at the next tick, and since its first day it also writes an event:

if lane == "gpu":
    fp = foreign_gpu_user(own)
    if fp:
        if fp != getattr(self, "_waited_on", None):  # log each blocker once
            try:
                cmd = open(f"/proc/{fp}/cmdline").read().replace("\0", " ")[:200]
                ppid = open(f"/proc/{fp}/stat").read().rsplit(")", 1)[1].split()[1]
            except OSError:
                cmd, ppid = "?", "?"
            self.event(name, "gpu-wait", pid=fp, ppid=ppid, cmd=cmd)
            self._waited_on = fp
        return  # someone else owns the GPU; try again next tick

The job stays in queue/. running/ stays empty and keeps aging, so after two minutes the agent reports no owner at all, while a benchmark job sits waiting for the proxy to leave. That state isn't exotic. It's what happens whenever the proxy starts an engine during an idle stretch and the queue gets work afterwards. Eight of the event log's ten gaps longer than two minutes ended in a re-seed or a runner restart, and in each of them an engine started during the gap would have left the next gpu job waiting behind it. In the other two, the runner was already logging a gpu-wait.

The runner already writes the signal. The 12:58 commit reads the end of events.jsonl: if the last gpu-wait has no start after it and the process it names is still alive, a benchmark job is waiting for the GPU. New work for the A9 then gets a 423, and the proxy stops its engine as soon as nothing is running on it. Streams in flight finish first, and the benchmark gets the GPU when they do. Nothing changed on the bench side, which matters, because the bench side is the part I don't touch.

gpu-wait is logged once per blocker#

The second review pass found the hole in that. The 12:58 version ended a wait on any start event, and the runner starts the net lane first and the cpu lane next to anything. So a download added to the queue starts while the gpu job waits, and its start line ends the wait as far as the proxy can tell. When the download finishes, the gpu job goes back to waiting on the same llama-server, and the runner logs that once per blocker: _waited_on keeps the blocker's pid and is never reset, so a second wait on the same process writes nothing at all. Invisible again.

There's history in that line. The gpu-wait event exists because on the queue's first day a gpu job waited 2 hours 16 minutes behind a GPU process the runner hadn't started and logged nothing (that silence is here). The fix made the wait say so. It says so once per blocker, and considers the matter settled.

The 13:14 commit ended a wait only on a gpu-lane start, or when the waiting job itself left the queue some other way: skipped, done, failed or parked. The third review pass found that the second half reopened the same hole one job further down. When the waiting job is skipped, because its DONE_IF came true, the next runnable gpu job meets the same blocker in the same pass of the loop, and the runner, having logged that pid already, says nothing at all. A waiting job can't log done or failed without a gpu start first, and the runner never logs parked. The 13:59 commit ends a wait on a gpu-lane start, a runner restart (the new runner logs its wait again) or a runner stop, and on nothing the waiting job does by itself:

switch ev.Event {
case "gpu-wait":
	wait.TS, wait.Job, wait.PID, wait.PPID, waiting = ev.TS, ev.Job, ev.PID, strings.Trim(string(ev.PPID), `"`), true
case "start":
	if ev.Lane == "gpu" { // a net/cpu start leaves the gpu job waiting, and the runner logs no new gpu-wait
		waiting = false
	}
case "runner-start", "stopped": // a restarted runner logs its wait again; a stopping one waits for nothing
	waiting = false
}
// Not "skipped"/"done" of the waiting job: the next gpu job meets the same blocker in the same pass, and the
// runner logs a gpu-wait only for a new blocker (_waited_on), so the wait goes on without a line.

Two smaller holes went with the 13:14 commit. One was in the tests: none of them noticed when the seek to the end of the log was taken out, and without it the reader would look at the first 256 KiB of an 858 KB log, which on the A9 means events from 10 to 15 October. The reader now takes the last megabyte, and a test puts more than a megabyte of old events in front of the wait. The other was the blocker: a live pid alone was too weak. On the A9 pid_max is 4194304 and pids have been advancing by about half a million a day, so they come round in about eight days, and a gpu-wait can sit at the end of the log for days. The blocker now has to be one of the runner's own GPU process names, read from /proc/<pid>/comm, and since 13:59 it also has to run inside an llm-engine-* unit, the name the proxy gives its engines. At first any such unit passed. Since v0.3.1 the unit must also belong to the user the agent runs as (/user@<uid>.service/ in the cgroup path): another user's engine unit is one the proxy's stop can't touch.

The pid can also be the wrong one of two. The runner names the first GPU process it finds, and behind a llama.cpp router that can be the router's per-model child. When the child exits, the router still holds the GPU, so the agent falls back to the ppid the runner logged with the wait. The 13:59 commit added that fallback and decoded the field into an any, then printed it with fmt.Sprint. That is harmless for a string, and runner.py writes a string. It is not harmless for a number: JSON numbers arrive as float64, and pid 2398942 comes out as 2.398942e+06, a perfectly good number and nobody's pid. That day the A9's new pids had seven digits. In v0.3.1 the field stays raw JSON with its quotes trimmed, as in the gpu-wait case above, and counts only if it parses as a pid.

Thirty seconds for a ten-second tick#

The last hole was in the handover itself. When the proxy stops its engine for a waiting benchmark, the runner doesn't take the GPU at once. It looks at its next tick, up to ten seconds later. A request in those ten seconds found the blocker gone and running/ unchanged, so the agent saw a free GPU, the proxy started its engine again, and the runner logged a gpu-wait on the new pid. Then the release stop, then the same race, about every thirty seconds plus a model load. Under scripted traffic the benchmark can lose most rounds of a game it doesn't know it's playing.

After a release stop, new work for the box now gets a 423 for thirty seconds, three of the runner's ticks, by which time the job is in running/ and the plain rule takes over (since 13:59 that also holds for a request already queued behind the release stop):

// benchHandover is how long new work stays refused after the engine was stopped for a waiting bench: the
// runner takes the GPU at its next tick (10 s), and a request in between would start the engine again.
const benchHandover = 30 * time.Second

Passes four to seven: small items inside the fixes#

The four commits weren't the end of it. The same loop as in The fixes had the bugs went on: each pass reviewed the previous pass's fixes and proved each code fix with a mutant that undoes it. The seven passes found 10, 9, 5, 6, 5, 3 and 2 findings, not counting the tests they asked for. The findings were graded MED, LOW or small, and all five MEDs were in the first three. The fourth pass found nothing above LOW. I asked for the LOWs to be fixed as well, and the passes went on. From the fifth pass on, no finding was above small, and every one sat inside the previous pass's own fixes: a failing stop logged on every tick, an error left on the status page of a host that was down, a test comment describing a rule the code no longer had.

The one worth telling went a step too far. The sixth pass noted that the stop error on /status could outlive the problem. My fix cleared it after a good unload, as the finding suggested, and also whenever an engine came up after a switch, which the finding hadn't asked for. The seventh pass showed why not: when a leftover GPU process of ours won't exit, the agent waits 30 seconds for it and then starts the new engine beside it, so the error could vanish from the page while the leftover still ran. Cosmetic in practice, since a stuck engine usually stops answering and the host then shows as down, which clears the error anyway. But a GPU process the page doesn't mention is exactly what keeps a benchmark job waiting. That clear is gone: only a good stop, or the host seen down, clears the error now. Those last fixes shipped without an eighth pass, and the changelog says so.

v0.3.1 fails closed on an old agent#

None of it runs on the A9 until engine install a9 replaces the agent binary on the box. The v0.3.0 agent accepts the new job_queue field without a word and ignores it, which is how a protection stays off without anyone noticing. The v0.3.1 agent reports that it read the field, and for a box with a job queue the proxy treats an agent that doesn't as a GPU it may not touch: every start there is refused with a 423 that names the command to run. What happened once I ran it, when the proxy started its first engine on the A9, is the next post. Until then, from 15:17 to 16:33 that afternoon, engine status a9 listed the old agent, with that command, among the GPU's owners. For a protection that an old agent would have ignored without a word, that was a promotion.

Filed under: local-llm, go, proxy, gpu, benchmarks

Sources#