Log every model call's time and tokens #175

2026-10-20T23:07:19Z

dev-agent commented

2026-10-20 23:07:19 +00:00

Part of #174. nisse-review's turns on infra/identity#8 grew from 1 to 5 minutes until LiteLLM's 300s limit stopped one. Nothing recorded how long each model call took or how many tokens it read and wrote, so the cause had to be guessed from gaps between tool calls.

What changes

BudgetedClient.complete (every model call, both agents, every role) emits llm.call:
- model, seconds;
- input_tokens, output_tokens, cached_tokens;
- answered_by when a fallback answered under another name.
A failed call emits llm.call with cause: failed, the error type and how long it ran, then re-raises.
last_usage gains cached: OpenAI's prompt_tokens_details.cached_tokens, Anthropic's cache_read_input_tokens. It shows whether the server reused the prompt between turns, which also matters for judging Strata / Qwen3.8-Flash-Next.

Tests

nisse-core/tests/test_llm.py: cached tokens parsed on both routes.
nisse-core/tests/test_context.py: an answered call logs time and tokens; a failed call logs its time and still raises. The "nothing is logged" test now checks only that no cut is logged.

🤖 Generated with Claude Code

https://claude.ai/code/session_01J5Utyfzw7gF7UhjRDEtjTk

Part of #174. nisse-review's turns on infra/identity#8 grew from 1 to 5 minutes until LiteLLM's 300s limit stopped one. Nothing recorded how long each model call took or how many tokens it read and wrote, so the cause had to be guessed from gaps between tool calls. **What changes** - `BudgetedClient.complete` (every model call, both agents, every role) emits `llm.call`: - `model`, `seconds`; - `input_tokens`, `output_tokens`, `cached_tokens`; - `answered_by` when a fallback answered under another name. - A failed call emits `llm.call` with `cause: failed`, the error type and how long it ran, then re-raises. - `last_usage` gains `cached`: OpenAI's `prompt_tokens_details.cached_tokens`, Anthropic's `cache_read_input_tokens`. It shows whether the server reused the prompt between turns, which also matters for judging Strata / Qwen3.8-Flash-Next. **Tests** - `nisse-core/tests/test_llm.py`: cached tokens parsed on both routes. - `nisse-core/tests/test_context.py`: an answered call logs time and tokens; a failed call logs its time and still raises. The "nothing is logged" test now checks only that no cut is logged. 🤖 Generated with [Claude Code](https://claude.com/claude-code) https://claude.ai/code/session_01J5Utyfzw7gF7UhjRDEtjTk

dev-agent added 1 commit 2026-10-20 23:07:19 +00:00

Log every model call's time and tokens

CI / checks (push) Skipped

CI / checks (pull_request) Successful in 2m57s

Details

CI / e2e (pull_request) Successful in 4m42s

Details

31c97ccfb5

Each call through BudgetedClient emits llm.call: seconds, input,
output and cached tokens, and the answering model when a fallback
answered; a failed call logs how long it ran before it failed.
Usage now carries the server's cached-prompt count on both routes.

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01J5Utyfzw7gF7UhjRDEtjTk

dongar approved these changes

2026-10-20 23:11:04 +00:00

dev-agent merged commit 949a89f6a4 into main

2026-10-20 23:19:30 +00:00

dev-agent deleted branch call-timing

2026-10-20 23:19:30 +00:00

Sign in to join this conversation.

2 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: dev/nisse#175