48-Hour Field Notes: The Load Test Looked Fast. Keep-Alive Was Reusing One Socket.

I thought I had a fast API until my laptop printed twelve milliseconds for two hundred sequential GETs. Production p95 then sat near a full network round trip, and nobody could reconcile the two graphs. Have you ever published a latency number that only existed because the TCP handshake never happened again? I spent the next forty-eight hours treating this as a server problem when it was a client measurement bug.

What I thought I was measuring

I had wrapped a requests.Session around a tiny loop because posts kept saying sessions were the grown-up HTTP client. The script lived in a gist, the URL pointed at staging, and the mean looked good enough for a design doc. Why would I question a timer that used time.perf_counter() and raised on every non-200 response? The session was doing me a favor I had never asked for in that measurement.

After the first call, urllib3 kept the TCP connection and the TLS session in a pool keyed by host. Requests two through two hundred never paid for handshake, never paid for TLS, and barely paid for DNS. I was measuring keep-alive reuse, not the cost a cold cron job or a new pod actually pays.

Hours 0–8: I blamed the application

I pulled application logs, then I stared at framework middleware, then I disabled a tracing exporter I blamed for ten milliseconds. Nothing moved the production graph, and the laptop script stayed smugly fast for the entire morning. Did I restart the process, and did I flush the local resolver cache while I was already guessing? I did both of those things, and I still never closed the session between timed calls.

Here is the shape of the original loop, written as a reader-runnable harness instead of the staging gist:

# harness_v0.py — first attempt; the mean hides the pool
import statistics
import time
import requests

URL = "https://example.com/"  # replace with an endpoint you own
N = 50

session = requests.Session()
samples_ms = []
for _ in range(N):
    t0 = time.perf_counter()
    response = session.get(URL, timeout=10)
    response.raise_for_status()
    samples_ms.append((time.perf_counter() - t0) * 1000)

print("n", N)
print("mean_ms", round(statistics.mean(samples_ms), 2))
print("p50_ms", round(statistics.median(samples_ms), 2))

Run that file once against a remote HTTPS URL and you will likely see a tight cluster of samples. That tightness is the connection pool doing its job, not your request handler suddenly becoming free. I treated the cluster as evidence, and that is how a keep-alive socket ended up in a design document.

Hours 8–24: sample zero was a different animal

I printed every sample instead of the mean, and sample zero was several times slower than sample one. Averaging cold and warm rows is not a measurement so much as a smoothing function with extra confidence. Is a pooled worker the same client as a one-shot cron? Only if you want the wrong number in the doc.

I then compared three setups that people casually mix together:

1. One long-lived Session for the whole loop, which is what a worker process usually does.
2. A brand-new Session per call, which is closer to requests.get() and to many CI checks.
3. The same session pattern with Connection: close, which forces the handshake back into view.

# harness_v1.py — split first vs rest; pooled vs closed
import statistics
import time
from dataclasses import dataclass
import requests

URL = "https://example.com/"
N = 30

@dataclass
class Row:
    label: str
    samples_ms: list[float]

    def summary(self) -> str:
        xs = self.samples_ms
        p95 = sorted(xs)[max(0, int(0.95 * (len(xs) - 1)))]
        rest = xs[1:] or xs
        return (
            f"{self.label:18} n={len(xs):2} "
            f"first={xs[0]:7.1f} rest_p50={statistics.median(rest):7.1f} "
            f"all_p95={p95:7.1f}"
        )

def take(n: int, extra_headers=None) -> list[float]:
    out = []
    headers = extra_headers or {}
    for _ in range(n):
        session = requests.Session()
        t0 = time.perf_counter()
        try:
            response = session.get(URL, timeout=10, headers=headers)
            response.raise_for_status()
        finally:
            session.close()
        out.append((time.perf_counter() - t0) * 1000)
    return out

def pooled(n: int) -> list[float]:
    session = requests.Session()
    out = []
    try:
        for _ in range(n):
            t0 = time.perf_counter()
            response = session.get(URL, timeout=10)
            response.raise_for_status()
            out.append((time.perf_counter() - t0) * 1000)
    finally:
        session.close()
    return out

rows = [
    Row("pooled_session", pooled(N)),
    Row("fresh_session", take(N)),
    Row("connection_close", take(N, {"Connection": "close"})),
]
for row in rows:
    print(row.summary())

The labels matter more than any absolute millisecond value you happen to see on one laptop. On mine, pooled_session made rest_p50 look like a local function call, while fresh_session brought handshake cost back into the open. connection_close was the honest story for a cron job that never keeps a pool.

response.elapsed did not save me either, because Requests counts from send until headers are parsed. Extra work around the call, including your own retries, still lives outside that timedelta. I wanted wall time for the whole attempt, including connect, which is why the harness wraps perf_counter() around session.get().

The same trap in httpx

If you already moved to httpx, the naming changes and the pooling behavior does not. A module-level httpx.get() is closer to a one-shot client, while a reused httpx.Client is the keep-alive path. I ran this beside the Requests file so I could not claim the bug was a library quirk.

# harness_httpx.py — Client reuse vs one-shot
import time
import httpx

URL = "https://example.com/"

