Add structured timing logs to stream-query for slow-request diagnosis #51

2026-09-12T15:45:00-04:00

ryan commented

2026-09-12 15:45:00 -04:00

Every stream-query SSE request now emits a JSON summary line to the logger on completion, cancellation, or error.

What it logs

{"event":"stream_request","conv":"abc123","user":"ryan",
 "total_ms":45210,"thinking_ms":38100,"ttft_ms":38200,
 "tokens":112,"tools":[{"tool":"web_search","ms":820}],
 "model":"llama","cancelled":false}

Field	Meaning
`total_ms`	End-to-end wall time
`thinking_ms`	Time from first LLM call to first content token (reasoning phase)
`ttft_ms`	Time to first content token from request start
`tokens`	Approximate content token count
`tools`	Each tool invoked with wall-clock duration
`model`	LLM name from LangChain metadata — catches OpenAI fallback
`cancelled`	`true` when client disconnected mid-stream

Tool timers use the LangChain run_id to correctly pair start/end even when the same tool is called multiple times in one turn.

Querying

journalctl -u raggr-blue | grep stream_request

What the fields tell you about slow requests:

thinking_ms large → reasoning is the bottleneck
tool with large ms → external API is slow (Tavily, YNAB, etc.)
total_ms >> ttft_ms + tools → long generation (many output tokens)
model ≠ llama → OpenAI fallback fired

74/74 tests pass. No schema changes.

🤖 Generated with Claude Code

Every `stream-query` SSE request now emits a JSON summary line to the logger on completion, cancellation, or error. ## What it logs ```json {"event":"stream_request","conv":"abc123","user":"ryan", "total_ms":45210,"thinking_ms":38100,"ttft_ms":38200, "tokens":112,"tools":[{"tool":"web_search","ms":820}], "model":"llama","cancelled":false} ``` | Field | Meaning | |---|---| | `total_ms` | End-to-end wall time | | `thinking_ms` | Time from first LLM call to first content token (reasoning phase) | | `ttft_ms` | Time to first content token from request start | | `tokens` | Approximate content token count | | `tools` | Each tool invoked with wall-clock duration | | `model` | LLM name from LangChain metadata — catches OpenAI fallback | | `cancelled` | `true` when client disconnected mid-stream | Tool timers use the LangChain `run_id` to correctly pair start/end even when the same tool is called multiple times in one turn. ## Querying ```bash journalctl -u raggr-blue | grep stream_request ``` What the fields tell you about slow requests: - `thinking_ms` large → reasoning is the bottleneck - tool with large `ms` → external API is slow (Tavily, YNAB, etc.) - `total_ms` >> `ttft_ms` + tools → long generation (many output tokens) - `model` ≠ `llama` → OpenAI fallback fired 74/74 tests pass. No schema changes. 🤖 Generated with [Claude Code](https://claude.com/claude-code)

ryan added 1 commit 2026-09-12 15:48:21 -04:00

Add structured timing log to stream_query for slow-request diagnosis c071fd12e1

Every SSE request emits a JSON summary line on completion, cancellation,
or error:

  {"event":"stream_request","conv":"...","user":"ryan",
   "total_ms":45210,"thinking_ms":38100,"ttft_ms":38200,
   "tokens":112,"tools":[{"tool":"web_search","ms":820}],
   "model":"llama","cancelled":false}

Fields:
- total_ms    end-to-end wall time
- thinking_ms time from first LLM call to first content token (reasoning)
- ttft_ms     time to first content token from request start
- tokens      approximate content token count (stream deltas)
- tools       each tool invoked with wall-clock duration
- model       LLM name from LangChain metadata (catches fallback to OpenAI)
- cancelled   true when client disconnected mid-stream

Tool timers use the LangChain run_id to correctly pair start/end even
when the same tool is called multiple times in one turn.

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>

ryan force-pushed stream-observability from fc9e11ba69 to c071fd12e1

2026-09-12 15:48:21 -04:00

Compare

ryan merged commit 3875ed4e4f into main

2026-09-12 15:48:33 -04:00

Sign in to join this conversation.

1 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: ryan/simbarag#51