Skip to content

feat(observability): log tool_calls_per_assistant_response as structured metric #623

Description

@Aaronontheweb

Summary

Add a structured log field (tool_calls_per_response) on every assistant response that emits tool calls, so we can durably measure whether the model is batching tool calls in a single response or only emitting one per round-trip.

This is a one-line logger addition that answers a question we had no way to answer before: does the model actually exercise the parallel-tool-execution code path in production?

Why this came up

Netclaw's SessionToolExecutionPipeline.ExecuteToolsAsync runs tool calls via Task.WhenAll — i.e., all calls in a single assistant response execute concurrently on the thread pool. The code path is tested (Multiple_tool_calls_in_single_response_all_executed in ToolExecutionIntegrationTests.cs:152) and functionally correct.

But: grepping two full days of production daemon logs (521 real tool invocations across 21 Slack sessions on 2026-04-11 and 2026-04-12), we found ZERO pairs of tool calls fired within 100ms of each other. Qwen3.5 via llama.cpp never batched a single tool call in production across this sample. Every tool call was a separate round-trip.

This means the parallel dispatch code path is a latent capability — correct, but unused with the current model + inference engine combination. This has implications for:

  1. Anything we change to encourage batching (prompt engineering, different tool-call parser, different model) needs a measurement to confirm it actually worked.
  2. The planned vLLM + Qwen3.5-35B-A3B migration (testlab-setup#131) may unlock batching via the qwen3_coder tool parser, but we'd never know without measurement.
  3. Provider switches (Anthropic, OpenAI) are well-known to batch aggressively. A metric comparing providers is useful for triage.

What changes

In LlmSessionActor.cs where tool calls are invoked (around line 1478), add one log line:

TurnLog().Info(
    "turn_tool_call_batch count={Count} tools={Tools}",
    toolCalls.Count,
    string.Join(",", toolCalls.Select(tc => tc.Name)));

Or ideally, emit it as structured metric data via _sessionMetrics (whatever the existing metric sink is). Preferably both — a Serilog-style structured log line for ad-hoc grep queries AND a counter/histogram for long-running aggregation.

Success criteria

  • Structured log field on every tool-invocation event (not just the first)
  • Captures the count and the tool names
  • After deployment, a one-liner grep+awk on daemon logs gives an instant distribution of tool_calls_per_response for any time window
  • No new dependencies, no new dashboards, no new instrumentation infrastructure required for this issue (follow-up can add Grafana/Prometheus integration later if useful)

Out of scope

  • Actually encouraging the model to batch (that's a separate experiment — prompt engineering, model choice, tool-call parser choice)
  • Dashboards, alerts, or any observability infrastructure beyond the one log line
  • Historical backfill — this measures from the moment it ships forward

Related

Metadata

Metadata

Assignees

No one assigned

    Labels

    enhancementNew feature or requestobservabilitysessionsLLM session actor, turn lifecycle, pipelines

    Type

    No type

    Projects

    No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions