Skip to content

BUG: message.updated before message.part.updated loses active-generation timing precision #27

Description

@devinoldenburg

Summary

In tps-meter.tsx, the message.updated handler (lines 121-148) uses timers.get(info.id) to look up the GenerationTimer for a completed message. But it uses the non-creating variant instead of timerFor(info.id). If message.updated fires before any message.part.updated events — which occurs for instant/cached responses or rapid completions — no GenerationTimer exists, setTokens() silently no-ops, and the message falls back to the less precise end-to-end or first-token window. The active-generation timing that the plugin is specifically designed to use is lost.

Root Cause

File: plugins/tps-meter.tsx:141

const t = timers.get(info.id);
if (t && generated > 0) t.setTokens(generated);

Compare with the streaming path at line 111:

if (part.messageID) {
  timerFor(part.messageID).push(tokens, now); // timerFor CREATES if missing
  currentMsgId = part.messageID;
}

timerFor (line 72-78) lazily creates a GenerationTimer if one doesn't exist for the message. But the completion path uses timers.get() which returns undefined for missing keys. The if (t && ...) guard silently skips setTokens, and no timer is created.

The timing object passed to messageStats() via timingFor() (line 80-85) also returns undefined when no timer exists, so the message uses the fallback window:

  1. "active" window → skipped (no activeMs)
  2. "first-token" window → skipped (no firstTokenAt)
  3. "end-to-end" → used as fallback (includes prefill + all tool waits)

When This Happens

  • Cached responses: OpenCode serves an assistant message from cache — instant completion, no streaming events
  • Very short responses: Tiny assistant replies complete before the first delta batch arrives
  • Message replayed from history: On TUI restart, historical messages appear via message.updated without prior streaming
  • Race condition: Event delivery order is not guaranteed; message.updated can precede the first message.part.updated

Impact

  • Precision loss: The plugin's core value proposition — active-generation TPS that excludes tool calls — is silently lost for affected messages. They use end-to-end wall-clock time which includes prefill AND tool waits.
  • Inconsistent display: Some messages show precise active-generation TPS; others show naive end-to-end TPS. Users see fluctuating precision with no visual indication.
  • Session averages polluted: aggregate() pools decode-time windows. Mixing end-to-end windows with active-generation windows gives a session average that is meaningless (lower than true generation speed).

Proposed Fix

Use timerFor in the completion path, same as the streaming path:

const t = timerFor(info.id);
if (generated > 0) t.setTokens(generated);

Additionally, if no streaming events occurred, t.activeMs will be 0 and messageStats() will correctly fallback. But at minimum this ensures the timer exists and setTokens runs so the exact token count is stored for any downstream timing that may become available later.

Steps to Reproduce

  1. Open OpenCode TUI with the TPS meter active
  2. Trigger a cached/short assistant message that completes without streaming chunks
  3. Observe that the message's TPS is computed using end-to-end time (includes prefill), not active-generation time

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions