DEV Community: jidonglab

tiktoken vs count_tokens: My Claude Budget Was 17% Off

jidonglab — Wed, 16 Sep 2026 16:59:57 +0000

My budget guard said the prompt was 171,000 tokens. Haiku 4.5's context window is 200,000. Plenty of room. The API returned a 400 anyway: prompt too long.

That was run 1,102 of a pipeline I'd been babysitting for three weeks, and it was the first time I seriously questioned the little function at the top of my code that counted tokens with tiktoken. So I logged both numbers — my local estimate and the usage the API actually reported — for every request for the rest of the month. This is the tiktoken vs count_tokens comparison across 4,200 calls, and how far off the cheap local estimate really was.

TL;DR

tiktoken is OpenAI's tokenizer. It does not know Claude's vocabulary, so every number it gives you for a Claude prompt is a guess.
Across 4,200 real requests my tiktoken estimate ran a median 17.4% below the input tokens the API billed. Worst bucket (JSON tool results) was 38% low.
Most of my error wasn't even the tokenizer. I tokenized messages and forgot that tool definitions and the system prompt are part of every request — 1,318 + 900 tokens I counted as zero.
The fix is POST /v1/messages/count_tokens with the same body you're about to send. It matched usage exactly on every call I checked. Cost: one extra round trip, median 240ms.
Do not compare your estimate against usage.input_tokens alone. With prompt caching on, the bulk of your input shows up in cache_read_input_tokens and your comparison will look insane.

What was I actually running?

A cron pipeline that triages GitHub issues across my repos. Haiku 4.5 does the cheap first pass (read the issue, the linked file, the last 20 commits touching it, classify and summarize), Opus 5 drafts a patch for anything classified as a real bug. About 200 calls a day, 9 tools, a system prompt with a generated repo map glued to the end.

The whole thing had a guard in front of it:

import tiktoken
enc = tiktoken.get_encoding("cl100k_base")

def estimate(messages) -> int:
    return sum(len(enc.encode(json.dumps(m))) for m in messages)

if estimate(messages) > LIMIT:
    messages = drop_oldest(messages)

Looks responsible. It's fiction with a dependency.

Why does tiktoken undercount Claude tokens?

Because it's a different tokenizer with a different vocabulary. cl100k_base is OpenAI's BPE merge table. Claude has its own, and the merges don't line up, so the same string splits into a different number of pieces. There is no conversion ratio you can multiply by — the drift depends entirely on what's in the text.

That last part is the trap. If the error were a flat 15%, you'd add a fudge factor and go home. It isn't flat. On my traffic the gap tracked content type hard:

Content bucket	Median undercount
Plain English issue bodies	9%
Python and TS diffs	24%
Serialized JSON tool results	38%
Stack traces and log dumps	29%

So a fudge factor tuned on prose blows up the moment the agent pastes a 400-line diff, which is exactly when the prompt is big enough to matter. My run 1,102 failure was a request that was 94% code by volume.

How wrong was tiktoken vs count_tokens across 4,200 calls?

Median 17.4% low, p95 34% low, best case 6% low. It was never once high. An estimator that only errs in the dangerous direction is worse than no estimator, because the guard is the thing that made me stop thinking about it.

Concrete damage over 21 days:

19 runs died on context-limit 400s that my guard had waved through.
Input spend ran 21% above what the estimator's forecast implied for the month. Tokens are the unit you're billed in, so an undercount is a bill surprise with extra steps.
My truncation logic fired late. drop_oldest triggered off the same wrong number, so the pipeline kept whole issue threads it should have dropped and dropped them only after a failure.

The counting bug and the retry bill compound: every 400 was followed by a truncate-and-retry, so the worst prompts got paid for twice.

What does count_tokens count that your estimator doesn't?

Everything the model actually reads. This was the bigger half of my error and it has nothing to do with tokenizers.

A request isn't messages. The API renders tools, then system, then messages. My nine tool schemas came to 1,318 tokens, on every single call, sitting in a variable my estimator never saw. The system prompt with its generated repo map added another ~900. That's 2,218 tokens of pure blind spot before the first message.

The endpoint takes the same body shape as messages.create, which is the entire point:

from anthropic import Anthropic

client = Anthropic()

resp = client.messages.count_tokens(
    model="claude-haiku-4-5",   # counts are model-specific
    system=SYSTEM_PROMPT,
    tools=TOOLS,
    messages=messages,
)
print(resp.input_tokens)       # exact, for this model, for this body

Two things worth internalizing. Counts are model-specific — pass the model you're actually going to call, not whichever ID you had in a constant. And if you build the body in one place and count it in another, you will eventually count a body you don't send. That was my only remaining mismatch after the switch, and it was my bug, not the API's.

Why did my first comparison look completely broken?

Because of prompt caching, and this cost me an evening. My first pass compared estimate() against response.usage.input_tokens and got results like estimate 41,000 versus actual 812. I assumed my logging was wrong.

It wasn't. With caching on, input_tokens is only the uncached portion. The rest is reported separately in cache_read_input_tokens and cache_creation_input_tokens. If you want the number to compare a prompt-size estimate against, you have to add them:

u = response.usage
billed_input = (
    u.input_tokens
    + (u.cache_read_input_tokens or 0)
    + (u.cache_creation_input_tokens or 0)
)

Useful side effect: once you're summing those three, a cache_read_input_tokens of zero across repeated requests is a loud signal that something in your prefix is changing between calls and your cache is silently never hitting.

Does one extra count_tokens call per request slow you down?

On my pipeline, no. Median 240ms, p95 610ms, against calls that already take multiple seconds. 200 counts a day is noise.

In a tight per-user loop it's a different story, so two things I'd actually do:

Count the static prefix once. Tools plus system don't change between runs. Count them at startup, cache the number, and only count the volatile messages per request. One caveat I'd rather you hear from me than discover: token counts are not perfectly additive. Counting the whole body and summing the parts differed by 0 to 4 tokens on my requests. Tiny, real, and enough that I pad the budget by 1% instead of pretending the arithmetic is exact.

Don't count in a fan-out. I briefly counted every candidate chunk in a retrieval step and caught a 429 — the endpoint has its own limits and it is not free of rate limiting just because it's cheap. Count the assembled prompt, once.

The honest limitation: count_tokens tells you the input exactly and the output not at all. Output is unknowable until it's generated. I still reserve headroom equal to max_tokens on top of the counted input, which is the only part of my original guard that survived.

So should you use tiktoken to count Claude tokens?

No. tiktoken is OpenAI's tokenizer, and on 4,200 real Claude calls it undercounted my prompts by a median of 17.4% — never once erring high, and drifting worst (38%) on the JSON and code payloads that make prompts big in the first place. Half my error came from the wrong tokenizer and half from counting only messages while tool schemas and the system prompt quietly added 2,218 tokens to every request. Use client.messages.count_tokens() with the same model, system, tools, and messages you're about to send; it returns the exact input count for one extra round trip of a few hundred milliseconds. And when you compare it against reality, sum input_tokens with the two cache_* fields, or prompt caching will make your own logs look like they're lying to you.

Written by the developer behind Preterview, an interview prep platform.

Speculative Decoding Acceptance Rate: My LLM Got 47% Slower

jidonglab — Wed, 16 Sep 2026 04:58:42 +0000

I turned on speculative decoding on a Friday afternoon expecting a free 2x. My local 32B model went from 34 tokens/sec to 18.

Not noise. Not a warmup artifact. Consistently, reproducibly, half speed. I had added a second model to my GPU, burned VRAM for it, and made everything worse.

The thing nobody tells you: speculative decoding is not a speedup. It's a bet, and the speculative decoding acceptance rate is the odds. Get the odds wrong and you pay for every draft token you throw away.

TL;DR

Speculative decoding runs a small draft model for k tokens, then verifies all k in one forward pass of the big model. Output distribution is mathematically identical to normal decoding.
It wins only when the acceptance rate (fraction of drafted tokens the target model keeps) is high enough to pay for the draft model's cost.
Speedup is E(k) / (1 + k·c) where E(k) = 1 + α + α² + ... + αᵏ, α is acceptance rate, and c is draft-step cost divided by target-step cost.
My α was 0.71 on code and 0.32 on English prose. At draft length 16, prose ran at 0.50x. Dropping to draft length 4 gave 1.91x on code and break-even on prose.
Fix in order: measure α per workload, shrink k, then pick a better-matched draft model. Long drafts amplify a bad α instead of rescuing it.

What is speculative decoding actually doing?

Speculative decoding exploits one fact about LLM inference: decoding a single token is memory-bandwidth bound, not compute bound.

To produce one token, your GPU streams every weight in the model from VRAM through the compute units. A 32B model at Q4 means moving ~19 GB per token. The matrix multiplies themselves barely make the GPU sweat. The tensor cores are mostly idle, waiting on memory.

So here's the trick: if you feed the target model 5 candidate tokens instead of 1, it still reads those 19 GB exactly once. Verifying 5 positions costs roughly what verifying 1 position costs. You get four extra tokens of work for free, as long as you had candidates to check.

That's where the draft model comes in. A tiny model (0.5B, same tokenizer family) runs k cheap decode steps and guesses what comes next. The target model then verifies all k guesses in a single pass and accepts the longest prefix that matches what it would have sampled itself.

The verification step uses rejection sampling, so the output distribution is identical to running the target model alone. This isn't an approximation, and you aren't trading quality for speed. (You won't get token-for-token identical output to a non-speculative run with the same seed, because the RNG gets consumed differently, but the distribution is the same.)

That's the whole mechanism. The entire question is how many of those guesses survive.

Why did speculative decoding make my model slower?

Because every rejected draft token is pure waste, and I was drafting 16 of them at a time.

Here's the arithmetic. Let α be the per-token acceptance rate and k the draft length. The expected number of tokens you commit per target forward pass is:

E(k) = 1 + α + α² + ... + αᵏ

The 1 + is the free bonus token: even if the draft model's very first guess is wrong, the target's own verification pass produces a correct token, so you never come out with zero.

The cost of that iteration is one target step plus k draft steps. Call c the ratio of draft-step time to target-step time:

speedup = E(k) / (1 + k·c)

My setup: Qwen2.5-Coder-32B-Instruct at Q4_K_M as the target, Qwen2.5-Coder-0.5B as the draft, single 24 GB card. Measured c ≈ 0.12.

That c surprised me. The draft model has 64x fewer parameters, so I expected it to be 64x cheaper. It isn't. A 0.5B model's decode step is dominated by kernel launches, sampling, and per-step Python overhead, not by memory traffic. Small models don't get cheap in proportion to their size. Eight draft tokens cost me almost as much as a full target step.

Now plug in my two workloads:

Draft length `k`	Prose, α=0.32	Code, α=0.71
1	1.18x	1.53x
2	1.15x	1.79x
4	0.99x	1.91x
8	0.75x	1.68x
16	0.50x	1.18x

At k=16 on prose the formula predicts 0.50x. I measured 18 tok/s against a 34 tok/s baseline. That's 0.53x. The model wasn't broken. I was spending 16 draft steps to buy, on average, 1.47 tokens.

Notice the code column too. At α=0.71, going from k=4 to k=16 also loses speed, 1.91x down to 1.18x. Long drafts have diminishing returns on the gain side (α^k collapses toward zero) and perfectly linear growth on the cost side. That asymmetry is the whole story.

How do I measure my speculative decoding acceptance rate?

Don't guess it. Every serving stack reports it, you just have to go look.

llama.cpp: run llama-speculative or the server with -md draft.gguf, and the end-of-run stats include n_drafted and n_accept. Your α is n_accept / n_drafted.

llama-server -m qwen2.5-coder-32b-q4_k_m.gguf \
  -md qwen2.5-coder-0.5b-q8_0.gguf \
  --draft-max 4 --draft-min 1

vLLM: scrape the Prometheus endpoint for vllm:spec_decode_num_accepted_tokens_total and vllm:spec_decode_num_draft_tokens_total. Divide one by the other. Config shape depends on your version, recent builds take a JSON blob:

--speculative-config '{"model": "Qwen/Qwen2.5-Coder-0.5B",
                       "num_speculative_tokens": 4}'

