Skip to content

Record every MCP tool call's duration into the read-latency histograms (#4442) - #4453

Merged
erikdarlingdata merged 8 commits into
devfrom
feat/4442-mcp-tool-latency
Sep 26, 2026
Merged

erikdarlingdata merged 8 commits into
devfrom
feat/4442-mcp-tool-latency

Conversation

@erikdarlingdata

Copy link
Copy Markdown
Owner

Refs #4442 (scope 2).

Why

The web /api/read/* dispatch loop and the composed-panel runner already record every read's
duration and outcome into ReadLatencyAccumulator. MCP tool calls (the third way a read reaches
Darling) recorded nothing, so a read tool that answers slowly, or times out, from an MCP client
was invisible to that histogram.

What changes

  • A new call-tool filter, McpToolLatencyFilter, registered in DarlingMcpHostService.ConfigureMcpServices
    alongside the two existing filters (McpUnknownArgumentGuard, GcfCallToolFilter). It times every
    tools/call (on both / and /core, since a call outside /core's narrowed tool set never reaches
    dispatch or any filter — there is nothing to time) and records one sample per call.
  • run_custom_view_panel is skipped by name: its body already records one Compose sample through the
    shared panel runner, so recording it here too would double-count every MCP custom-view call.
  • Outcome classification: a thrown exception classifies through the same rule the web loop's backstop
    uses; a normal return whose result is an explicit error, or carries the tool's own caught-error
    envelope, classifies the envelope's sentence the same way (so a 57014 statement-timeout sentence
    counts as a timeout, not a generic error); anything else counts as Ok.
  • Recording never throws into the call — a recording failure is swallowed and logged at Debug, the same
    posture the web and compose recorders already take.
  • ConfigureMcpServices and DarlingMcpHostService's constructor both gained an optional
    ReadLatencyAccumulator parameter, defaulted so every existing call site keeps building unchanged;
    production resolves the one process-wide singleton Program.cs already registers for the web host and
    worker flush.

Test plan

New class McpToolLatencyRecordingTests drives real tools/call requests through the actual
ConfigureMcpServices + ConfigurePipeline pipeline (the same pattern the existing MCP host gate tests
use), with the test's own accumulator:

  • a cheap test-only tool call records exactly one (Mcp, tool, Ok) sample;
  • a test-only tool that returns the 57014 statement-timeout error envelope records one
    (Mcp, tool, Timeout) sample;
  • a call on /core for a tool in its pinned set (list_servers) is recorded too;
  • run_custom_view_panel records no sample.
Darling.Tests.McpToolLatencyRecordingTests   Total: 4, Errors: 0, Failed: 0, Skipped: 0

Mutation test: commented out the filter's Record call on the success/error-return path (the exception
path's Record call was left in place, since removing either one alone proves the point) and reran the
new class:

RED (before restoring):

Darling.Tests.McpToolLatencyRecordingTests   Total: 4, Errors: 0, Failed: 3, Skipped: 0

(3 of 4 facts failed — the "run_custom_view_panel records nothing" fact still passed, correctly, since it
asserts absence.)

GREEN (after restoring):

Darling.Tests.McpToolLatencyRecordingTests   Total: 4, Errors: 0, Failed: 0, Skipped: 0

Also run, all green:

Darling.Tests.McpUnknownArgumentGuardTests   Total: 6,  Errors: 0, Failed: 0
Darling.Tests.GcfCallToolFilterTests         Total: 4,  Errors: 0, Failed: 0
Darling.Tests.DarlingMcpHostGateLiveTests    Total: 10, Errors: 0, Failed: 0
Darling.Tests.ReadLatencyWebRecordingTests   Total: 3,  Errors: 0, Failed: 0
Darling.Tests.ReadOutcomeClassifierTests     Total: 8,  Errors: 0, Failed: 0
Darling.Tests.DocCommentHygieneTests         Total: 77, Errors: 0, Failed: 0

Both Darling.Tests and Lite.Tests build 0 errors / 0 warnings with EnableWindowsTargeting=true.
The full suite was not run here (tests-only scope, targeted classes above cover the touched
surface); the product code itself was written and merged in an earlier PR and is unchanged here.

CHANGELOG entry

SECTION: None
ENTRY: None: MCP tool durations are recorded into the store's latency histograms; nothing surfaces them until the read tool lands (a later change).

…ome classifier, and record web and compose reads (#4442)
…in (#4442)

ReadLatencyPercentilesTests' field-shaped fixture asserted p99 strictly
above 5,000 ms, but with the fixture's exact 90/9/1 split the 990th
sample lands exactly on the slow tier's own upper bound -- fixed to
assert the honest answer, 5,000 ms.

Added ReadLatencyWebRecordingTests: drives a real /api/read/<name>
request through the actual web pipeline and asserts the read-latency
accumulator received the sample the dispatch loop is supposed to
record, plus a second case for the 57014 timeout shape.
…ency

# Conflicts:
#	Darling/Darling.Tests/ReadLatencyWebRecordingTests.cs
Adds McpToolLatencyRecordingTests: a real tools/call through
DarlingMcpHostService.ConfigureMcpServices + ConfigurePipeline, with the
test's own ReadLatencyAccumulator, proving a cheap tool call records one
Ok sample, a 57014-shaped error envelope records one Timeout sample, a
/core call is recorded too, and run_custom_view_panel records nothing.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant