The Log Line Moved My p99

Your p99 is probably not the model. It is something you wrote after the model answered. I learned that the boring way, with a timer in the wrong place.

Everyone ships AI features faster than their dashboards. So the endpoint looks slow and the model takes the blame. But which phase is actually slow? If you cannot split the latency, you cannot answer that question.

I stopped guessing and split the request into four phases. Queue wait, prep, call, and tail. Then I kept the histogram. Here is the harness, and here is what it found.

Split the clock before you split the traffic

The idea is small. Stamp perf_counter() at four points inside the handler. Everything between two stamps is a phase you can defend.

# tail_probe.py — phase-split latency probe (single file)
import asyncio, json, os, time
import httpx

N = int(os.getenv("N", "200"))
CONC = int(os.getenv("CONC", "20"))
SYNC_LOG = os.getenv("SYNC_LOG", "0") == "1"
STUB = os.getenv("STUB", "1") == "1"
BASE_URL = os.getenv("BASE_URL", "").rstrip("/")
MODEL = os.getenv("MODEL", "")

SEM = asyncio.Semaphore(CONC)
ROWS = []

def pct(xs, q):
    xs = sorted(xs)
    k = min(len(xs) - 1, int(round(q * (len(xs) - 1))))
    return xs[k]

def log_sync(row):
    with open("probe.log", "a") as fh:      # blocking write, on purpose
        fh.write(json.dumps(row) + "\n")

async def call_model(client, payload):
    if STUB:
        await asyncio.sleep(0.08)           # synthetic service time
        return
    r = await client.post(
        f"{BASE_URL}/chat/completions",
        json=payload,
        headers={"Authorization": f"Bearer {os.environ['API_KEY']}"},
        timeout=60,
    )
    r.raise_for_status()

async def one(i, client):
    t_send = time.perf_counter()
    async with SEM:
        t_enter = time.perf_counter()
        payload = {"model": MODEL,
                   "messages": [{"role": "user",
                                 "content": f"turn {i}: summarise the last 40 lines"}],
                   "stream": False}
        body = json.dumps(payload)
        t_prep = time.perf_counter()
        await call_model(client, payload)
        t_call = time.perf_counter()
        if SYNC_LOG:
            log_sync({"i": i, "bytes": len(body)})
        t_done = time.perf_counter()
    ROWS.append({"wait": t_enter - t_send, "prep": t_prep - t_enter,
                 "call": t_call - t_prep,  "tail": t_done - t_call,
                 "total": t_done - t_send})

def bars(rows):
    edges = [0, .05, .10, .15, .20, .30, .50, 1.0, 9e9]
    counts = [0] * (len(edges) - 1)
    for r in rows:
        for j in range(len(counts)):
            if edges[j] <= r["total"] < edges[j + 1]:
                counts[j] += 1
                break
    top = max(counts) or 1
    for j, c in enumerate(counts):
        label = f"{edges[j]*1000:5.0f}-{edges[j+1]*1000:5.0f}ms"
        print(f"{label} {'#' * int(40 * c / top):40s} {c}")

async def main():
    async with httpx.AsyncClient() as client:
        t0 = time.perf_counter()
        await asyncio.gather(*(one(i, client) for i in range(N)))
        wall = time.perf_counter() - t0
    for phase in ("wait", "prep", "call", "tail", "total"):
        xs = [r[phase] * 1000 for r in ROWS]
        print(f"{phase:6s} p50={pct(xs,.5):7.1f} p90={pct(xs,.9):7.1f} p99={pct(xs,.99):7.1f}")
    print(f"throughput={N/wall:6.1f} req/s  conc={CONC}  sync_log={SYNC_LOG}")
    bars(ROWS)

asyncio.run(main())

Four phases, five percentile lines, one histogram. That is the whole instrument. Nothing here needs a profiler, a vendor, or a paid tier.

Run the stub first, twice

The stub proves the harness before the network joins the argument. Run both arms with one difference only.

: > probe.log
STUB=1 N=200 CONC=20 SYNC_LOG=0 python tail_probe.py
: > probe.log
STUB=1 N=200 CONC=20 SYNC_LOG=1 python tail_probe.py

Same synthetic 80ms service time. Same concurrency. The only change is one blocking write() in the tail of the handler.

What did I expect? p50 flat, call flat, and wait climbing for everyone queued behind the write. That is the shape a blocked event loop leaves behind. Your absolute numbers are your business. The shape is the finding.

I am not quoting my milliseconds. A laptop on wifi is not evidence. Run it and write your own four lines into a file you keep.

Now point it at a real endpoint

Set STUB=0 and aim it at any OpenAI-compatible base URL. Adjust the path if your provider differs, and keep concurrency low on a shared tier.

export BASE_URL="https://your-endpoint.example/v1"
export MODEL="your-model-id"
export API_KEY="your-key"
STUB=0 CONC=4 N=100 python tail_probe.py

This is where MonkeyCode's free model access and free server option made the loop cheap for me. The token allowance covered the repeated runs, and the server meant my own network was never the variable. Those two availability claims are the operator's, not a benchmark I ran. At the time of writing, the free model access and the free server are both offered; confirm current terms before you plan around them.

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

One warning. Free tiers are shared, and shared tiers are noisy. Treat them as a place to test the harness, not a place to certify capacity.

Keep the histogram, not the dashboard

Averages lie and dashboards forget. Commit a baseline file and let CI compare percentiles instead.

# keep_this.py — fail the build on a tail regression, not a mean shift
import json, sys
baseline = json.load(open("latency_baseline.json"))   # {"total_p99_ms": ...}
current = json.load(open("latency_current.json"))
if current["total_p99_ms"] > baseline["total_p99_ms"] * 1.25:
    sys.exit("p99 regressed more than 25% — check tail phase first")

Why 25%? Because small samples wobble. Pick a threshold you can defend and write it down next to the file. Mine is a placeholder until you have twenty runs.

Read the shape, not the number

Shape	Likely bottleneck	Next move
wait p99 up, call flat	blocked loop or too much concurrency	find the sync call in the handler
tail p99 up, call flat	logging, serialization, response work	buffer or offload the write
call p99 up, rest flat	provider or network	stream, shorten prompts, retry less
prep p99 up	payload build, tokenizing	cache the template, measure again
wait flat, total up everywhere	one shared queue	lower concurrency and rerun

Print that table once. Tape it above your monitor. It ends most latency arguments in one reread.

What this will not tell you

This measures your process, not the model. If the kernel time or the provider's queue is the wall, you will see it in call and no further.

Small N lies. Under-concurrency hides queueing. Over-concurrency manufactures it. Sweep three concurrency levels before you believe a slope.

And skip this if you need contractual numbers. Shared free capacity is for learning the shape, not for signing an SLA. Also skip it if a profiler already gave you a flame graph you trust. Do not rebuild a worse tool.

Who should use it? Anyone shipping an AI endpoint with a p99 they cannot explain. That was me last week.

So keep the graph. Keep the four phase lines next to it. Then ask the only question that matters: which phase moved, and who wrote it?

If you want to rerun both arms without a cloud bill, the free server and free model access are the reason I could.