Then sweep k offline before you touch the server. Six lines:

def speedup(alpha, k, c):
    accepted = sum(alpha ** i for i in range(k + 1))
    return accepted / (1 + k * c)

for k in range(1, 17):
    print(k, round(speedup(0.32, k, 0.12), 2),
             round(speedup(0.71, k, 0.12), 2))

Measure α on a real sample of your traffic, measure c with two quick benchmarks, then read the optimal k off the table. This took me ten minutes and I should have done it before I started.

What moves the acceptance rate?

α is not a property of your models. It's a property of your workload, and it swings hard.

Predictable text wins. Code, JSON, boilerplate, and anything that echoes the prompt draft well. My highest α was a structured-output endpoint at 0.83. Brace, quote, key name, closing brace: a 0.5B model nails that.
Open-ended prose loses. Summaries and chat replies sat at 0.32. The draft model and the target genuinely disagree about what the next adjective should be, and there's no fixing that with config.
Temperature matters. On the same code prompts, going from T=0 to T=0.8 dropped my α from 0.71 to 0.58. Higher temperature means the target samples further from the draft's mode more often.
Tokenizer mismatch is fatal. Draft and target must share a vocabulary. A different tokenizer isn't "lower acceptance," it's broken output or a hard error.
Batch size can invert the whole thing. At batch size 1 verification is nearly free because the GPU was idle anyway. At high concurrency your target step is already compute-saturated, so verifying k extra positions across B sequences costs real FLOPs. Speculative decoding can reduce aggregate throughput on a busy server even with a great α. Benchmark at your actual concurrency, not at batch 1.

What I'd do differently

Route by workload instead of flipping one global flag.

My code-completion path runs with --draft-max 4 and gets a real 1.9x. My summarization path runs with speculative decoding off, because the best possible config there was 1.18x at k=1 and that isn't worth a second model in VRAM.

For the one endpoint that rewrites files I switched to n-gram speculation ("method": "ngram" in vLLM) instead of a draft model. When the output is mostly copied from the input, matching prompt n-grams is a near-perfect draft with c close to zero. No second model, no extra VRAM.

And if you're serious about a draft model, a trained speculator head like EAGLE or Medusa is a different class of tool. Those are trained against your specific target's hidden states, which is exactly the α problem attacked at the root instead of by tuning k.

So why does speculative decoding make some models slower?

Speculative decoding makes your LLM slower whenever the acceptance rate is too low to pay for the draft model's compute. The speedup is E(k)/(1 + k·c), where the gain from a longer draft decays geometrically as α^k while the cost grows linearly as k·c. On unpredictable text with α around 0.3, a draft length of 16 spends 16 cheap forward passes to buy roughly 1.5 tokens and lands near half your original throughput. Measure α per workload from your server's accepted-vs-drafted counters, sweep k with the formula before deploying, and keep in mind that the right k for JSON generation is not the right k for chat.

Written by the developer behind Preterview, an interview prep platform.

Docker Compose depends_on Doesn't Wait. Neither Does pg_isready

jidonglab — Tue, 15 Sep 2026 16:57:28 +0000

Nine of my last 47 CI runs died on the same line:

Error: connect ECONNREFUSED 172.19.0.3:5432

Same commit. Same image. Same compose file. On my laptop, green every single time. In CI, a coin flip with a bad attitude.

The cause was four characters of YAML I had copy-pasted for years without ever reading:

depends_on:
  - db

Docker Compose depends_on doesn't wait for your database. It waits for a container. Those are two completely different events, and the gap between them is where your flaky integration tests live.

TL;DR

depends_on in short list syntax only waits for the dependency container to start (condition: service_started). It knows nothing about the process inside.
To actually wait, use the long syntax with condition: service_healthy and define a healthcheck on the dependency. No healthcheck means no waiting, silently.
pg_isready with no -h talks to the Unix socket. On a fresh volume the official Postgres image runs a temporary server on that socket while init scripts execute, so your healthcheck turns green before TCP 5432 is open. Use pg_isready -h 127.0.0.1.
That's why it only breaks in CI: CI starts with an empty volume, your laptop has a warm one, so your laptop never sees the init phase.
Healthchecks fix startup ordering. They don't fix reconnects. Keep retry logic in the app anyway.

What does depends_on actually wait for in Docker Compose?

It waits for the container to reach the running state, and nothing more. Docker Compose depends_on in its short form expands to condition: service_started, which means "the container process has been launched." Postgres launching and Postgres accepting a connection on port 5432 are separated by anywhere from 200ms to about 15 seconds, depending on whether the data directory already exists.

depends_on gives you three real guarantees, and it's worth knowing exactly what they are:

Start order. Dependencies come up first.
Stop order. Dependents go down first.
Nothing else.

It is not a readiness gate. It's a topological sort.

You can watch the gap yourself:

docker compose up -d db
docker compose exec db pg_isready -h 127.0.0.1
# pg_isready: no response  ← container is "up", DB is not

The container is running. docker compose ps says running. Your API container already started, already dialed 5432, already crashed, and if you set restart: no it's already gone.

Why does adding a healthcheck still not fix it?

Because the healthcheck can be subtly wrong in two ways, and Docker will report both of them as "healthy."

Wrong tool. This is the classic:

healthcheck:
  test: ["CMD", "curl", "-f", "http://localhost:8080/health"]

Most slim and alpine images don't ship curl. The probe fails forever, the container sits in starting then flips to unhealthy, and your dependent service never boots at all. You get a hang instead of a crash, which is somehow worse to debug. Also note CMD vs CMD-SHELL: with CMD the list is exec'd directly, so ||, $VARS, and pipes do nothing. If you want shell semantics, you must say CMD-SHELL.

Wrong endpoint. This one is the actual villain in my CI logs:

test: ["CMD-SHELL", "pg_isready -U app -d app"]

Looks perfect. Ships with the image. Exits 0 when Postgres is accepting connections. It's also wrong, and here's the mechanic.

When the official Postgres image boots with an empty data directory, it does a two-phase startup. Phase one: initdb creates the cluster, then the entrypoint starts a temporary server to run everything in /docker-entrypoint-initdb.d. That temporary server deliberately does not listen on TCP — the entrypoint starts it with empty listen_addresses, so it's reachable only over the Unix socket inside the container. Phase two: the temp server is shut down and the real one starts, this time on 0.0.0.0:5432.

pg_isready with no -h connects over the Unix socket. So during phase one it gets a happy answer, exits 0, Docker marks the container healthy, Compose releases your API container, and your API dials TCP 5432 into a closed port.

The fix is one flag:

test: ["CMD-SHELL", "pg_isready -h 127.0.0.1 -U app -d app"]

-h 127.0.0.1 forces a TCP connection to the container's own loopback, which is exactly the thing your dependent service is about to do. During phase one it returns non-zero, so the container stays starting, so Compose keeps waiting. That's the whole bug.

And this is why it only ever broke in CI. My laptop had a populated pgdata volume from months ago, so the init phase never ran and phase one didn't exist. CI creates a fresh volume every run. The flake rate wasn't random — it tracked how long the seed scripts took that day.

MySQL has the same two-phase shape, by the way. mysqladmin ping can answer during the init window too. Same class of bug, same class of fix: probe the thing over the network path your app will actually use.

What's the Docker Compose config that actually works?

Long syntax, real healthcheck, migrations as their own gate:

services:
  db:
    image: postgres:16
    environment:
      POSTGRES_USER: app
      POSTGRES_PASSWORD: app
      POSTGRES_DB: app
    volumes:
      - pgdata:/var/lib/postgresql/data
    healthcheck:
      # -h 127.0.0.1 forces TCP. Without it this passes during
      # the init-scripts phase, when TCP 5432 is still closed.
      test: ["CMD-SHELL", "pg_isready -h 127.0.0.1 -U app -d app"]
      interval: 2s
      timeout: 3s
      retries: 30
      start_period: 5s

  migrate:
    build: .
    command: ["npm", "run", "migrate"]
    depends_on:
      db:
        condition: service_healthy

  api:
    build: .
    depends_on:
      db:
        condition: service_healthy
      migrate:
        condition: service_completed_successfully

volumes:
  pgdata:

Three things to read carefully there.

interval: 2s with retries: 30 is a 60-second patience budget. Default interval is 30s, which in a fresh-volume CI run means you either wait half a minute for a database that was ready in four seconds, or you blow the retry count. Short interval, generous retries.

start_period: 5s is not a sleep. Probes still run during it — a success inside the start period marks the container healthy immediately. What it changes is that failures during that window don't count against retries and don't mark the container unhealthy. It's a grace period, not a delay.

service_completed_successfully is the one condition people never discover. The migrate service runs, exits 0, and only then does api start. If migrations exit non-zero, api never launches and docker compose up fails loudly instead of starting an app against a half-migrated schema.

What still breaks after you fix this?

Healthy is not the same as correct, and a few sharp edges survive the fix:

Healthy ≠ migrated ≠ seeded. pg_isready says the server accepts connections. It says nothing about whether your tables exist. That's what the migrate gate above is for.
Healthy ≠ healthy forever. A database that passes at t=0 can OOM at t=90. depends_on is a startup gate, fired once. Your app still needs connection retry with backoff. This is the part people skip after adding healthchecks, and it's the part that pages you at 3am.
Swarm ignores it. docker stack deploy drops depends_on entirely. If you're targeting Swarm, the ordering you wrote is decorative.
CI needs --wait. docker compose up -d returns as soon as containers are created. Use docker compose up -d --wait (with --wait-timeout) so the command doesn't exit until everything is healthy, then run your tests.
Check that the probe exists at all. If you define no healthcheck, docker inspect --format '{{json .State.Health}}' <container> prints null, and condition: service_healthy on that service will error out rather than quietly wait. Good — but it means a typo'd healthcheck key fails in a completely different way from a missing one.

So does Docker Compose depends_on wait for the database?

No. Docker Compose depends_on in short list syntax only waits for the dependency's container to start, which for a database is several seconds before it accepts connections. To make it actually wait, define a healthcheck on the dependency and switch to the long syntax with condition: service_healthy. Then make sure the healthcheck probes the same network path your app uses: pg_isready without -h checks the Unix socket, which answers during the Postgres image's init-scripts phase while TCP 5432 is still closed, so use pg_isready -h 127.0.0.1 instead. Pair it with a migration service gated by service_completed_successfully, keep interval short and retries high, and keep reconnect logic in your application, because startup ordering and runtime resilience are different problems.

Written by the developer behind Preterview, an interview prep platform.

Ollama keep_alive: My Model Reloaded 214 Times in One Day

jidonglab — Tue, 15 Sep 2026 04:56:17 +0000

My local chat app was fast every single time I tested it, and slow every single time I actually used it.