def once_ms() -> float:
    t0 = time.perf_counter()
    r = httpx.get(URL, timeout=10.0)
    r.raise_for_status()
    return (time.perf_counter() - t0) * 1000

def pooled_ms(n: int) -> list[float]:
    out = []
    with httpx.Client(timeout=10.0) as client:
        for _ in range(n):
            t0 = time.perf_counter()
            r = client.get(URL)
            r.raise_for_status()
            out.append((time.perf_counter() - t0) * 1000)
    return out

print("one_shot_first", round(once_ms(), 1))
print("pooled_first_three", [round(x, 1) for x in pooled_ms(3)])

Would you publish the third pooled sample as “API latency”? I almost did, and that is the whole incident.

Hours 24–36: curl printed phases I had formatted away

Python was not the only liar in the toolbox that afternoon. I had been using curl -w '%{time_total}' in a shell loop, which is better than a hidden pool, until I reused one curl process and fed it several URLs. The useful form writes DNS, connect, TLS, and TTFB on one line so a fast total cannot hide a slow handshake.

# one-shot: you pay DNS + connect + TLS every time
curl -sS -o /dev/null \
  -w 'dns=%{time_namelookup} connect=%{time_connect} tls=%{time_appconnect} ttfb=%{time_starttransfer} total=%{time_total}\n' \
  --http1.1 \
  https://example.com/

# reuse inside one curl process (HTTP/1.1 keep-alive)
curl -sS -o /dev/null \
  -w 'total=%{time_total}\n' \
  --http1.1 \
  https://example.com/ https://example.com/ https://example.com/

The third total on that second command is a warm socket. DNS can also stay cached in the OS stub resolver even when your Python process is brand new. That is why a second machine still matters after the script looks “reproducible” on the laptop.

Hours 36–48: I reran the harness where my laptop was not

Laptop numbers include a warm resolver, leftover connections, and sometimes an HTTP/2 session the rest of the fleet does not share. I wanted the same file on a clean host before I argued with the production graph again.

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

I pasted the harness into MonkeyCode and used free model access to review the timing code, not to invent a faster handler. The free server option was the useful part: a second environment that did not inherit my laptop’s warm sockets. The review did not uncover a new protocol trick. It did catch that urllib3 retries were still on, which turned a failed connect into a quieter, longer sample.

I disabled retries for the measurement run so connect failures could not masquerade as tail latency:

from requests.adapters import HTTPAdapter
from urllib3.util.retry import Retry
import requests

def no_retry_session() -> requests.Session:
    session = requests.Session()
    adapter = HTTPAdapter(max_retries=Retry(total=0, connect=0, read=0))
    session.mount("https://", adapter)
    session.mount("http://", adapter)
    return session

After that change, connect failures showed up as exceptions instead of mysterious p95 bumps. That is the kind of break I would rather see in hour two, not hour forty-six.

Decision table I wish I had on hour one

Question you are answering	Client setup	Metric worth publishing
What does a cold cron or new process pay?	Fresh session or Connection: close; retries off	First sample, plus p95 of fresh calls
What does a long-lived worker pay on a hot pool?	One Session / httpx.Client for the process	rest_p50 and rest_p95, first sample excluded
What does a browser-like client pay?	Do not use this harness; use a browser or HTTP/2 tool	Connect and TTFB from that tool
Are we sure this is the server?	Compare pooled vs closed on two hosts	Delta between rest_p50 and fresh p95

If pooled rest_p50 is fine and fresh p95 is not, your handler is probably not the villain. If both rows are bad, then you finally get to look at application code with a straight face. Mixing those two questions in one mean is how I lost the first day.

What actually broke

Several small choices stacked, and none of them looked like a bug in review:

• I reported the mean of cold and warm samples as if they were one distribution.
• I used a long-lived Session while several production callers were closer to one-shot jobs.
• urllib3 retries hid connect errors inside elongated timings instead of hard failures.
• I never printed time_connect and time_appconnect, so TLS stayed invisible.
• I treated laptop DNS cache as a property of the API rather than of my laptop.

None of those are exotic, and all of them survive a quick review because the script is short. A single printed number feels like evidence even when the socket pool did the work.

What I would repeat

I would print first versus rest before I print any mean, every time, even for a “quick” check. I would keep a phase-level curl -w line next to the Python harness so connect and TLS cannot hide inside time_total. I would turn retries off while measuring, then turn a documented policy back on for production clients. I would run the same file on a second host before I paste a number into a design doc.

I would not use this loop as a load test, because sequential GETs from one process say nothing about saturation. They also say nothing about lock convoy, thread-pool exhaustion, or head-of-line blocking under concurrency. Tools built for load still own that question. This harness only answers a narrower one: did I accidentally measure the socket pool?

Who should not use this approach

Skip this if you need a formal SLA number, a multi-region study, or a concurrency limit you can defend. A shared free server is also the wrong place to certify tail latency, because noisy neighbors move p95 around without touching your handler. Do not ask a coding model to make the API faster when the timer is the bug you actually have. And do not disable keep-alive in production just to make a lab script match a cron job; reuse is usually the correct behavior for a long-lived worker.

If you only remember one check from the forty-eight hours, remember this next time a graph looks too good to argue with. Print sample zero before you print the mean, and ask whether the rest of the distribution is just a socket you forgot to close.