I Split the Wait Into Three Clocks

One wall-clock number lied about the model. It blamed generation for every stall I felt. The graph I kept made the split obvious.

You feel a pause and name it inference. Do you actually know that? I didn't until three timestamps existed.

I still watch coding agents do this live. Someone wraps await complete() in a timer. They screenshot the total and shrug. They call the remote path dead after one run.

A single elapsed time is a blended drink. Queue time dissolves inside that glass. Network time dissolves beside it quietly. Your JSON parse dissolves last, smiling.

Generation drinks the insult alone. That is the whole measurement bug. We argue about models with dirty clocks. Then we twist the wrong knob for days.

I wanted a graph I could keep overnight. Not a vibe about intelligence. Not a badge on a vendor card. Three clocks on every call, always.

I stamp t_send when bytes leave me. I stamp t_first on the first inbound byte. I stamp t_last when the stream goes quiet. Anything after t_last belongs to me.

Does that sound too simple for production work? It is painfully simple on purpose. People skip simple measurements every single week. Complexity makes a gorgeous hiding place.

Think about a late dinner at home. You blame the oven immediately, right? You shopped after preheating the rack though. Then you plated for twenty slow minutes.

The oven was never the whole story. Remote inference gets that same unfair blame. Shared free paths get it even worse. Noise turns into mythology by morning.

I needed names for each wait. I use three names, only three. I call them queue-ish, generation-ish, and mine. They are nicknames, not laboratory physics.

Queue-ish is t_first minus t_send. It includes DNS lookup time. It includes the TLS handshake. It includes server admission. It includes a proxy that hoards bytes.

Generation-ish is t_last minus t_first. It includes real token emission. It also includes server-side buffering. A stream flag can still dump once.

Mine is work after t_last returns. Logging frameworks love this slice. Schema validators love it too. Pretty printers rewrite the world slowly.

Why three clocks, not ten spans? Ten clocks never get kept. Three clocks survive a working afternoon. The CSV stays small enough to open.

Here is the harness I keep locally. Treat every line as a labeled example. This snippet is unexecuted in this article. Point it at your own URL.

# labeled example: three-clock stream harness, not a vendor scoreboard
import csv, json, sys, time, urllib.request
from pathlib import Path

url, prompt, token = sys.argv[1], sys.argv[2], sys.argv[3]
body = json.dumps({
    "stream": True,
    "messages": [{"role": "user", "content": prompt}],
}).encode()

req = urllib.request.Request(
    url,
    data=body,
    method="POST",
    headers={
        "Content-Type": "application/json",
        "Authorization": f"Bearer {token}",
        "Accept": "text/event-stream",
    },
)

t_send = time.perf_counter()
cpu0 = time.process_time()
t_first = t_last = None
chunks = nbytes = 0
gaps = []
last = t_send

with urllib.request.urlopen(req, timeout=120) as resp:
    while True:
        piece = resp.read(256)
        now = time.perf_counter()
        if not piece:
            break
        if t_first is None:
            t_first = now
        gaps.append(now - last)
        last = now
        t_last = now
        chunks += 1
        nbytes += len(piece)

t_done = time.perf_counter()
cpu1 = time.process_time()
if t_first is None:
    raise SystemExit("no bytes returned; cannot split the wait")

queue_s = t_first - t_send
gen_s = t_last - t_first
mine_s = t_done - t_last
cpu_s = cpu1 - cpu0
max_gap = max(gaps) if gaps else 0.0

row = {
    "ts": time.strftime("%Y-%m-%dT%H:%M:%SZ", time.gmtime()),
    "queue_s": f"{queue_s:.4f}",
    "gen_s": f"{gen_s:.4f}",
    "mine_s": f"{mine_s:.4f}",
    "cpu_s": f"{cpu_s:.4f}",
    "chunks": chunks,
    "bytes": nbytes,
    "max_gap_s": f"{max_gap:.4f}",
}
path = Path("wait_split.csv")
new = not path.exists()
with path.open("a", newline="") as f:
    w = csv.DictWriter(f, fieldnames=row.keys())
    if new:
        w.writeheader()
    w.writerow(row)
print(row)

Curl still earns a permanent seat beside it. HTTP hiding places show up there first. DNS and TLS often fake a slow model. I check those before I touch prompts.