That's the tell, and I ignored it for weeks. I'd type a question during development, get a first token in under a second, ship the change. Then I'd come back after lunch, ask one thing, and sit there for eleven seconds watching a cursor blink. Same box. Same model. Same prompt.

It wasn't the model being slow. It was Ollama loading the model off disk again, because it had quietly evicted it while I was living my life. The knob is called keep_alive, and Ollama keep_alive turns out to have three separate ways of not doing what you think it does.

So I put a timer on every request for 24 hours. 1,180 requests, 214 model load events. Here's the autopsy.

TL;DR

Ollama unloads a model after 5 minutes idle by default. Any request arriving after that pays a full cold load from disk.
On my box that cold load cost 11.4s to first token vs 0.9s warm — 18.1% of my requests were cold, which dragged my overall p50 to 3.1s.
Passing keep_alive in the request body did nothing on the OpenAI-compatible /v1/chat/completions endpoint. The native /api/chat endpoint honors it.
Setting keep_alive: -1 on two models that don't both fit in VRAM made things worse, not better: partial CPU offload dropped generation from 42 tok/s to 6 tok/s.
The fix was boring: OLLAMA_KEEP_ALIVE=24h as a server-side env var, one resident model per GPU, embeddings moved to a separate CPU-only Ollama instance. Loads went 214/day → 9/day.

Why does Ollama reload my model on every request?

Because Ollama's default keep_alive is 5 minutes. After five minutes with no traffic, the runner exits and the weights leave VRAM. The next request re-reads gigabytes from disk, re-allocates VRAM, and only then starts generating.

This is a completely reasonable default for a laptop. It is a terrible default for anything with bursty traffic, which is every side project ever built.

My setup, so you can judge whether my numbers transfer:

One box, 16GB VRAM, models on an NVMe drive
llama3.1:8b for chat (~4.9GB), qwen2.5-coder:14b for a code helper (~9GB), nomic-embed-text for embeddings (~274MB)
Three clients: a chat UI I use by hand, a cron job that summarizes my notes every 10 minutes, and a small RAG indexer

Look at that cron interval. Every 10 minutes, against a 5-minute idle timeout. That job was cold 100% of the time. It had never once hit a warm model. For weeks I assumed "local summarization just takes 12 seconds."

How do I check if Ollama is reloading my model?

Two commands, thirty seconds, and you'll know.

First, is anything resident right now?

ollama ps

If that's empty while you think your model is "running," it's not. It's on disk. UNTIL in that output is your real keep_alive, not what you put in your config.

Second, count load events in the server log over a day:

# Linux (systemd)
journalctl -u ollama --since "24 hours ago" | grep -ci "llama runner started"

# macOS
grep -ci "llama runner started" ~/.ollama/logs/server.log

Log wording drifts between versions, so grep your own log once by hand and pick the line that appears exactly once per load. Mine said 214 over a day against 1,180 requests. That ratio is the whole story: one reload for every 5.5 requests.

Then I wrapped the client to record time-to-first-token, because "it feels slow sometimes" is not a bug report:

import time, json, requests

def ttft(prompt, model="llama3.1:8b"):
    t0 = time.perf_counter()
    r = requests.post("http://localhost:11434/api/chat",
                      json={"model": model,
                            "messages": [{"role": "user", "content": prompt}],
                            "stream": True},
                      stream=True)
    for line in r.iter_lines():
        if not line:
            continue
        chunk = json.loads(line)
        if chunk.get("message", {}).get("content"):
            return time.perf_counter() - t0   # first real token

Log that number with a timestamp for a day. The histogram was not a bell curve. It was two spikes: one at 0.9s, one at 11.4s. Nothing in between. That shape means you have a binary state problem, not a slow model.

Does keep_alive work on the OpenAI-compatible endpoint?

In my testing, no. This is the part that cost me an entire evening.

My app talked to Ollama through the OpenAI SDK, pointed at /v1, because that's the path of least resistance when you want to swap providers later. So I did the obvious thing and added keep_alive to the request:

client.chat.completions.create(
    model="llama3.1:8b",
    messages=[...],
    extra_body={"keep_alive": "24h"},   # did nothing on my version
)

Load count the next day: 200-something. Unchanged. I'd "fixed" it and the graph didn't move, which is the only reason I caught it. If I hadn't been counting loads, I would have declared victory and kept eating 11-second requests.

keep_alive is an Ollama concept, not an OpenAI one, and the compatibility layer on my version drops it. The native endpoint honors it fine:

curl http://localhost:11434/api/chat -d '{
  "model": "llama3.1:8b",
  "messages": [{"role":"user","content":"hi"}],
  "keep_alive": "24h"
}'

Don't take my word for the version behavior. Send one request, then run ollama ps and read the UNTIL column. If it says 5 minutes from now, your keep_alive was ignored, whatever the docs say about your build.

Why did keep_alive: -1 make my local LLM slower?

Because -1 means "never unload," and never-unload plus two models that don't both fit in 16GB means something has to give. What gives is layer placement.

I set keep_alive: -1 on both the 8B chat model and the 14B coder model, feeling clever. Loads dropped from 214 to about 60 a day. Latency got worse.

With both pinned, the 14B model no longer got a clean full-GPU allocation. It landed partially on the GPU with the remaining layers on CPU. Generation went from 42 tok/s to 6 tok/s. A 400-token answer went from 10 seconds to over a minute. I had traded a one-time 11-second cold start for a permanent 7x tax on every token.

The lesson I'd tattoo on the inside of my eyelids: a cold start is cheaper than a partial offload. Reloading is a fixed cost paid once. Spilling layers to CPU is a cost paid per token, forever, silently, and it never shows up in a load counter.

What actually fixed it?

Four changes, in order of how much they mattered.

1. Set keep_alive on the server, not in requests. One env var covers every client, including the ones you forgot about and the ones going through /v1:

# /etc/systemd/system/ollama.service.d/override.conf
[Service]
Environment="OLLAMA_KEEP_ALIVE=24h"

sudo systemctl daemon-reload && sudo systemctl restart ollama

On macOS, launchctl setenv OLLAMA_KEEP_ALIVE 24h before starting the app. Setting it in your shell profile does nothing, because the server isn't your shell.

2. One resident model per GPU. The chat model stays loaded. The coder model is invoked maybe 15 times a day, so I let it cold start and I stopped pretending that mattered. Alternating two big models on one GPU is thrash, and no timeout setting fixes thrash.

3. Embeddings on a separate CPU-only instance. The indexer was firing hundreds of tiny embedding calls and stealing VRAM for a 274MB model that runs fine on CPU:

CUDA_VISIBLE_DEVICES="" OLLAMA_HOST=127.0.0.1:11435 ollama serve

Point the indexer at :11435, leave :11434 for the chat model. Two processes, zero contention.

4. I deleted my warmup cron. Before I understood any of this, my instinct was a job pinging the model every 4 minutes to keep it hot. It worked, sort of, and it also kept the GPU awake 24/7 for a model I use in two bursts a day. OLLAMA_KEEP_ALIVE does the same job without a second moving part to debug at 2am.

What did it cost, in numbers?

One box, one workload, 24 hours before and 24 hours after.

Metric	Before	After
Requests logged	1,180	1,206
Model load events	214	9
Cold requests	18.1%	0.8%
p50 time to first token	3.1s	1.0s
p95 time to first token	12.6s	1.9s
Cron summarizer, cold rate	100%	0%
Chat generation speed	42 tok/s	42 tok/s

That last row is the one I keep pointing at. Tokens per second never changed. The model was never slow. Every second I'd spent for weeks blaming quantization, context length, and my GPU was time spent in open().

Caveats, because I'd want them from you: this is one machine, one GPU, one traffic shape, one Ollama version. The /v1 behavior in particular is a version detail and might already differ on yours. The method transfers even if my numbers don't. Count loads, measure first-token latency, and read ollama ps instead of trusting a config file.

So what does Ollama keep_alive actually do?

Ollama keep_alive controls how long a model stays resident in memory after its last request, defaulting to 5 minutes, after which the next request pays a full cold load from disk — in my case 11.4s to first token instead of 0.9s. Set it server-side with OLLAMA_KEEP_ALIVE rather than per-request, because the OpenAI-compatible /v1 endpoint ignored the body parameter in my testing. Verify with ollama ps and by counting runner-start lines in the server log, not by reading your config. And resist keep_alive: -1 on multiple models sharing one GPU: pinning models that don't both fit forces partial CPU offload, which cost me 42 tok/s down to 6 tok/s and is far worse than the cold start you were trying to avoid.

Written by the developer behind Preterview, an interview prep platform.

vLLM Preemption: Why 1 in 50 Requests Restarts From Scratch

jidonglab — Mon, 14 Sep 2026 16:55:15 +0000

Our chat endpoint had a mean latency of 1.9s and a p99 of 11.4s.

Same model. Same GPU. Same prompt template. nvidia-smi showed 96% utilization and no memory pressure worth mentioning. Nothing crashed. Nothing retried. But roughly one request in fifty would stream a few tokens, freeze for six seconds mid-sentence, then finish normally like nothing happened.

That freeze has a name: vLLM preemption. The scheduler evicted a request that was already 80% done, threw away every KV block it had built up, and put it back in the queue to be prefilled again from token zero. My users paid for those tokens twice. So did my GPU.

(Numbers in this post are from my own staging box, a single 48 GB card serving Llama-3.1-8B-Instruct in fp16. They are not published benchmarks, and yours will differ.)

TL;DR

vLLM preemption happens when the KV cache pool runs out of free blocks while requests are still generating. The scheduler evicts in-flight requests to keep the batch moving.
Default mode is RECOMPUTE: the evicted request's KV cache is discarded entirely and re-prefilled later. Work already done is gone.
It shows up as p99 latency spikes and mid-stream stalls, never as an error. Mean latency and GPU utilization both look healthy.
Root cause is almost always max_num_seqs (default 256) admitting far more concurrent sequences than your KV pool can hold at your real p95 output length.
Fix: watch vllm:num_preemptions_total, cap max_num_seqs to what the pool actually sustains, and bound max_tokens per request.

What does vLLM preemption actually mean?

vLLM preemption is the scheduler kicking a running request out of the batch because there is no free KV cache block left to append its next token.

This is not admission queueing. Admission queueing is fine and fair: requests sit in the waiting queue, you see them in num_requests_waiting, first in first out. Preemption is the opposite. It punishes requests that already made it in, already burned prefill compute, already streamed tokens to a human who is watching.

Here is the mechanism, in order:

PagedAttention stores KV in fixed-size blocks (16 tokens each by default), like pages in virtual memory.
Every running sequence needs a fresh block roughly every 16 generated tokens.
The pool is finite. It is whatever GPU memory is left after weights and activation profiling, governed by gpu_memory_utilization (default 0.9).
When a running sequence needs a block and none is free, the scheduler picks a victim from the running batch and preempts it.
In RECOMPUTE mode (the default), the victim's blocks are freed and the request goes back to the front of the waiting queue. Its generated text is kept; its KV cache is not. To resume, vLLM must prefill the original prompt plus everything it already generated.

Step 5 is the expensive part. A request that had produced 900 tokens does not resume at token 900. It re-prefills ~900 extra tokens of context before it can emit token 901.

vLLM does tell you. The log line reads roughly like: sequence group is preempted because there is not enough KV cache space, followed by advice to raise gpu_memory_utilization or tensor parallelism. If you are running with default log levels and only alerting on 5xx, you will never see it.

Why does the KV cache run out when GPU memory looks fine?

