48-Hour Field Notes: My Latency Numbers Were Wrong Because I Started the Clock in the Wrong Place

For two days I tried to answer one question about a free model endpoint and a free server box: is this combination fast enough to keep? I answered it wrong, and not because the box was slow. I answered it wrong because I put the starting line of my stopwatch in the wrong place, then trusted the number that fell out of it.

Here is the part that stings a little. A wrong clock does not produce an obviously wrong number; it produces a confident, well-formatted number that survives review because nobody asks where start came from. So this post is not a review of any provider. It is the harness I rebuilt on the second pass, the queries that make the mistake visible, and the decision rule I now use before I judge any free tier.

The three numbers I actually needed

When you run a batch job against a model endpoint on a box you do not own, "how fast is it" is not one number. It is at least three, and they answer different questions:

1. Queue wait — how long an item sits inside my own process before a request leaves the machine. This measures my semaphore, my thread pool, my scheduler. It says nothing about the provider.
2. Service time — how long the request itself takes, from send to full body. This is the only slice the provider controls.
3. Attempts per item — how many requests I spent to get one usable answer. This is the multiplier that quietly eats your rate budget.

If you collapse all three into one elapsed_ms field, you get a number that moves when any of them moves, and you cannot tell which one moved. So which of those three do you think your current logs actually separate out?

The mistake: one time.time() for four different intervals

My first pass looked like this, and it looked reasonable at the time:

import time, requests

SESSION = requests.Session()

def classify(text: str):
    start = time.time()
    resp = SESSION.post(ENDPOINT, json=payload(text), timeout=90)
    elapsed_ms = (time.time() - start) * 1000
    log.info("classify", extra={"elapsed_ms": elapsed_ms, "status": resp.status_code})
    return resp.json()

This single timer hides four separate things, and each one is enough to flip a build-or-abandon decision:

• Connection setup is inside the measurement. DNS, TCP, and TLS happen before the model sees anything, so a cold pool looks like a slow model.
• Client-side retries multiply rows. Three attempts on one item produce three elapsed_ms samples, so your average is now an average over attempts, not over items.
• Wall clock can step. On a box you do not control, an NTP correction can move time.time() mid-request, and the delta can even come out negative.
• Queue wait is invisible. If items wait on a semaphore for forty seconds, that wait never appears anywhere, because the timer starts after the wait.

Notice that none of these are provider bugs. They are all my instrumentation, which is exactly why they are worth writing down.

Rebuild: one row per attempt, four timestamps

On the second pass I logged one row per attempt instead of one row per call, and I kept two kinds of time on purpose. Durations come from time.monotonic() inside the process, because monotonic cannot step. Wall timestamps are stored too, but only to join and order rows across processes, never to compute a duration.

CREATE TABLE IF NOT EXISTS attempt (
  attempt_id     TEXT PRIMARY KEY,
  item_id        TEXT NOT NULL,
  try_index      INTEGER NOT NULL,
  queued_wall    REAL NOT NULL,
  sent_wall      REAL,
  done_wall      REAL,
  queue_wait_ms  INTEGER NOT NULL,
  service_ms     INTEGER NOT NULL,
  status         INTEGER,
  outcome        TEXT NOT NULL,   -- ok | retryable | permanent
  error          TEXT
);

CREATE INDEX IF NOT EXISTS idx_attempt_item ON attempt(item_id, try_index);

The writer is boring on purpose, because instrumentation that can throw is instrumentation that will throw at 3am:

import sqlite3, time, uuid, requests

DB = sqlite3.connect("attempts.sqlite3")
SESSION = requests.Session()
RETRYABLE = {408, 429, 500, 502, 503, 504}

def attempt(item_id, payload, try_index, url, headers):
    queued_wall, queued = time.time(), time.monotonic()
    resp, sent = None, None
    try:
        resp = SESSION.post(url, json=payload, headers=headers, timeout=(5, 90))
        sent = time.monotonic()
        outcome = "ok" if resp.status_code == 200 else (
            "retryable" if resp.status_code in RETRYABLE else "permanent")
        error = None
    except requests.RequestException as exc:
        sent = time.monotonic()
        outcome, error = "retryable", type(exc).__name__
    done = time.monotonic()
    DB.execute(
        "INSERT INTO attempt (attempt_id, item_id, try_index, queued_wall, sent_wall,"
        " done_wall, queue_wait_ms, service_ms, status, outcome, error)"
        " VALUES (?,?,?,?,?,?,?,?,?,?,?)",
        (str(uuid.uuid4()), item_id, try_index, queued_wall, time.time(), time.time(),
         int((sent - queued) * 1000), int((done - sent) * 1000),
         getattr(resp, "status_code", None), outcome, error))
    return resp, outcome

One honest limitation: this does not split DNS and TLS apart from generation, because requests does not hand you that boundary without a transport hook. For my decision it did not matter, since both are client-side and I control the pool. If yours are slow, reach for a hook before you reach for a bigger box.

The three queries that make the mistake obvious

Logs you never query are just disk usage, so the harness is only half the artifact. These three queries are what I run before forming any opinion.

