Four Timers Beat One Benchmark

One number tells you nothing. Four timers told me where the clock lived.

I stopped profiling my agent loop end to end. End-to-end latency is a sum, and sums hide arguments. So I split wall clock into four phases and logged each one, every run.

The phases are boring on purpose: build, model, tool, glue. Build is context assembly. Model is the HTTP round trip. Tool is whatever the loop runs locally. Glue is parsing, validation, logging, and retry sleeps.

Why four? Every phase has a different fix. You cannot patch a sum. You can patch a phase.

The shape I keep coming back to

Here is the output shape I keep landing on. The numbers below came from a stub model I wrote myself, so treat them as a shape, not a benchmark.

runs=40 wall=812.4s
build  p50=  1.90s p95=  6.40s share=12.1%
model  p50=  3.10s p95=  9.80s share=19.4%
tool   p50=  9.70s p95= 31.20s share=61.3%
glue   p50=  0.80s p95=  4.10s share= 7.2%

Tool ate sixty-one percent. Model ate nineteen. Would a faster model have saved me? Nineteen percent, at best. And swapping models costs a week of prompt retuning.

That is the whole argument. The expensive thing was not the thing I was tuning.

The harness

Stdlib only. No SDK, no framework, no dashboard. Two files.

# loop_profile.py — four timers, one JSON line per run
import json, os, time, urllib.request

BASE  = os.environ["LLM_BASE_URL"].rstrip("/")
KEY   = os.environ.get("LLM_API_KEY", "")
MODEL = os.environ["LLM_MODEL"]

def t(): return time.perf_counter()

def chat(messages):
    req = urllib.request.Request(
        BASE + "/chat/completions",
        data=json.dumps({"model": MODEL, "messages": messages}).encode(),
        headers={"Content-Type": "application/json",
                 **({"Authorization": f"Bearer {KEY}"} if KEY else {})},
    )
    with urllib.request.urlopen(req, timeout=120) as r:
        return json.loads(r.read())

def timed(fn, *a):
    s = t()
    out = fn(*a)
    return out, t() - s

def one_run(task, tools):
    rec = {}
    msgs, rec["build"] = timed(build_context, task)
    resp, rec["model"] = timed(chat, msgs)
    rec["tool"] = 0.0
    for call in parse_tool_calls(resp):
        _, d = timed(run_tool, call, tools)
        rec["tool"] += d
    _, rec["glue"] = timed(validate_and_log, resp)
    return rec

if __name__ == "__main__":
    with open("phases.jsonl", "a") as f:
        for line in open("tasks.txt"):
            f.write(json.dumps(one_run(line.strip(), TOOLS)) + "\n")

Swap in your own build_context, parse_tool_calls, run_tool, validate_and_log. Keep them honest. If one function does two things, split it first.

The rule that matters: one timer, one function, one reason. A timer wrapping three concerns measures nothing you can act on.

Then aggregate:

# phases_report.py
import json
rows = [json.loads(l) for l in open("phases.jsonl")]
P = ["build", "model", "tool", "glue"]

def pct(xs, p):
    xs = sorted(xs)
    return xs[min(len(xs) - 1, round(p / 100 * (len(xs) - 1)))]

wall = sum(sum(r[p] for p in P) for r in rows)
print(f"runs={len(rows)} wall={wall:.1f}s")
for p in P:
    xs = [r[p] for r in rows]
    print(f"{p:6s} p50={pct(xs,50):6.2f}s p95={pct(xs,95):6.2f}s share={sum(xs)/wall:5.1%}")

Run it with three prompts, not thirty. Run it twice, because the first run is cold. Then keep the diff between the two runs.

The graph I kept

I keep one chart file, not a dashboard. Stacked bars, one row per run, four bands, sorted by tool time.

python phases_report.py > graph.txt
git add graph.txt && git commit -m "loop shape before prompt change"

I regenerate it on every prompt change. If the tool band grows, I look at tool scope first. If the build band grows, I look at what I started stuffing into context. The chart is a diff of my own decisions.

Dashboards invite staring. A file invites a git diff.

Where free access actually fits

Profiling has a cost problem. Every run you add spends money and time. That is why most people profile once, badly, and then guess forever.

MonkeyCode provides free model access and a free server option. I used both to keep this harness alive: free model access for the model phase, and a free server to host the runner so my laptop could sleep mid-batch. Disclosure: This article was prepared as part of MonkeyCode's product outreach.

Treat availability claims carefully, mine included. Free tiers change shape. I did not test quotas, limits, hardware, or how long any of it lasts, so check the current terms before you build a habit on top of them.

What I like about the setup is narrow and honest. Cheap runs make more runs. More runs make the fourth timer worth keeping.

Decision table

Biggest band	First fix	Do not
build	cache context, trim files	swap models
model	fewer tokens, smaller model	rewrite tool code
tool	narrow scope, cache results, parallelize	tune temperature
glue	remove retry sleeps, cheap validation	add more retries

Read the table once. Then read your own numbers twice.

Limitations and who should skip this

These timers measure your loop, not your provider. They will not separate your network from their queue. They will not survive a laptop on hotel wifi.

My sample numbers are from a stub, on purpose. A stub does not flatter anyone. Your real numbers will be noisier and less tidy.

Skip this if you need capacity planning with confidence intervals. Skip it if your real bottleneck is a human reading output. Skip it if you cannot reproduce a run twice, because instrumentation on top of nondeterminism just adds a fifth mystery.

For everyone else: four timers, forty runs, one chart. That is enough to stop guessing.

Start with the phase you would have blamed last. Then run the harness on the loop you actually ship. The first forty runs are the cheapest thing you will do all month.