Skip to content

opencode-go: deepseek-v4.1-flash first-token latency scales with context (p90 ~25s at 657k, minutes at the tail), plus empty completions and missing finish_reason #57055

New issue
New issue
Closed
Closed
opencode-go: deepseek-v4.1-flash first-token latency scales with context (p90 ~25s at 657k, minutes at the tail), plus empty completions and missing finish_reason#57055

Description

@Ploppy3
Ploppy3
opened on Oct 19, 2026

Description

On the built-in opencode-go provider with deepseek-v4.1-flash, requests frequently sit with a spinner and no bytes arriving, sometimes for 2-3 minutes, then either answer late or get interrupted. I reproduced all of it with plain HTTP against the same endpoint (https://opencode.ai/inference/go/openai/v1/chat/completions), with no opencode client in the loop, so this is server side.

Summary of what I measured (same account, same machine, warm prompt cache >= 95% so it is not a cold-prefill problem):

input n median first token p90 max > 20 s
tiny prompt (raw HTTP) 120 1.6 s 2.8 s 28.5 s 0.8%
657k-token prompt (raw HTTP, back to back) 34 4.3 s 24.6 s 59.0 s 14.7%
app sessions, < 50k ctx (30 days) 4764 3.4 s 11.8 s 283 s 4.0%
app sessions, 150-300k ctx 3327 7.6 s 28.4 s 239 s 17.2%
app sessions, 300-500k ctx 741 10.6 s 37.4 s 272 s 28.5%
app sessions, 500k+ ctx 142 16.8 s 50.6 s 126 s 43.0% (> 60 s: 6.3%)

Once the first token arrives the stream is fine (144 tok/s, max gap between chunks 0.27 s), and prefill is fast (a 1M-token cold prompt returns in 27 s), so the delay is specifically before the first token and it scales with prompt length.

Same endpoint, also reproducible:

  • Streams that end with no finish_reason and no [DONE], which the client reports as provider.invalid-output: OpenAI Chat stream ended without finish_reason (1 in 25 at 657k in my run; 15 hits in one session of the app yesterday).
  • HTTP 200 with a valid [DONE] but "choices": [] and completion_tokens: 0 - the model never runs and the client gets an empty turn.
  • Repeated identical prefix sometimes comes back with cached_tokens: 0 (full re-read) - same family as [URGENT] Go: frank/DeepSeek-V4.1-Flash upstream repeatedly drops prompt cache — ~50% of billed usage is full-context re-reads #50258.
  • The same 780 KB prompt was reported as prompt_tokens: 160013 (4.9 chars/token) on some calls and 393392 (2.0 chars/token) on another - that looks like two different backends/tokenizers answering the same request, and the empty completions came from the 160k-reporting one.

Ruled out on my side (each verified by measurement):

  • network: caught a 21.8 s stall on an already-established pooled socket whose TCP state was rtt:9ms retrans:0/.. pmtu:1500 cwnd:10, i.e. no loss, no MTU issue, remote just did not answer;
  • DNS: connecting to the Cloudflare IP directly (no DNS at all) changes nothing;
  • Tailscale/AdGuard (DNS runs over the tailnet here): ran the same probe set with Tailscale fully stopped, no difference (median 1.83 s vs 1.76 s);
  • concurrency: 16 parallel requests max 7.6 s;
  • client/TUI: 120 sequential requests via raw HTTP are clean, and my session_message timings match the raw HTTP numbers.

Plugins

Only a local one (rtk.ts, rewrites shell commands). No MCP servers.

OpenCode version

2.0.32

Steps to reproduce

  1. Take an opencode-go key.
  2. Send a ~650k-token prompt ~40 times back to back (requests after the first are cache-warm):
curl -N https://opencode.ai/inference/go/openai/v1/chat/completions \
  -H "Authorization: Bearer $OPENCODE_API_KEY" \
  -H "Content-Type: application/json" \
  -H "x-opencode-session: ses_probe_$(uuidgen)" \
  -d '{"model":"deepseek-v4.1-flash","stream":true,"max_tokens":16,"messages":[{"role":"user","content":"<~650k tokens of text>\n\nReply with OK."}]}'
  1. Measure time to the first token. Expect median ~4 s, p90 ~25 s, max ~60 s, ~15% of requests over 20 s. Occasionally the stream ends without finish_reason/[DONE], and occasionally a 200 comes back with choices: [] and completion_tokens: 0.
  2. In the app, the same effect shows up as the spinner sitting for minutes with no thinking/output; the rate grows with context size (see table above).

Related: #57040, #50258, #40479, #36889, and the stream ended without finish_reason reports (#56870, #56861, #56858, #50146).

Screenshot

Not applicable (raw numbers above; can provide logs/probe dumps on request).

Operating System

Ubuntu 26.04.1 LTS

Terminal

herdr 0.9.5 (TERM_PROGRAM=herdr), TUI runs inside it

Activity

  1. opencode-agent commented on Oct 19, 2026

    @opencode-agent
    opencode-agentBot
    on Oct 19, 2026 – with OpenCode Agent
    Contributor

    Thanks for the detailed measurements and the raw-HTTP reproduction. I couldn't reproduce this here. Everything you describe happens on the OpenCode Go service itself, and testing it needs a real opencode-go key and very large prompts, which this sandbox doesn't have. That covers the first-token wait growing with context size, streams ending without finish_reason/[DONE], 200 responses with choices: [] and completion_tokens: 0, cached_tokens: 0 cache misses, and the different prompt_tokens counts for the same prompt. A maintainer with access to the Go gateway will need to look at it, and your probe dumps (with request timestamps and any x-opencode-session IDs) will probably help them match requests in the server logs.

    Related issues, roughly from most to least related:

  2. Ploppy3 commented on Oct 19, 2026

    @Ploppy3
    Ploppy3
    on Oct 19, 2026
    Author

    Adding the request-level details you asked for. Everything below came from my own account; the machine is UTC+2 and the times are UTC, so you can align them with the Go logs directly.

    Raw-HTTP probes: POST https://opencode.ai/inference/go/openai/v1/chat/completions, model: deepseek-v4.1-flash, stream: true. req id is the id field of the SSE chunks; session is the value I sent in the x-opencode-session header.

    time (UTC)             ttft prompt_tk    cached  session (x-opencode-session)           req id
2026-10-19 10:44:29  58.95s    657894    657792  ses_probe_649e475771754c0c9ba21f09dcc227bc 02179240666974065da4203214fbe81b3e8151fb2922fb1cef83b
2026-10-19 10:34:23  41.38s   1037873   1037824  ses_probe_96ee0b84f1e64a2ebbb5a8c218531573 0217924060635458cdbdac5f420e20fe0e1829640806a227c1785
2026-10-19 10:46:47  35.90s    657894    657792  ses_probe_27178711c1ee4d9ca3a80c100b4ba901 02179240680792734cb6184a92ddd9ae87302c189a666e5c9d3d8
2026-10-19 10:40:06  28.51s       297       256  ses_probe_c032e3bcff0b4cbda3dfccef4ed4ce2f 0217924064067607afbd658227445da69c5198dc2d1b70848c9d3
2026-10-19 10:42:39  27.17s    657894    657792  ses_probe_7cc9f47a0f334ace86ea403444d88e22 02179240655947345ed1e5750293ff098e8b34eca79d24a4986fd
2026-10-19 10:33:37  26.90s   1037873         0  ses_probe_96ee0b84f1e64a2ebbb5a8c218531573 021792406017716fd3ae808d5ba084b55a7f9e1600032cd3b9b17
2026-10-19 10:35:04  25.12s   1037873   1037824  ses_probe_4f8c5f14d7e8497284ed5b8bc50f6629 021792406104202a4a9e4d164f3c176730993b0b2e8dd9da38fdc
2026-10-19 10:46:03  24.55s    657894    657792  ses_probe_ae8b27c7b350493697b79949a939fdba 021792406763373aaaf13501739a5ff290af8d9343e27fcf529e9
n/a                  23.74s    657894         0  ses_probe_ef8740f9e20d4499b109536904486f52 gw-a697b26c5509-62bb4d
n/a                  19.00s    524794         0  ses_probe_a6079680ef8447c0b2a38c0da9d2aa21 gw-a70a2abc01d3-62bc5a
2026-10-19 10:39:16  15.31s       297       256  ses_probe_f915e4071d124fd9b677159c1b9be3ed 021792406356477fd2e0ebdb3eb064cbe39fbfe58bf726330fa88
2026-10-19 10:37:39  15.18s       297       256  ses_probe_737ff36af4a04df581a804f8333dbf44 02179240625909949d9e4e345fff0a9cbe1dfa11f8e7ca0eb4471

    Three specific ones worth pulling from the list:

    • 2026-10-19 10:44:29 UTC, 59.0s to first token, 657894 prompt tokens of which 657792 cached - warm cache, still 59s to first token.
    • 2026-10-19 10:33:37 UTC, 26.9s, 1037873 prompt tokens with cached: 0 - identical prefix served from cache one request earlier. Note this one (and the next) came back with a gw-... id instead of the numeric one: 021792406017716fd3ae808d5ba084b55a7f9e1600032cd3b9b17.
    • the empty completion: HTTP 200, data: [DONE], "choices": [], completion_tokens: 0, sent with x-opencode-session: ses_probe_a5027c93e46b4525bd1bfe6665a6804f (around 10:48 UTC, 657k-token prompt, no id captured in my parser for it).

    From the app itself (same account), for the two failure modes:

    session_id                     time (UTC)         what
ses_eaca9704dffePTfSggKnMMBulK 11:12:42-11:54:16  15x 200 OK streams ending with no finish_reason/[DONE]
ses_eaca9704dffePTfSggKnMMBulK 12:02:33           172s with zero bytes, no output, then manually interrupted
ses_eaca9704dffePTfSggKnMMBulK 12:13:12           145s to first token
ses_eac5824ebffeZk2teKxs841SVi 12:15:20           179s with zero bytes, then manually interrupted

    For those 15, the stored retry on the message is {"attempt": 2, "error": {"type": "provider.invalid-output", "message": "OpenAI Chat stream ended without finish_reason", "status": 200}} - so each truncation costs a second full request, and the retry is delivered as a synthetic "previous response was interrupted, continue" turn.

    I still have the raw probe dumps (per-chunk arrival timeline, response headers including x-opencode-log-id) - happy to attach them wherever a maintainer wants them.

  3. Ploppy3 commented on Oct 20, 2026

    @Ploppy3
    Ploppy3
    on Oct 20, 2026
    Author

    Adding controlled A/B results from the CLI to narrow this down. All runs use the same ~401k-token session/prefix, warm cache (401,280 cached tokens), opencode-go/deepseek-v4.1-flash, effort max, and a one-word output.

    Output-token cap is not the cause

    max_tokens new tokens cache read TTFT
    256,000 79 401,280 4.175s
    32,768 94 401,280 4.177s

    Same prefix and cache. The gateway is not queueing on output-token reservation.

    Explicit affinity headers are not the cause

    • Removing x-session-affinity and X-Session-Id: still hit 401,280 cached tokens, TTFT 4.43s.
    • Removing x-opencode-session too: HTTP 400 MissingSessionID — "Request is missing x-opencode-session and cannot be routed efficiently."

    So x-session-affinity / X-Session-Id are redundant for Go; x-opencode-session is the actual routing key and cannot be removed.

    Same context, huge spread

    In the same ~400k session, all with ~99.7% cache:

    4.1, 7.1, 8.7, 11.2, 15.0, 15.7, 20.0, 48.8, 152.5, 176.6, 231.2, 236.1 seconds.

    The 236s request had only 504 new tokens and 393,856 cached tokens. That rules out prefill, cache miss, decode speed, and max_tokens; it looks like endpoint/queue scheduling.

    Session-age drift

    Within-session median TTFT:

    • 585k session: 2.7s early → 4.4s late
    • 379k session: 5.0s → 6.9s
    • current session: 1.8s → 2.5s
    • 401k session: 2.1s → 11.4s (late window overlaps the 12:23 incident)

    New sessions are fast mainly because they start at low context; a 401k fork can still be 4.2s warm.

    Cross-check

    Direct DeepSeek at 250–450k: p50 4.8s, p95 17.6s, max 42s.

    Conclusion: this is not client request shape, max_tokens, or a missing affinity header. x-opencode-session routes to an endpoint/queue that occasionally takes minutes at long context. Can a maintainer check the gateway's endpoint selection/queue for that key, and expose x-opencode-endpoint-id again so slow requests can be correlated with a specific upstream?

  4. Ploppy3
    closed this as completedon Oct 21, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions