feat: add generation metrics to logs (think, rounds, tokens)

Log think flag, round count, prompt/output token counts per generation.
Change log category from 'usage' to 'generation' for clean MCP filtering.

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
This commit is contained in:
2026-04-02 14:14:41 -04:00
parent 3e42992f67
commit 25d448f896
3 changed files with 21 additions and 3 deletions
@@ -212,7 +212,11 @@ async def run_generation(
t_start = time.monotonic() t_start = time.monotonic()
timing: dict = { timing: dict = {
"think": think,
"tools": [], "tools": [],
"rounds": 0,
"prompt_tokens": None,
"output_tokens": None,
"ttft_ms": None, "ttft_ms": None,
"generation_ms": None, "generation_ms": None,
"total_ms": None, "total_ms": None,
@@ -228,6 +232,7 @@ async def run_generation(
research_completed = False research_completed = False
for _round in range(MAX_TOOL_ROUNDS + 1): for _round in range(MAX_TOOL_ROUNDS + 1):
timing["rounds"] = _round + 1
round_tool_calls: list[dict] = [] round_tool_calls: list[dict] = []
logger.info("Generation round %d started for conv %d (model=%s)", _round, conv_id, model) logger.info("Generation round %d started for conv %d (model=%s)", _round, conv_id, model)
@@ -261,6 +266,12 @@ async def run_generation(
logger.warning("Failed periodic flush for message %d", msg_id, exc_info=True) logger.warning("Failed periodic flush for message %d", msg_id, exc_info=True)
last_flush = now last_flush = now
elif chunk.type == "done":
if chunk.prompt_tokens is not None:
timing["prompt_tokens"] = (timing["prompt_tokens"] or 0) + chunk.prompt_tokens
if chunk.output_tokens is not None:
timing["output_tokens"] = (timing["output_tokens"] or 0) + chunk.output_tokens
elif chunk.type == "tool_calls" and chunk.tool_calls: elif chunk.type == "tool_calls" and chunk.tool_calls:
logger.info("Round %d: model returned %d tool call(s)", _round, len(chunk.tool_calls)) logger.info("Round %d: model returned %d tool call(s)", _round, len(chunk.tool_calls))
for tc in chunk.tool_calls: for tc in chunk.tool_calls:
+8 -1
View File
@@ -149,6 +149,9 @@ class ChatChunk:
type: Literal["content", "thinking", "tool_calls", "done"] type: Literal["content", "thinking", "tool_calls", "done"]
content: str = "" content: str = ""
tool_calls: list[dict] | None = None tool_calls: list[dict] | None = None
# Token counts from the Ollama done event (only set on type="done")
prompt_tokens: int | None = None
output_tokens: int | None = None
async def stream_chat_with_tools( async def stream_chat_with_tools(
@@ -221,7 +224,11 @@ async def stream_chat_with_tools(
yield ChatChunk(type="tool_calls", tool_calls=accumulated_tool_calls) yield ChatChunk(type="tool_calls", tool_calls=accumulated_tool_calls)
else: else:
logger.debug("Ollama done with no tool calls") logger.debug("Ollama done with no tool calls")
yield ChatChunk(type="done") yield ChatChunk(
type="done",
prompt_tokens=data.get("prompt_eval_count"),
output_tokens=data.get("eval_count"),
)
break break
+2 -2
View File
@@ -68,12 +68,12 @@ async def log_generation(
"""Persist per-generation timing breakdown to app_logs for benchmarking.""" """Persist per-generation timing breakdown to app_logs for benchmarking."""
async with async_session() as session: async with async_session() as session:
log = AppLog( log = AppLog(
category="usage", category="generation",
user_id=user_id, user_id=user_id,
action="generation", action="generation",
endpoint=f"/chat/conversations/{conv_id}", endpoint=f"/chat/conversations/{conv_id}",
duration_ms=timing.get("total_ms"), duration_ms=timing.get("total_ms"),
details=json.dumps({"model": model, **timing}), details=json.dumps({"model": model, "conv_id": conv_id, **timing}),
) )
session.add(log) session.add(log)
await session.commit() await session.commit()