# labeled example: ask curl to name the handshake
curl -sN -o /tmp/stream.bin \
  -H "Authorization: Bearer $TOKEN" \
  -H "Content-Type: application/json" \
  -H "Accept: text/event-stream" \
  --data '{"stream":true,"messages":[{"role":"user","content":"ping"}]}' \
  -w "dns:%{time_namelookup} tcp:%{time_connect} tls:%{time_appconnect} ttfb:%{time_starttransfer} total:%{time_total}\n" \
  "$URL"

I append one CSV row per call. I keep the file beside the service. I refuse to trust memory tomorrow morning. Graphs beat hallway anecdotes when something pages.

Then I draw the split as stacked bars. A tiny script is enough here. Queue-ish gets one color. Generation-ish gets another. Mine gets a color that looks guilty.

# labeled example: draw the CSV you actually kept
import csv
from pathlib import Path

rows = list(csv.DictReader(Path("wait_split.csv").open()))
print("n=", len(rows))
for name in ("queue_s", "gen_s", "mine_s", "cpu_s"):
    vals = [float(r[name]) for r in rows]
    avg = sum(vals) / len(vals)
    print(f"{name} avg={avg:.3f} max={max(vals):.3f}")

Read those bars like a mechanic would. Do not read them like a launch blog. One sample is weather on a window. A week of samples is climate.

I use a tiny decision matrix here. It keeps my hands off the wrong knob. I taped a copy above the terminal. Yes, that part is sincere.

Dominant slice	What it usually is	What I refuse to tune
queue-ish	admission, DNS, TLS, proxy buffer	temperature, max tokens, prompt poetry
generation-ish, steady gaps	actual decode / long prompt	JSON pretty printers, extra log lines
mine, or CPU rising during read	client parse, tools, tracing	model shopping for its own sake
one cliff, then silence	someone buffered the "stream"	anything that assumes live tokens

If queue-ish dominates, I stop decoding. Tokens do not exist yet. I warm the connection instead. I reuse the session. I inspect the admission path.

If generation-ish dominates with steady gaps, tokens are real. Prompt size belongs in that fight. Packing belongs there too. That fight is a different note.

If mine dominates, I inspect my process. Receiving already finished cleanly. I was still narrating a wait. The model had left the building.

If chunk gaps look violently spiky, someone buffered. The stream flag was ceremonial, honestly. First byte arrived late on purpose. The graph shows a cliff, not rain.

I also watch cpu_s next to wall time. If CPU climbs during the so-called wait, I lied. I was parsing inside the read loop. I was pretty-printing tokens as they landed.

That bug felt like generation drag. It was me, talking too much. Logging each token to disk is expensive. So is coloring a terminal on every chunk.

I pointed this loop at a free remote path. I needed retries without burning a paid key.

Disclosure: This article was prepared as part of MonkeyCode's product outreach.

MonkeyCode's free model access fit that loop. A free server option fit it too. I used both as a reachable target. I did not crown them with latency medals.

Could I have used any other URL? Yes, obviously I could. The harness does not care about brands. The lesson is the split itself.

What broke my first graphs badly? Proxies did. They delayed first byte for assembly. My queue-ish bar went cartoonish overnight. I thought the model was queued. The proxy was writing a novel.

TLS handshakes polluted queue-ish as well. Cold starts look like heavy congestion. I logged curl -w beside the Python client. The two stories had to rhyme.

Clock resolution lied on tiny replies. A thirty millisecond generation is just noise. Do not rank models on that jitter. Rank your parser instead, every time.

I commit the CSV on bad weeks only. Not forever, and not as marketing. Just long enough to compare two Mondays. The graph I kept is the argument.

Who should ignore this whole note? Anyone selling an SLA from it. This is a debug habit. It is not a bakeoff protocol. It will not survive a legal review.

Skip it if your API never streams. You will invent a first-byte fairy tale. The response is one fat chunk then. Three clocks collapse into two shrugs.

Skip it if you need quality evaluation. Tokens per second is not correctness. A fast wrong answer still loses users. Keep this graph next to tests.

Shared free capacity stays noisy on purpose. Neighbors exist whether you like them. One slow call proves almost nothing. I keep a week or I stay quiet.

I still catch myself cheating daily. I glance at total wall time. I invent a story in one breath. Then I open the CSV and stop.

The core move stays boring on purpose. Split the wait into three clocks. Name the biggest slice out loud. Fix only that slice this round.

Repeat until the graph looks dull. Dull is the actual goal here. Drama is usually a measurement bug. When all three slices shrink, ship.

If you already have an endpoint, run the harness. Keep the CSV next to the code. Argue with the bars, not with me.