-- 1. Retry amplification: requests spent per item answered
SELECT COUNT(*) AS attempts,
       COUNT(DISTINCT item_id) AS items,
       ROUND(1.0 * COUNT(*) / COUNT(DISTINCT item_id), 2) AS attempts_per_item
FROM attempt;

-- 2. Split the wall time: my backpressure vs the endpoint
SELECT ROUND(AVG(queue_wait_ms), 1) AS avg_queue_wait_ms,
       ROUND(AVG(service_ms), 1)    AS avg_service_ms,
       ROUND(SUM(queue_wait_ms) * 1.0
             / SUM(queue_wait_ms + service_ms), 3) AS queue_share
FROM attempt WHERE outcome = 'ok';

-- 3. Per-item latency, not per-attempt latency
SELECT ROUND(AVG(total_ms), 1) AS avg_item_ms FROM (
  SELECT item_id, SUM(queue_wait_ms + service_ms) AS total_ms
  FROM attempt WHERE outcome = 'ok' GROUP BY item_id
);

Run query 3 without the GROUP BY, and you are averaging retries into your latency. That number trends upward as the endpoint gets flakier, which makes a provider problem look like a speed problem and sends you optimizing the wrong layer.

Read the shape, not the score

The output is only meaningful as a shape, so I stopped writing percentages on a whiteboard and started matching shapes to actions. The rows below are labels, not measurements you can borrow; the numbers in any sample output you generate are yours.

Shape in your log	Likely cause	What I do next
queue_share high, service_ms flat	My own concurrency limit or worker starvation	Raise workers, shrink payloads, stop blaming the endpoint
service_ms noisy, attempts_per_item near 1.0	Endpoint variance, no retry pressure	Keep it for batch work, keep it out of interactive paths
attempts_per_item above 1.5	Timeouts or rejections being retried	Fix timeout budget and backoff before touching limits
outcome = 'permanent' clustered	Bad payloads being retried pointlessly	Classify the error before the retry, every time

That fourth row deserves a paragraph. A client that retries anything non-200 will happily burn your entire budget on a malformed request, and it will look busy rather than broken. Classify first, then retry, and write permanent to the table so the next person can see it.

Where MonkeyCode's free model access and free server fit in this workflow

I ran the collector and the job loop on MonkeyCode's free server option and pointed the client at its free model access, which changed two things about the experiment. First, instrumentation multiplies request count, and when calls are free there is no billing conversation about re-running a batch to check variance. Second, a box I do not own forces me to treat the clock and the disk as unreliable inputs, which is the correct default anyway; I would have skipped that discipline on hardware I trusted.

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

What I will not do here is quote throughput or latency figures as if they were a property of the platform. Availability is the claim, and the harness above is how you turn availability into a decision for your own workload, on your own machine, with your own numbers.

What broke, and what I would repeat

Field notes should be honest about the boring failures, so here is the list from my two days:

• SQLite writes became the bottleneck once workers went up. I batched inserts in memory and flushed every 200 rows; the log stopped competing with the job.
• A missing index made my analysis query slower than the workload, which is a funny way to discover you forgot idx_attempt_item.
• time.time() bit me once with a negative delta after a clock correction, which is why durations are monotonic-only now.
• I logged the payload twice in the first version, once in the row and once in a JSON blob, and the log grew faster than the results.

What I would repeat without hesitation is the ordering: instrument first, decide second. It costs one extra half hour and saves you from writing a confident postmortem about the wrong component.

Who should not use this approach

• Anyone who needs billing-grade accounting. Provider-side usage records are the authority there, not my local rows.
• Interactive products with a hard per-request budget. You need distributed tracing with spans, not a single SQLite file on one box.
• Teams running fewer than a few hundred calls. Variance dominates the sample, and you will read tea leaves instead of shapes.
• Anyone who will not run the queries. A log nobody aggregates is a slower job with extra disk I/O.

The 20-minute test plan I now run first

1. Point the client at the endpoint with a payload you already trust, and cap it at 200 items.
2. Wrap every call in attempt() so each request becomes one row, including retries.
3. Run once with concurrency 1, then again at the concurrency you plan to ship.
4. Run queries 1 and 2 and compare the two runs, paying attention to queue_share moving while service_ms stays put.
5. Add one deliberately malformed payload and confirm it lands as permanent instead of being retried.
6. Only then look at query 3 and decide whether the box earns a longer trial.

The whole thing fits in a single file plus a SQLite database, and it survives being run against anything that speaks HTTP.

The question I should have asked on day one

If a number moves when you change your own concurrency limit, is it really telling you anything about the endpoint? Mine was not, and I spent two days reading my own scheduler's fingerprints as if they were a provider's. Instrumenting the boundaries takes an afternoon; arguing about a latency figure with no boundaries takes longer and ends in a guess.

If you want somewhere to run the harness while you tune it, MonkeyCode's free model access is a reasonable place to point the probe, and its free server option is enough to host the collector; just keep the 20-minute test plan, because the harness is the part that travels with you.