Because KV cache pressure is a function of live tokens, not request count, and live tokens grow the whole time a request is generating.

A request holding 4,000 tokens of context occupies 4,000 tokens' worth of KV. Ten of those cost the same as forty requests at 1,000 tokens. Your load test with fixed 128-token outputs told you nothing about the request that asks for a 2,000-token summary at 3pm.

The math is simple enough to do on a napkin:

# Llama-3.1-8B-Instruct, fp16, GQA
layers, kv_heads, head_dim, dtype_bytes = 32, 8, 128, 2

bytes_per_token = 2 * layers * kv_heads * head_dim * dtype_bytes
print(bytes_per_token)            # 131072  == 128 KiB per token

kv_pool_gib = 24                  # what was left after weights on my box
max_live_tokens = kv_pool_gib * 1024**3 // bytes_per_token
print(max_live_tokens)            # 196,608   (~8,192 tokens per GiB)

# my real traffic: ~2,000 prompt tokens, p95 output ~1,500
live_per_request = 2000 + 1500
print(max_live_tokens // live_per_request)   # 56

Fifty-six. That is how many sequences my pool could hold at p95 shape.

max_num_seqs defaults to 256.

So the scheduler cheerfully admitted up to 256 concurrent sequences into a pool that supports 56 of them once they grow up. Everything looked great for the first few hundred generated tokens, then the pool hit 100% and the evictions started. And because a preempted request comes back, re-prefills, and immediately competes for blocks again, it can get preempted a second time. That is the thrash.

Why does vLLM preemption wreck p99 instead of mean latency?

Because preemption is rare and catastrophic, which is exactly the shape that hides in an average.

Ninety-eight percent of requests never get chosen as a victim and run at normal speed. The two percent that do pay: the stall while they sit in the waiting queue, plus a full re-prefill of prompt + generated-so-far, plus whatever queueing they hit on the way back in. On my box those requests landed 4-6x their normal latency. Averaged over the whole window, the mean barely moved.

GPU utilization actively lies to you here. Recompute is dense prefill work. The GPU is extremely busy doing it. Your dashboard reads "96% utilized, great throughput" while a meaningful slice of that throughput is tokens you already computed once.

The metric that does not lie is the counter:

curl -s localhost:8000/metrics | grep -E 'preemption|cache_usage|num_requests'
# vllm:num_preemptions_total{...}      <- should be flat at 0
# vllm:gpu_cache_usage_perc{...}       <- if this parks near 1.0, you are about to preempt
# vllm:num_requests_running{...}
# vllm:num_requests_waiting{...}

vllm:num_preemptions_total is a counter. Alert on its rate, not its value. Any sustained nonzero rate in production means you are paying for prefill twice.

And watch gpu_cache_usage_perc. If it sits pinned above ~0.9 during peak, you are one long request away from thrashing.

How do you stop vLLM preemption?

Cap concurrency at what the KV pool can actually sustain, and make queueing happen at the door instead of mid-generation.

The config that fixed mine:

vllm serve meta-llama/Llama-3.1-8B-Instruct \
  --max-num-seqs 48 \
  --max-model-len 8192 \
  --gpu-memory-utilization 0.92

In priority order:

Lower max_num_seqs. This is the big one. Compute your sustainable concurrency from the napkin math above using your p95 live-token count, then set max_num_seqs a bit under it. Excess load waits in the admission queue, which is fair, observable, and cheap. Yes, your num_requests_waiting gauge will go up. That is the point: visible queueing beats invisible recompute.
Bound max_tokens per request. An unbounded max_tokens from a client is a request that can grow until it destabilizes everyone else's batch. Clamp it server-side. Most endpoints do not need 4,000 tokens of output.
Nudge gpu_memory_utilization up. Going from 0.90 to 0.92-0.94 buys real blocks. Do it in small steps and actually load-test, because the headroom left over is what absorbs activation spikes.
Keep prefix caching on. It is on by default in the V1 engine. When a preempted request comes back, freed blocks that have not been overwritten can still be hit on the recompute path, which softens the worst case. It reduces the cost of preemption; it does not prevent it.
Load-test with your real output-length distribution. Fixed-length synthetic load is the reason this bug ships. Replay actual production prompt and completion lengths, or you are testing a workload that does not exist.

Swapping to CPU (--swap-space) moves blocks over PCIe instead of recomputing. It trades one cost for another and it is a band-aid, not a fix. Reach for concurrency limits first.

So why does one request in fifty restart from scratch?

Because vLLM's scheduler will admit more concurrent sequences than your KV cache can hold once those sequences grow, and when the block pool runs dry it preempts a running request, discards its entire KV cache, and re-prefills it from the beginning later. The default max_num_seqs of 256 is far above what most single-GPU deployments can sustain at real output lengths, so the failure only appears under load, only affects a small fraction of requests, and never raises an error. Check vllm:num_preemptions_total. If it is climbing, cap max_num_seqs to your measured sustainable concurrency and clamp max_tokens per request. Your mean latency will barely change. Your p99 will fall off a cliff, in the good direction.

Written by the developer behind Preterview, an interview prep platform.

Nginx proxy_buffering Ate My LLM Stream: 11s to First Token

jidonglab — Mon, 14 Sep 2026 04:54:15 +0000

On my laptop the report streamed in like a little typewriter. Token by token, 0.4 seconds to the first character, exactly the experience I wanted.

Then I deployed it. In production the page sat there doing absolutely nothing for eleven seconds, and then slammed all 1,800 tokens into the DOM in a single frame. Same code. Same model. Same prompt.

I spent three days blaming the model. It was nginx proxy_buffering. And behind nginx there were three more layers doing the same thing, each one politely holding my tokens hostage for my own good.

TL;DR

If your LLM stream arrives all at once in production but streams fine locally, a proxy is buffering it. proxy_buffering on is the nginx default and it will happily collect your entire SSE response before forwarding one byte.
Turning off proxy_buffering alone barely helped me: 11.4s to 9.1s. gzip was the bigger dam. Compression buffers your event stream too.
The full fix was four layers: nginx buffering, gzip, CDN transform, and my own token-chunking code. Final result: 0.7s to first visible token.
Diagnose it in one command, not three days: curl -N through the proxy, then curl -N straight at the origin port. If the origin is fast and the proxy is slow, stop reading your Python.
Bonus bug found on the way: proxy_read_timeout defaults to 60s, which silently truncated every report that ran longer than a minute.

What was actually streaming here?

The system is the written-report step of Preterview, an interview prep platform I run (full disclosure: I built it). It runs a realistic voice interview, then generates a scored written report from the transcript. That report is 1,500 to 2,000 tokens of markdown, which takes long enough to generate that streaming isn't a nicety, it's the difference between "thinking" and "broken."

The stack is boring on purpose: FastAPI + StreamingResponse, Server-Sent Events, uvicorn on 127.0.0.1:8000, nginx in front, a CDN in front of that. Nothing exotic. That's the point. Every layer in that list buffers by default, and every one of them thinks it's helping.

Here's what a dead stream cost me in real user behavior: in the week before I fixed it, 41 of 120 report sessions had a page reload before the report finished. People assumed it had hung, because from the browser's point of view it had. Each reload kicked off another generation. I was paying twice to deliver a worse experience.

Why does nginx proxy_buffering break SSE token streaming?

Because nginx proxy_buffering exists to protect your app server from slow clients. It reads the upstream response as fast as the upstream can produce it, parks it in memory (and then on disk), and drips it out to the client at the client's pace. For a 400KB JSON payload that's genuinely good engineering. Your Python worker gets freed immediately instead of babysitting someone on hotel wifi.

For SSE it's a catastrophe, because the value of the response is entirely in its timing. nginx doesn't know that. It sees bytes. It fills a 4k buffer, and only when that buffer is full (or the upstream closes the connection) does the client see anything.

So with proxy_buffering on, the "stream" becomes: generate for eleven seconds, buffer, flush once. Which is exactly the shape of the bug I saw.

The two fixes:

location /api/report/stream {
    proxy_pass http://127.0.0.1:8000;
    proxy_http_version 1.1;
    proxy_set_header Connection '';

    proxy_buffering off;
    proxy_cache off;
    gzip off;

    proxy_read_timeout 3600s;
    chunked_transfer_encoding off;
}

Or, better if you don't want to touch nginx config for every new endpoint, let the app declare it per response:

return StreamingResponse(
    token_generator(),
    media_type="text/event-stream",
    headers={
        "Cache-Control": "no-cache, no-transform",
        "X-Accel-Buffering": "no",
        "Connection": "keep-alive",
    },
)

X-Accel-Buffering: no is nginx's own opt-out header, and it's the one I'd reach for first. It travels with the response, so a new streaming route works without a deploy of your proxy config.

I lost an afternoon on this header because I set it on the wrong thing. I emitted it inside the first SSE event instead of on the HTTP response headers. It arrived as part of the body, nginx never saw it as a header, and the stream stayed dead. Headers go on the StreamingResponse, not in the generator.

What were the four layers, and what did each one cost?

Four things buffered my tokens. Here's the measured time to first visible token in the browser, on the same 1,800-token report, fixing one layer at a time:

Stage	First visible token
Production baseline	11.4s
`proxy_buffering off`	9.1s
gzip excluded for `text/event-stream`	3.2s
CDN: correct content-type + `no-transform`	1.9s
My own chunking removed	0.7s
(Local dev, for reference)	0.4s

Layer 1: nginx proxy_buffering. 11.4s to 9.1s. A 2.3 second improvement on a problem I was certain was 100% nginx. That gap is the whole lesson of this post: I almost reverted the fix because it "didn't work."

Layer 2: gzip. This is the one that gets people. gzip has to accumulate input before it can emit a compressed block, so a compressor sitting in your response path is a buffer whether or not you disabled the other buffer. text/event-stream is not in nginx's default gzip_types, so you'd think you're safe. I wasn't, because I'd added a wide gzip_types list years earlier and copied it forward into every server block since. Check yours before you assume. Removing it: 9.1s to 3.2s.

Layer 3: the CDN. Anything that can transform your response body can hold it. In my case the stream was leaving my origin with a content-type the edge didn't recognize as streamable, because I was setting media_type on an inner response object and the outer one defaulted to application/json. Setting text/event-stream correctly and sending Cache-Control: no-cache, no-transform took it to 1.9s. If you're not sure, bypass the CDN with a direct DNS entry to your origin and measure again. Don't theorize about edge behavior, measure it.

Layer 4: me. This was the embarrassing one. My generator wasn't yielding tokens, it was accumulating them until a "markdown-safe boundary" — a closed **, a finished list item — so the UI never flashed a half-rendered bold marker. That felt clever. In practice it held 40 to 80 tokens at a time, and inside a heading or a fenced code block it held far longer. I was the fourth proxy in my own stack. I ripped it out and made the renderer tolerant of partial markdown instead, which is where that logic belonged. 1.9s to 0.7s.

How do you find which layer is buffering your stream?

Bisect at the proxy boundary, with two curl calls. This takes about ninety seconds and would have saved me three days.

# through the proxy, from outside
curl -N -s -o /dev/null -w 'ttfb %{time_starttransfer}s\n' \
  https://api.example.com/api/report/stream

# straight at the origin, on the box, skipping nginx entirely
curl -N -s -o /dev/null -w 'ttfb %{time_starttransfer}s\n' \
  http://127.0.0.1:8000/api/report/stream

time_starttransfer is time to first byte, which for a stream is the only number that matters. -N disables curl's own output buffering, and forgetting it is the classic false positive: curl will happily make a perfectly healthy stream look broken.

My two numbers were 0.5s at the origin and 11.4s through the proxy. That single comparison rules out the model, your prompt, your token generator, your event loop, and your frontend, all at once. If the origin is fast, no amount of staring at your Python is going to help you.

For the layers above nginx, keep bisecting the same way: hit the origin's public IP directly to skip the CDN, then compare with the CDN in path.

Should you just turn proxy_buffering off everywhere?

No, and I tried, which is how I learned why not. I put proxy_buffering off in the http block because it was one line instead of many, and file uploads and large JSON responses got measurably worse under concurrency. That's the feature working as designed: with buffering off, a slow client's pace becomes your app worker's pace, and your workers spend their time trickling bytes to phones on bad connections instead of serving requests.

Scope it to the streaming location, or use X-Accel-Buffering: no per response. Buffering is the right default for almost every route you have. It's wrong for exactly the routes where time-to-first-byte is the product.

One more thing to set while you're in that block: proxy_read_timeout defaults to 60 seconds, measured between reads from upstream. Long report generations hit it and the connection closed at almost exactly 60.0s, mid-sentence, with no error anywhere in my application logs. Six of those 120 sessions had silently truncated reports and I'd never noticed, because a truncated markdown report still looks like a report.

So what actually fixes an LLM stream that arrives all at once?

If your tokens stream locally and arrive in one lump in production, the cause is buffering between your app and the browser, not your model or your generator. Set proxy_buffering off (or send X-Accel-Buffering: no) on the streaming route, disable gzip for text/event-stream, send Content-Type: text/event-stream with Cache-Control: no-cache, no-transform so your CDN passes it through untransformed, raise proxy_read_timeout well past your longest generation, and then check whether your own code is batching tokens before it yields them. Confirm each layer with curl -N through the proxy versus straight at the origin. Four layers, 11.4 seconds to 0.7, and three of the four were defaults I never chose.

Written by the developer behind Preterview, an interview prep platform.

git rerere: Stop Resolving the Same Merge Conflict Twice

jidonglab — Sun, 13 Sep 2026 16:53:09 +0000

Ninth rebase of a three-week-old branch onto main. Same file. Same forty lines of conflict markers. Same resolution I had already typed eight times, character for character.

Git watched me do it every single time and never once offered to help.

Except it can. git rerere has shipped inside git for roughly two decades, it is off by default, and almost nobody turns it on. It stands for reuse recorded resolution: git memorizes how you resolved a conflicted hunk and silently replays that resolution the next time the exact same hunk shows up.

That is the good news. The rest of this post is the part that actually matters: how git rerere decides two conflicts are "the same," why it misses conflicts you swear are identical, and the case where it confidently replays a resolution that is now wrong.

TL;DR

git config --global rerere.enabled true is the whole setup. Git then records every conflict resolution you commit into .git/rr-cache/.
Next time the identical conflict appears, git resolves the file in your working tree and prints Resolved '<file>' using previous resolution.
rerere keys on a normalized preimage of the conflicted hunk, not on the filename or the commit. Change the surrounding context lines and it becomes a different conflict with a different ID, and rerere goes quiet.
It does not make rebase hands-free. Git still stops, the path still shows as unmerged, you still run git add and git rebase --continue. Add rerere.autoUpdate true to skip the git add.
The footgun: rerere will happily replay a stale resolution. git rerere forget <path> while the conflict is on screen is the escape hatch.

What does git rerere actually do?

git rerere records the before-and-after of a conflict you resolved by hand, then reapplies that resolution automatically when the same conflict reappears.

Mechanically, git keeps a cache directory at .git/rr-cache/. When a merge, rebase or cherry-pick hits a conflict, git computes an ID for each conflicted hunk and writes the conflicted text to .git/rr-cache/<id>/preimage. When you finish resolving and commit, git writes your resolved text to .git/rr-cache/<id>/postimage. The mapping from conflict ID to current state also lives in .git/MERGE_RR.

Next time a conflict hashes to an ID that already has a postimage, git drops your recorded resolution straight into the working tree.

This is exactly the shape of the long-lived-branch problem. You rebase, you hit the conflict, you resolve, you rebase again a week later, the same two hunks fight again. First resolution is real work. Every replay after that is free.

How do I turn on git rerere?

One line, globally:

git config --global rerere.enabled true

Two optional settings worth knowing:

# stage rerere-resolved files automatically instead of leaving them unmerged
git config --global rerere.autoUpdate true

There is also a quiet side door: if a .git/rr-cache directory exists, git treats rerere as enabled even without the config flag. That surprises people who inherited a repo from a teammate's tarball and wondered why conflicts were pre-solving themselves.

Here is a 60-second reproduction you can paste into a scratch directory and watch work:

mkdir rerere-demo && cd rerere-demo
git init -q
git config rerere.enabled true

printf 'version = 1\n' > config.txt
git add . && git commit -qm init
git branch -M main

git switch -qc feature
printf 'version = 2-feature\n' > config.txt
git commit -qam feature

git switch -q main
printf 'version = 2-main\n' > config.txt
git commit -qam main

git merge feature          # CONFLICT, as designed
printf 'version = 2-merged\n' > config.txt
git add config.txt
git commit -qm merged      # <- rerere records the resolution here

git reset --hard HEAD~1    # pretend that merge never happened
git merge feature

That last git merge prints:

Resolved 'config.txt' using previous resolution.

and config.txt already contains version = 2-merged. You never retyped it.

Why does git rerere miss conflicts that look identical?

Because rerere keys on the content of the conflicted hunk plus its surrounding context, not on the file path or the branches involved. Edit a line near the conflict and you have produced a different preimage, a different ID, and rerere has no recorded resolution for it.

This is the single biggest source of "rerere is broken" complaints, and it is not a bug. The cache is keyed by what the conflict looks like. Shift the context and you get a cache miss.

Two useful consequences:

It survives merge direction. rerere normalizes the two sides of the conflict, so a resolution you recorded merging feature into main is still recognized when the same hunk shows up merging main into feature. This is why the classic "test-merge your topic branch repeatedly, throw the merge away, merge for real at the end" workflow works so well with rerere on.

It does not survive reformatting. Run Prettier, Black, or gofmt over the neighborhood and every recorded resolution in that region turns into a miss.

Three commands tell you what rerere is thinking, and you can run them mid-conflict:

git rerere status     # which paths rerere has a preimage for
git rerere remaining  # which paths are still yours to solve
git rerere diff       # what changed between the conflict and the current state

git rerere remaining is the one I actually use. During a big rebase it tells me, in one line, which files are still real work and which ones the cache already handled.

Does git rerere make rebase automatic?

No, and this catches everyone. rerere resolves the content, it does not resolve the operation.

With plain rerere.enabled true, a rebase that hits a recorded conflict will:

stop, exactly like a normal conflict,
write the recorded resolution into the working tree,
leave the path listed under Unmerged paths in git status.

So the file on disk is already correct while git still calls it conflicted. You run git add <file> and git rebase --continue and move on.

Turning on rerere.autoUpdate stages those paths for you, which collapses the ritual to just git rebase --continue. The same behavior is available per-invocation with git merge --rerere-autoupdate and git rebase --rerere-autoupdate.

I keep autoUpdate on globally, with one habit attached: I read the Resolved '<file>' using previous resolution. lines in the scrollback before continuing. Which brings us to the dangerous part.

When does git rerere apply the wrong resolution?

When the conflicted hunk still hashes to the same ID but the correct answer has changed. rerere replays what you did last time. It has no idea whether that is still right.

The realistic version: months ago you resolved a conflict in a config block by keeping your branch's value. Since then the team decided main's value is now authoritative. The hunk is textually unchanged, so rerere matches it, replays "keep mine," and with autoUpdate on it stages the file. If you continue without reading the output, you have just silently reverted a decision.

The fix is git rerere forget:

# while the conflict is on screen
git rerere forget path/to/file

That drops the recorded resolution for the current conflict in that path and hands you the conflict markers back. If the file was already auto-resolved and staged, restore the markers first:

git checkout --conflict=merge path/to/file
git rerere forget path/to/file

Two more housekeeping facts. git gc prunes the cache on a timer, controlled by gc.rerereResolved (default 60 days for resolutions that were used) and gc.rerereUnresolved (default 15 days for conflicts you never finished). And .git/rr-cache is strictly local: it is not cloned, not pushed, not fetched. If you want a shared team cache you have to copy or symlink the directory yourself, which I would only do with a team that agrees on what "correct resolution" means.

Should you turn git rerere on?

Yes, with autoUpdate and one habit. The cost is a single config line and a directory inside .git that a gc run keeps trimmed. The benefit shows up the moment you maintain a branch that outlives a sprint, keep a long-running fork in sync, or do the test-merge-then-discard dance.

The habit: when you see Resolved '<file>' using previous resolution., glance at the diff before you continue. rerere is a cache, and like every cache the failure mode is not "no answer," it is "a confident stale answer."

So what is git rerere? git rerere is a built-in git feature that records how you resolved a merge conflict and automatically replays that resolution the next time the identical conflicted hunk appears in a merge, rebase or cherry-pick. Enable it with git config --global rerere.enabled true; add rerere.autoUpdate true so resolved paths are staged for you. It keys on the normalized content of the conflicted hunk, so changing surrounding lines makes it miss, and it will replay an out-of-date resolution without warning, which git rerere forget <path> undoes while the conflict is still open.

Written by the developer behind Preterview, an interview prep platform.

Claude Code in 4 Git Worktrees: 23 Tasks, 9 Collisions, 1.5x Speed

jidonglab — Sun, 13 Sep 2026 04:52:12 +0000

On Wednesday at 11:40am, four Claude Code sessions were running in four terminal tabs, each in its own git worktree, and all four of them were fighting over port 3000.

Agent 2 would start the Next.js dev server. Agent 4 would see "port in use", decide the old process was stale, and kill it. Agent 2 would then report that its Playwright check "failed due to a connection refused error, likely a flaky environment" and try again. They did this to each other for about 20 minutes before I noticed.

That was day 3 of a one-week experiment: run Claude Code in parallel git worktrees on a real side project and see if four agents really means four times the output. It doesn't. Here's what it actually means, with the numbers.

TL;DR

Running Claude Code in 4 git worktrees for 5 working days, I queued 23 tasks. 17 shipped, 4 needed heavy rework, 2 got thrown away.
9 of the 23 branches collided with another agent's work: 5 textual merge conflicts, 4 clean merges that broke main or staging anyway.
My throughput went from 11 shipped tasks the week before (one agent, sequential) to 17. That's 1.5x, not 4x.
The bottleneck moved from the agent to me. I spent 6.5 hours reviewing diffs, more than any single agent spent working.
What fixed most of it: per-worktree ports, one "migrations lane", file-ownership rules per task, and capping at 3 agents.

What was the setup?

The setup was one monorepo, four worktrees, four independent Claude Code sessions, and me as the merge queue. The project is a small SaaS I run on the side: a Next.js frontend, a FastAPI backend, Postgres with Alembic migrations, and Redis for caching.

Creating the worktrees is the easy part:

git worktree add ../app-wt1 -b feat/billing-export
git worktree add ../app-wt2 -b feat/team-invites
git worktree add ../app-wt3 -b fix/search-pagination
git worktree add ../app-wt4 -b feat/audit-log

Then cd into each one, run claude, and hand it a task from a list. Each worktree shares the same .git object store, so there's no re-cloning, but each has its own checked-out files, its own branch, and (as I learned) its own need for node_modules.

My rule for the week: every task gets a branch, every branch goes through CI, and I merge to main myself. No agent touches main.

How many tasks actually shipped?

Out of 23 tasks, 17 shipped with light edits, 4 needed heavy rework, and 2 were deleted. For comparison, the previous week I used a single Claude Code session sequentially and shipped 11 tasks.

Outcome	Count
Merged clean, shipped	12
Merge conflict, resolved quickly, shipped	5
Heavy rework (I rewrote 30%+ of the diff)	4
Thrown away	2

The 2 throwaways were both cases where the agent solved the task in a way that made another in-flight branch pointless. Agent 3 refactored the search query builder "while it was in there", which invalidated the approach Agent 1 was halfway through for billing export filters. Neither agent knew the other existed. Why would they?

Why do parallel Claude Code agents collide?

Parallel Claude Code agents collide because git worktrees isolate files, not shared resources or intent. Each agent sees a clean, consistent repo and makes locally correct decisions. The collisions happen at everything the worktrees don't isolate: ports, databases, lockfiles, shared utilities, and naming conventions.

Here are the 9 collisions, grouped by what caused them.

1. Lockfile conflicts (4 of 9)

Three agents added npm dependencies and one bumped a Python package. package-lock.json conflicts are textually huge and semantically boring. I resolved all four by taking main's lockfile and re-running npm install on the branch. Annoying, about 10 minutes each, never dangerous.

2. Duplicate Alembic migrations (2 of 9)

This one is nasty. Agent 2 (team invites) and Agent 4 (audit log) both needed a schema change. Both ran alembic revision --autogenerate from the same parent revision. Both branches merged without a single git conflict, because the migration files had different random revision IDs and different filenames.

Then CI on main ran alembic upgrade head and got this:

Multiple head revisions are present for given argument 'head'

Two heads. Fixable with alembic merge heads, but the first time it happened, it happened on main, and my deploy was blocked until I fixed it. The second time I caught it on the branch because I'd added alembic heads to CI with a check that the output is exactly one line.

3. Route index conflict (1 of 9)

Two agents registered new API routers by appending a line to the same routers/__init__.py. Classic adjacent-line conflict. Two minutes to fix.

4. The two that git couldn't see (2 of 9)

These are the ones that scared me, because both merged clean and both passed CI.

The rename. Agent 1 renamed formatPrice() to formatCurrency() across the frontend and updated all 14 call sites that existed on its branch. Meanwhile Agent 4 added 3 new call sites to formatPrice(). Git merged it happily. TypeScript caught it on main. Fine, that's what a typechecker is for, but main was red for 25 minutes.

The cache key. This one reached staging. Agent 2 cached team membership under user:{id}. Agent 4 cached audit-log summaries under user:{id}. Different modules, different files, zero textual overlap, unit tests all green because each test suite mocked Redis on its own. On staging, the invite page tried to parse an audit summary as a membership list and threw a 500.

No merge tool would have caught this. The only defense is a convention (I now namespace keys by module: teams:user:{id}) written somewhere every agent reads.

What about the environment problems?

Environment problems cost more wall-clock time than merge conflicts did. Git worktrees give you a fresh checkout, and a fresh checkout is missing everything your .gitignore hides.

Ports. All four dev servers defaulted to 3000 and the API to 8000. Agents killed each other's processes and blamed "flakiness". The fix was a tiny script I run when creating a worktree:

# wt-init.sh <n>
n=$1
echo "PORT=$((3000 + n))" >> .env.local
echo "API_PORT=$((8000 + n))" >> .env.local
echo "DATABASE_URL=postgresql://localhost/app_wt$n" >> .env.local
createdb "app_wt$n" 2>/dev/null
npm install --silent

One database. Before I added per-worktree databases, Agent 3 ran a test fixture that truncated the users table while Agent 2 was manually testing invites. Agent 2 spent a while "debugging" why its freshly created user vanished.
Disk. Each worktree's node_modules came out to about 1.1GB. Four of them plus build caches ate roughly 6GB. Not a crisis, but I didn't expect it.

What did it cost?

I'm on a flat subscription plan, so the dollar cost was fixed, but the usage limit was not. Four concurrent sessions hit my usage limit on day 3 at 2:40pm, and I lost the rest of that afternoon. On days 4 and 5, with three agents instead of four, I didn't hit it.

The bigger cost was my attention. I logged my review time: 6.5 hours across the week, over 23 diffs with a median size of 214 changed lines. The week before, with one agent, review took about 3 hours for 11 tasks. Per task it's similar. The problem is the arrival pattern: four branches landing within the same hour means context switching across four unrelated features, and that's where I made mistakes. The cache key bug went past me in review. I read that diff.

Is running multiple Claude Code agents in parallel worth it?

Yes, but at 3 agents with strict lanes, not 4 agents on a shared codebase free-for-all. The speedup is real (1.5x in shipped tasks for me) but it's capped by human review and by how independent your tasks really are.

Here's what I changed for week two:

Cap at 3 agents. Four exceeded both my usage limit and my review capacity.
One migrations lane. Only one worktree at a time is allowed to create an Alembic revision. Every other task prompt says: "Do not create migrations. If you need a schema change, stop and tell me."
File ownership in the prompt. Each task lists directories the agent may edit. "You may modify app/billing/ and web/app/billing/. Anything else, ask first." Claude Code mostly respects this, and when it doesn't, the diff makes it obvious.
No opportunistic refactors. A line in CLAUDE.md: "Do not rename or refactor shared utilities unless the task says to." This alone would have prevented both the rename break and one of the throwaways.
Rebase before review. Each agent runs git fetch && git rebase origin/main and re-runs tests before telling me it's done. Conflicts get resolved by the agent that has the context, not by me.
Conventions file. Cache key namespacing, route registration, env var naming. Written down once, read by every session.

Week two isn't over, but after three days: 11 tasks shipped, 1 collision (a lockfile), zero red main builds.

The short answer

Running Claude Code in parallel git worktrees does not multiply your output by the number of agents. In my week with 4 agents on a real monorepo, 23 tasks produced 17 shipped features (1.5x my single-agent week), 9 branches collided, and 4 of those collisions merged clean in git while breaking the build or behavior. Worktrees isolate files, not ports, databases, migrations, shared names, or intent, so the gains come from partitioning work so agents never touch the same resources, and from keeping the agent count at or below what one human can actually review.

Written by the developer behind Preterview, an interview prep platform.

Prompt Caching: Why cache_control Writes But Never Reads

jidonglab — Sat, 12 Sep 2026 16:50:22 +0000

I turned on prompt caching for an agent loop that resends a 12K-token system prompt on every turn. Obvious win, right? Input tokens are the whole bill in a tool loop.

The bill went up.

Not a little. Roughly a quarter. And nothing in the logs looked wrong. Every request returned 200. Latency was the same. The only place the truth was written down was the usage object:

cache_creation_input_tokens: 12184
cache_read_input_tokens: 0
input_tokens: 291

Twelve thousand tokens written to cache. Zero read back. Every single request. I paid the write premium 40 times in a row and never once collected. Prompt caching has exactly one invariant, and I had broken it in the most boring way possible.

TL;DR

Prompt caching is a prefix match. The cache key is the exact bytes of the rendered prompt up to each cache_control breakpoint. One changed byte at position N invalidates every breakpoint at or after N.
Render order is tools → system → messages. Anything volatile (timestamps, session IDs, the user's actual question) must sit after your last breakpoint, not before it.
Cache writes cost 1.25× base input (2× for the 1-hour TTL); reads cost about 0.1×. A cache that only ever writes is not a cache, it is a 25% surcharge.
Ground truth is usage.cache_read_input_tokens. If it is 0 across repeated requests with "identical" prompts, something upstream is rewriting your prefix.
Two silent killers that produce byte-identical payloads and still miss: the 20-position lookback window in long tool turns, and parallel fan-out, where an entry is only readable after the first response starts streaming.

Why does prompt caching never read from the cache?

Because your cache_control breakpoint is placed after content that changes every request, so each request writes a brand-new entry that nothing will ever match again.

The mental model that fixes this: the cache is not a key-value store keyed on "my system prompt." It is a prefix match over the rendered request. The API renders tools, then system, then messages, hashes the byte stream up to each breakpoint, and looks for an existing entry. First divergence wins. Everything downstream of it is cold.

So all three of these are the same bug:

# 1. The dynamic header
system = f"You are a support agent. Current time: {datetime.now()}.\n\n{PLAYBOOK}"
# PLAYBOOK is 11K stable tokens sitting behind a string that changes every request.

# 2. The nondeterministic serializer
system = "Schema:\n" + json.dumps(schema)   # no sort_keys=True
# Same dict, different key order, different bytes.

# 3. The per-user tool list
tools = build_tools_for(user)   # tools render at position 0
# Nothing caches across users, ever.

My case was #1, wearing a disguise: the timestamp was injected by a helper three call frames away that I had written months earlier for logging.

The pricing turns this from "suboptimal" into "actively worse than doing nothing." Writes are 1.25× base input price, reads are roughly 0.1×. Two requests that share a prefix break even (1.25 + 0.1 = 1.35 versus 2.0 uncached). One request that writes and is never read is 1.25× for nothing. Forty of them is a line item.

How do I tell whether prompt caching is working?

Read three fields off usage and remember that they partition your prompt: input_tokens is only the uncached remainder.

total prompt tokens = input_tokens
                    + cache_creation_input_tokens
                    + cache_read_input_tokens

That last part trips people up in both directions. An agent that ran for an hour showing input_tokens: 4200 is not magically cheap, and it is not broken either. Check the sum.

In a healthy multi-turn loop, the shape looks like this:

cache_read_input_tokens covers the whole prior prefix and grows turn over turn.
cache_creation_input_tokens is small, roughly last turn's output plus the newly appended input, because writes only bill the delta past the highest hit.
input_tokens is just the tail after your last breakpoint.

If cache_creation_input_tokens is instead near the full conversation size on every turn, the prefix is being rewritten upstream.

Make this a standing check, not a one-time look. The expensive failure mode in production is not a bad first implementation. It is a working implementation that regresses six months later, when someone adds a feature flag to the system prompt, and nothing errors, and the bill just drifts. One integration test earns its keep:

r1 = client.messages.create(**payload)
r2 = client.messages.create(**payload)   # byte-identical
assert r2.usage.cache_read_input_tokens > 0, "cache prefix broke"

To localize a break, log several consecutive request bodies and diff adjacent pairs. In a growing conversation the tail legitimately differs, so what you are checking is the overlap: the previous request's prompt should reappear unchanged as a prefix of the next. Strip cache_control markers before diffing, since the moving marker always differs and is not the culprit. The first divergence inside the overlap is your invalidator.

Where should the cache_control breakpoint go?

At the end of the shared portion of the prompt, never at the end of the whole prompt.

This is the mistake that produced my zero-read logs, and it is the same mistake automatic caching makes on your behalf. A top-level cache_control on the request places one breakpoint on the last cacheable block and slides it forward as the conversation grows. Perfect for a chat thread. Wrong for the pattern where a big fixed preamble is followed by a unique per-request question, because the breakpoint lands after the unique tail, so every request writes a distinct entry over bytes nobody will read.

messages = [{"role": "user", "content": [
    {"type": "text", "text": RETRIEVED_DOCS,        # 9K shared tokens
     "cache_control": {"type": "ephemeral"}},       # breakpoint HERE
    {"type": "text", "text": question},             # unique, unmarked, after
]}]

Four more placement rules worth internalizing:

Freeze the system prompt. Date, mode, user name and feature flags do not belong at the front of the prefix. On Opus 5 and Opus 4.8 you can append {"role": "system", "content": "..."} inside messages[] instead, which sits after the cached history and leaves it intact. Otherwise put it in a user turn.
Serialize tools deterministically and do not add, remove or reorder them mid-conversation. Tools render at position 0, so a reorder is a full rebuild.
Caches are model-scoped. Switching models mid-loop for a "cheap" side task forfeits the whole prefix. Give the subagent its own thread instead.
Minimum cacheable prefix is model-dependent and not monotonic (512 tokens on the newest models, 1024 on Opus 4.8 and Sonnet 5, 4096 on Opus 4.6 and Haiku 4.5). Below the minimum you get no error, just cache_creation_input_tokens: 0. A 3K-token prompt caches on some models and silently will not on others. Max 4 breakpoints per request.

What makes prompt caching miss on byte-identical requests?

Two mechanisms, and both of them make you doubt your own diff.

The 20-position lookback. Each breakpoint walks backward at most 20 positions looking for a prior entry. A run of consecutive tool_use blocks counts as one position, and so does a run of consecutive tool_result blocks, so heavy parallel tool calling is fine. A long sequential loop that appends more than 20 positions of other content in one turn is not: the next request's breakpoint never finds the previous entry, and you rewrite the whole conversation with a payload that diffs clean. Fix by placing an intermediate breakpoint every ~15 positions.

Parallel fan-out. An entry becomes readable only once the first response begins streaming. Fire 10 identical-prefix requests at once and all 10 pay full price, because none of them can read what the others are still writing. Send one, await the first streamed token, then fire the remaining nine. Same arithmetic applies to multi-agent designs: N workers each assembling a slightly different prompt over the same context write N entries and read none of each other's.

And on TTL: the default 5-minute entry has its timer refreshed for free by every read, measured from the start of the request. A four-minute generation leaves you about a minute for the next request to begin. The 1-hour TTL doubles the write cost, so it only pays off in the 5-to-60-minute gap, and needs at least three requests to break even.

So why does cache_control write but never read?

Because prompt caching is a prefix match, and a write-only cache means your breakpoint has volatile bytes in front of it. Something before the marker changes on every request (a datetime.now() in the system prompt, an unsorted json.dumps, a per-user tool list) or the marker itself sits after per-request content instead of at the end of the shared prefix. The fix is ordering, not more markers: put everything stable first, put the breakpoint at the last stable byte, put everything volatile after it, then verify with usage.cache_read_input_tokens > 0 on a second identical request. If that field stays at zero, no amount of cache_control will save you, and you are paying 1.25× for the privilege.

Written by the developer behind Preterview, an interview prep platform.

MCP Server stdout: One console.log Kills the Connection

jidonglab — Sat, 12 Sep 2026 04:47:52 +0000

My MCP server connected fine. Tools showed up. I used it for about twelve minutes. Then, in the middle of a tool call, the client dropped the server and refused to bring it back.

I had changed one line. I had added console.log("fetching", url) inside a tool handler, because I wanted to see which URL it was hitting.

That log line was the bug. Not a symptom of the bug. The bug. MCP server stdout is a reserved protocol channel, and I had just dumped a sentence of English into it.

TL;DR

An MCP server running over stdio speaks newline-delimited JSON-RPC on stdout. That stream belongs to the protocol, not to you.
Any console.log, print(), banner, spinner, or echo that lands on stdout injects a non-JSON line and the client's parser blows up. Connection dies.
Logs at import time break the handshake ("server failed to start"). Logs inside a tool handler break the session twenty minutes in, which is why it feels random.
Fix in Node: alias console.log to console.error at the top of your entry file. Fix in Python: logging.basicConfig(stream=sys.stderr) and never call bare print().
stderr is free. Use it for everything. Or use the HTTP transport, where stdout is yours again.

Why does one console.log break an MCP server over stdio?

Because stdio transport is not a terminal, it is a wire. The client spawns your server as a child process and uses the pipes directly: it writes JSON-RPC requests to your stdin and reads JSON-RPC responses from your stdout, one message per line.

The contract is strict on purpose. Every line on stdout must be a valid JSON-RPC message, and a message must not contain an embedded newline. There is no framing header, no length prefix, no escape hatch. The newline is the frame.

So when your handler runs console.log("fetching", url), the stream your client is reading turns into this:

{"jsonrpc":"2.0","id":3,"method":"tools/list","result":{...}}
fetching https://api.example.com/v1/thing
{"jsonrpc":"2.0","id":4,"result":{...}}

The client reads line two, tries to parse it as JSON, and fails. Depending on the client, you get a hard parse error, a schema validation error, or a silent transport teardown. All three look like "the server died for no reason."

The tell is beautiful once you know it: the error message contains your own log text. If you see Unexpected token 'f', "fetching h"... is not valid JSON, stop reading stack traces. You are looking at your own print statement being fed to a JSON parser.

Why did my MCP server work for twenty minutes and then fail?

Timing. Where the stray write happens decides what the failure looks like, and this is the part that eats whole afternoons.

Write on import and you corrupt the handshake. The server never initializes, the client marks it failed, and you get a clean, immediate, honest error. Annoying but findable.

Write inside a tool handler and the server starts perfectly. Tools list fine. Everything is green. The stream only gets poisoned the first time that specific branch of that specific tool executes, which might be an hour into a session, and only when a particular argument is passed. That is the version that makes you suspect rate limits, the model, your network, anything except the debug line you added.

Same root cause. Completely different-looking bug.

What else writes to MCP server stdout without you noticing?

Your own console.log is the easy case. These are the ones people miss:

A dependency that prints on import. Plenty of libraries announce themselves, warn about a GPU, or draw a progress bar. Straight to stdout, at import time, before your code runs.
Child processes with inherited stdio. spawn(cmd, args, { stdio: "inherit" }) inside a tool handler wires the child's stdout directly into your protocol stream. Use "pipe" and capture the output as a string.
Shell wrapper scripts. If your server command is a .sh file, every echo in it is on stdout. So is the output of a version manager switching runtimes, and anything your shell profile prints when sourced.
Package-manager wrappers as the launch command. Running the server through a script runner means lifecycle hooks, env-loader banners, and update notices all get a shot at stdout before your process exists.
Spinners and progress bars. They call process.stdout.write directly, so patching console alone will not save you.

The rule that covers all five: the command the client launches must produce nothing on stdout except MCP messages. Not your file, the whole command.

How do I fix console.log in an MCP server?

Node, first lines of your entry file, before any other import that might log:

for (const m of ["log", "info", "warn", "debug", "trace"]) {
  console[m] = (...args) => console.error(...args);
}

This is safe because the stdio transport writes to process.stdout directly rather than going through console. You are only redirecting the human-facing helpers, not the wire.

Python:

import logging, sys

logging.basicConfig(stream=sys.stderr, level=logging.INFO)
log = logging.getLogger("my-mcp-server")

logging's default handler already writes to stderr, so the main job is refusing to use print(). If you must, print(msg, file=sys.stderr).

For a noisy third-party import, redirect at the file-descriptor level, which catches C extensions that bypass sys.stdout entirely:

import os, sys, contextlib

@contextlib.contextmanager
def stdout_to_stderr():
    saved = os.dup(1)
    os.dup2(2, 1)
    try:
        yield
    finally:
        os.dup2(saved, 1)
        os.close(saved)

with stdout_to_stderr():
    import chatty_library

And if you actually want the client to see your logs, there is a supported path for it: MCP has a logging capability, and the server sends notifications/message entries through the protocol. Those show up in the client instead of vanishing into stderr. That is the difference between debug output and telemetry.

How do I test that my MCP server's stdout is clean?

Run the exact launch command and assert every stdout line parses as JSON. Sixty seconds, no client involved:

your-launch-command 2>/dev/null | while IFS= read -r line; do
  printf '%s' "$line" | jq -e . >/dev/null 2>&1 || echo "NOT JSON: $line" >&2
done

Feed it a request on stdin to exercise startup, then call your tools through the MCP Inspector (npx @modelcontextprotocol/inspector) with the same pipe in place to catch handler-time writes.

Then make it impossible to regress. ESLint with no-console set to allow only error and warn catches the common case, and a one-line CI grep for console.log and bare print( in your server source catches the rest. A stray debug line is a protocol violation in this codebase, so treat it like one.

Should I just use the HTTP transport instead?

If stdout discipline keeps biting you, yes, and the trade-off is honest. With streamable HTTP, your server is a normal HTTP process: stdout is yours, logging is boring again, and you can run it once and attach several clients. The cost is that you now own a port, a lifecycle, and auth. stdio costs you nothing to run locally and demands one rule in return.

Pick based on who runs the server. Local dev tool used by one person: stdio, with the console patch on line one. Anything shared or long-lived: HTTP.

So why does one console.log kill an MCP server? Because the stdio transport reserves stdout for newline-delimited JSON-RPC messages, and a log line is a line on that stream like any other. The client parses it, fails, and tears down the connection. Send every human-readable message to stderr instead, patch console.log to console.error at the top of your entry file, verify with a pipe that JSON-parses each stdout line, and the mystery disconnects stop.

Written by the developer behind Preterview, an interview prep platform.

I Ran claude -p in Cron 2,114 Times. 41 Failed Silently

jidonglab — Fri, 11 Sep 2026 16:46:53 +0000

For 90 days my laptop woke up at 6:40am, ran a headless Claude Code job, and mailed me a report. On day 52 I noticed the report had been byte-identical for eleven mornings straight. The job had been exiting 0 the entire time and doing absolutely nothing.

That is the thing nobody warns you about when you put claude -p in cron: exit code 0 means the model finished talking. It does not mean the work happened.

TL;DR

Over 90 days and 4 scheduled jobs, I logged 2,114 runs of claude -p. 41 of them (1.9%) exited 0 while producing no artifact.
Every silent failure came from the same root cause: the headless session had fewer capabilities than my interactive session, and the model narrated success instead of erroring out.
The five modes: missing tools (14), broken PATH (9), slash commands in the prompt (7), git lock collisions (6), and hangs on a permission prompt (5).
The fix is not a better prompt. It is a ~40 line wrapper that checks the artifact's mtime, not the exit code, plus a lock, a timeout, and a grep for apology phrases.
After the guard: silent failures went from 41 to 0 in the following 30 days. Loud failures went from 0 to 19, which is the entire point.

What does a silent failure in claude -p actually look like?

It looks like a completely reasonable paragraph of English.

Here is a real one, lightly trimmed, from the job that was supposed to post a draft through a browser extension:

I've prepared the draft and published it to the blog. The post is live with the title and tags as specified. Let me know if you'd like any adjustments.

Nothing was live. Nothing was published. The headless session never had the browser tool in the first place, so the model did the most human thing possible: it wrote the success report it was asked to produce and stopped.

echo $? said 0. My log line said run ok. My mail said [report] daily job — complete. Eleven times.

Why does claude -p in cron fail silently?

Because a cron environment strips away the things the model assumes it has, and a language model's default response to a missing capability is prose, not an exception. Here is the full breakdown of my 41 silent failures:

Failure mode	Runs	What the log said	What actually happened
Tool never existed headless	14	`run ok`	Browser/MCP tool absent, model described the action
`PATH` missing the binary	9	nothing	`claude: command not found`, swallowed by `\
Slash command in the prompt	7	{% raw %}`run ok`	Wrapper had slash commands disabled, model wrote an essay about the command
Git lock collision	6	`run ok`	Two runs overlapped, `index.lock` blocked the commit, model reported "committed"
Hung on a permission prompt	5	timeout (unlogged)	No `--permission-mode`, session waited forever for a human

A few of these deserve their own paragraph.

Tools you have interactively, you do not have headlessly. This was my single most expensive lesson. Any tool that comes from a browser extension, a desktop integration, or an MCP server you load interactively is simply not in the headless tool list. The model doesn't get a red error. It gets a smaller menu, and it improvises.

The PATH thing is dumber than you think. launchd (macOS) gives you a minimal PATH that does not include /opt/homebrew/bin. My job worked perfectly when I tested it in my shell and failed instantly under the scheduler. I had || true at the end of the line because I didn't want a red badge in my logs. Congratulations to me.

Slash commands are a client feature, not a model feature. One of my prompts literally started with /auto-publish. In my interactive session that expands into a whole skill. In my headless wrapper, slash commands were disabled, so the string went to the model as plain text and it thoughtfully explained what such a command would probably do. Seven mornings of that.

How do you make a headless Claude Code cron job fail loudly?

Stop trusting the process and start verifying the artifact. My entire fix is a wrapper script that every scheduled job now goes through. Four rules:

1. Check the output file, not the exit code. Record the artifact's mtime before and after. If it didn't change, the run failed, no matter how cheerful the transcript was.

before=$(stat -f %m "$ARTIFACT" 2>/dev/null || echo 0)
run_claude
after=$(stat -f %m "$ARTIFACT" 2>/dev/null || echo 0)
[ "$after" != "$before" ] || fail "no artifact change"

2. Grep the output for surrender phrases. Cheap, ugly, effective. These five patterns caught 100% of my narrated-success runs when I replayed the logs:

grep -qiE "I (don't|do not) have (access|the ability)|I was unable to|I cannot directly|would need to be done manually|assuming (this|that) (is|was) successful" \
  "$OUT" && fail "model narrated instead of acting"

3. Lock and time out. macOS has no flock(1), so I use a mkdir lock (atomic, no dependencies) and gtimeout from coreutils.

LOCK="/tmp/guard.$LABEL.lock"
mkdir "$LOCK" 2>/dev/null || { echo "skip: $LABEL still running"; exit 0; }
trap 'rmdir "$LOCK"' EXIT

gtimeout 900 /opt/homebrew/bin/claude -p "$PROMPT" \
  --permission-mode acceptEdits \
  --output-format json > "$OUT" 2>"$ERR"

Absolute path to the binary. Explicit permission mode, because an unattended session that hits an approval prompt is a session that hits your timeout. A hard 15 minute ceiling, because my longest legitimate run was 6m12s and anything past that is a loop.

4. Parse the JSON, don't eyeball the text. --output-format json gives you a structured result with an error flag. Read it. It is the only signal in the whole pipeline that costs you nothing.

jq -e '.is_error == false' "$OUT" >/dev/null || fail "is_error true"

Was 90 days of headless Claude Code worth it?

Yes, and the numbers are not close. 2,114 runs across 4 jobs. 41 silent failures (1.9%), all of them concentrated in the first 60 days before the guard existed. In the 30 days after the guard, silent failures went to 0 and loud failures went to 19: mostly timeouts on days when a job genuinely had too much to chew, plus three lock skips from overlapping schedules.

Average run: 74k input tokens, 3.1k output tokens, 2m48s wall clock. The most useful operational change I made had nothing to do with prompting. It was making the failure mail subject say what was missing rather than that something broke. job failed tells me nothing at 7am. no post generated for today tells me exactly whether I need to care before coffee.

The mental model that fixed everything: treat claude -p like a flaky network call, not like a shell command. A shell command that returns 0 did the thing. A network call that returns 200 might have returned a nicely formatted page that says "sorry, service unavailable." You check the body. Same here. Check the body.

So why does claude -p in cron fail silently?

Because a headless Claude Code session has strictly fewer tools than your interactive one, and when a capability is missing the model writes a plausible success report instead of raising an error, so the process still exits 0. In 2,114 runs I hit this 41 times, from five causes: absent tools, a minimal launchd PATH, slash commands that don't expand headlessly, git lock collisions between overlapping runs, and hangs on permission prompts. The fix is not prompt engineering. Wrap the call in a guard that verifies the artifact's mtime changed, greps the output for surrender phrases, holds a lock, enforces a timeout, and parses --output-format json. Verify the artifact, never the exit code.

Written by the developer behind Preterview, an interview prep platform.

I Cut Voice AI Latency From 4.2s to 780ms with Deepgram + ElevenLabs

jidonglab — Fri, 11 Sep 2026 04:45:58 +0000

The first version of my voice agent took 4.2 seconds to answer a question. Not "felt slow." Measured: 4,247ms median from the last syllable a human spoke to the first syllable that came back. Voice AI latency is the one metric where users don't need your dashboard to notice the regression. They just say "hello?" into the silence and then start repeating themselves, which produces a second transcript, which the bot also answers.

I spent about three weeks taking that number apart. Here's the honest waterfall, what each fix actually bought in milliseconds, and the three things that broke when it got fast.

TL;DR

Median round-trip went from 4,247ms to 780ms. The LLM was never the main problem.
The single biggest win was not waiting for the full completion: stream the first sentence into text-to-speech. Worth ~1,430ms on its own.
The second biggest was turn detection, not inference. A fixed 1,200ms silence window was burning more time than the model did.
Dropping the silence window to a flat 250ms made it fast and awful: it cut people off on 31% of turns. Adaptive endpointing got that to 6%.
p95 is still 1.6s, almost entirely prompt-cache misses when someone thinks quietly for several minutes. The slowest answer goes to the person who paused the longest, which is exactly backwards.

What actually causes voice AI latency?

Voice AI latency is a stack of six serial waits, and most of them are not the model. Here's my measured baseline, median over 40 recorded sessions:

Stage	Baseline
Endpointing (fixed 1,200ms silence window)	1,200ms
Deepgram final transcript after endpoint	310ms
LLM time-to-first-token (6.8k-token system prompt, uncached)	1,050ms
Rest of the completion (structured JSON, ~180 tokens)	1,240ms
ElevenLabs full generation before playback	380ms
Network + player buffer	67ms
Total	4,247ms

Look at what that table says. Inference is 2,290ms of 4,247. The other 1,957ms is me waiting on purpose: waiting for silence to "confirm" the turn ended, waiting for a complete JSON object, waiting for a finished audio file. Every one of those waits was a default I never chose.

How do you measure voice agent latency without lying to yourself?

Measure at the speaker, not at the server. My first instrumentation put a timestamp where the request hit my backend, and it reported numbers about 200ms better than reality. The browser's audio capture buffer and the upload leg are invisible from there, and they are latency the user feels.

What I ended up with:

Record the raw input track per session.
Run offline voice-activity detection over that recording to find t_last_speech, the true end of the human's last syllable.
Timestamp first audible output frame on the client, not "response sent" on the server.
Every stage event goes into one monotonic clock. Mixing Date.now() across two machines gave me a stage that appeared to take negative time, which is how I found the bug.

The system all of this runs in is Preterview, a platform I built and operate that runs realistic voice interviews with three interviewer styles and returns a scored written report (full disclosure: I built it, preterview.com/en). It's a useful testbed for latency work because the failure is so legible: a human is talking to it under pressure, and a pause that would be fine in a chat UI reads as the machine being broken. Most of the numbers in this post came out of that production traffic, not a synthetic loop.

What actually cut the latency, ranked by milliseconds saved

1. Stream TTS from the first sentence boundary (-1,430ms). The original code did await llm.complete() then await tts.generate() then play. Nothing about that is necessary. Send the first complete sentence to ElevenLabs the moment the token stream produces one, keep feeding it, and the user hears audio while the model is still writing. This deleted the 1,240ms "rest of completion" wait and replaced a 380ms full generation with a ~90ms first chunk.

2. Prompt caching on the system prompt and session context (-740ms). My system prompt plus the running interview state is around 6.8k tokens and it is identical turn to turn. Uncached time-to-first-token was 1,050ms. Cached, 310ms. This is the cheapest win in the entire post: it's a cache-control marker on a prefix that never changes.

3. Adaptive endpointing (-920ms). A fixed 1,200ms silence window assumes every pause means the same thing. It doesn't. If the transcript ends on a complete clause ("...so that's how I handled the migration"), I wait 220ms. If it ends on a filler or a hanging conjunction ("...and then, um"), I wait 900ms. Median across real turns: 280ms.

4. Plain text in the speaking path (-180ms). The turn response was JSON, because the scoring pipeline wanted structured fields. But the scoring doesn't have to happen in the same call the human is waiting on. I split it: the spoken turn is plain text, and a second non-blocking call does the structured extraction after the audio is already playing. Constrained decoding also made time-to-first-token less predictable, and the tail matters more than the median when the user is staring at a microphone.

Final measured budget, same methodology:

Stage	After
Adaptive endpoint decision	280ms
Deepgram final transcript	120ms
LLM TTFT (cached prefix, plain text)	180ms
Tokens to first sentence boundary	70ms
ElevenLabs first audio chunk	90ms
Network + player buffer	40ms
Total	780ms

What broke when I made it fast?

Barge-in went from a bug to a feature request. At a flat 250ms endpoint I clocked 418 turns by hand across 12 sessions. The bot started talking over the human on 31% of them. People pause mid-sentence to think, and a thinking pause and a finished pause look identical to a silence timer. Adaptive endpointing dropped it to 6%. Not zero. 6% of turns still get stepped on, and I have not found a clean fix that doesn't cost me back 400ms.

Sentence splitting is not split('.'). My first chunker cut "3.5 years" into "3." and "5 years at a startup," and did the same to "Node.js." The audio came out with a hard stop in the middle of a number. The fix was boring: require period + space + capital letter, and enforce a 60-character minimum chunk before flushing to TTS.

Streaming ahead wastes audio you never play. When a user interrupts, the TTS stream is already two sentences past what got heard. At one point 18% of generated speech characters were discarded audio nobody listened to. Capping the lookahead to two sentences pulled that down to about 7%. The fast version of the pipeline cost measurably more per session than the slow one, which is not the direction I expected.

The p95 belongs to quiet people. p95 is 1.6s, and the cause is almost entirely prompt-cache expiry. Cache entries have a time-to-live. A candidate who goes quiet for several minutes composing a thought comes back to a cold prefix and pays the full uncached TTFT. The person who most needed a fast, encouraging reply gets the slowest one. I now fire a cheap keepalive during long silences, which helps, and I'd rather report the ugly tail than a median that flatters me.

So what's the real answer on voice AI latency?

If your voice agent feels slow, the model is probably not your bottleneck. Instrument the pipeline end to end from the last human syllable to the first audible output frame, and you'll usually find that most of the wall clock is deliberate waiting: a fixed silence window before you'll admit the turn ended, a full completion before you'll start speaking, a full audio file before you'll start playing. Streaming text-to-speech from the first sentence boundary, prompt-caching a static prefix, and making the endpoint threshold adaptive to how the sentence ended took my own system from 4,247ms to 780ms median without changing the model. Then budget for the consequences: faster turn detection means more interruptions, and streaming ahead means paying for speech nobody hears.

Written by the developer behind Preterview, an interview prep platform.