Skip to content

perf(mcp): reuse the request's plan lookup in tools/call instead of repeating it untraced - #725

Merged
dash0-dev[bot] merged 3 commits into
mainfrom
weekly-improve/2026-10-26-reuse-mcp-plan-lookup
Oct 26, 2026
Merged

dash0-dev[bot] merged 3 commits into
mainfrom
weekly-improve/2026-10-26-reuse-mcp-plan-lookup

Conversation

@dash0-dev

@dash0-dev dash0-dev Bot commented Oct 26, 2026 •

Copy link
Copy Markdown
Contributor

Summary

Every hosted MCP tools/call waits for a second, serial, untraced user_plans query before the tool's first DB query. The transport preamble in mcp/index.ts has already looked up the same row for the same user. This affects every authenticated agent calling memory.* tools. With this change getUserPlanName memoises per request span and tools/call passes the request span, so the preamble's lookup is reused. Where the preamble skips the lookup (BYOD), the call now runs traced instead of invisibly.

Evidence (production telemetry)

  • Signal: gap between a lorekit.memory.* MCP handler span's start and its first DB CLIENT child (service.name=api, deployment.environment.name=production). Current window is 2026-10-19T06:01:30Z..2026-10-26T06:01:30Z, baseline is 2026-09-28T06:01:30Z..2026-10-19T06:01:30Z:
    • memory.write: 177 ms (n=1,382) vs 106 ms (n=2,052)
    • memory.list: 280 ms (n=1,303) vs 133 ms (n=1,931)
    • memory.read: 271 ms (n=633) vs 165 ms (n=981)
    • memory.search: 334 ms (n=466) vs 159 ms (n=714)
    • Gaps over 1 s this week: write 29, list 32, read 15, search 20. The REST handlers (lorekit.memories.get/*) show a 3-4 ms gap because they don't repeat the lookup.
  • Signal: the traced copy of the same lookup (SELECT user_plans, issued by index.ts) averaged 144 ms (n=16,615) this week, with 615 calls over 500 ms. That matches memory.write's gap, since write makes no other call before its first query. list/read/search also make the untraced lorekit_member_org_ids RPC first (avg 225 ms where traced), which this PR does not change.
  • Signal: tools/call root SERVER span duration p50 0.59 s vs 0.50 s, p95 3.43 s vs 1.53 s (n=3,927 vs 5,809).
  • Query: D0QL (Dash0 SQL), with timeRange set to each window:
SELECT h.name AS handler, count() AS n, round(avg(toFloat64(c.first_ts) - toFloat64(h.timestamp)) * 1000) AS avg_gap_ms, countIf(toFloat64(c.first_ts) - toFloat64(h.timestamp) > 1) AS gaps_over_1s FROM spans AS h INNER JOIN (SELECT trace_id, parent_id, min(timestamp) AS first_ts FROM spans WHERE resource_attributes['service.name'] = 'api' AND resource_attributes['deployment.environment.name'] = 'production' AND kind = 'CLIENT' GROUP BY trace_id, parent_id) AS c ON c.trace_id = h.trace_id AND c.parent_id = h.span_id WHERE h.resource_attributes['service.name'] = 'api' AND h.resource_attributes['deployment.environment.name'] = 'production' AND h.name IN ('lorekit.memory.write', 'lorekit.memory.list', 'lorekit.memory.read', 'lorekit.memory.search') GROUP BY handler ORDER BY n DESC
  • Examples: trace 01a15d42968b7d8c8d55b8b120765cd5 (memory.write, 23 s before CALL memory_write). The multi-second outliers line up with a database contention episode on 2026-10-20..10-22. This change removes the steady ~144 ms per call. It does not fix those outliers.

Root cause

  • mcp/index.ts L193-L213 resolves the plan for every authenticated hosted request, traced and concurrent with the rate-limit check. L244 then calls handleMcp(req, auth, span, adapter) without passing the plan on.
  • mcp/mcp-handler.ts L330-L363 opens the lorekit.<tool> span and then runs await getUserPlanName(db, analyticsUserId) again for the same user (in hosted mode analyticsUserId === auth.userId). It passes no span, so the round trip shows up as unexplained time at the start of the handler span. The value is used only for the lorekit.plan attribute and the usage event, never for enforcement.
  • _shared/telemetry/usage.ts L165-L185 has no memo. A memo keyed on the db client would not help either: getDb builds a new client on every call. The request's root span is the one object both call sites share.

Change

  • _shared/telemetry/usage.ts: when getUserPlanName is given a parentSpan, it memoises the in-flight promise in a module-level WeakMap<Span, Map<userId, Promise<string | null>>>. This follows the per-request WeakMap memo memberOrgIds uses in mcp/tools.ts. Concurrent callers share one query. A null (failed, fail-open) result is evicted, so a later caller retries as before. Without a span (the REST router) nothing is memoised. Values: the plan name, 'free' for a missing row, and null on any error — including a PostgREST error returned in the response, which previously fell through to 'free' (review fix 9700c48). That last case changes one thing outside MCP: on a DB error the REST router's usage event and span now carry no plan instead of 'free', matching the function's documented fail-open contract; nothing enforces on plan name.
  • mcp/mcp-handler.ts: tools/call passes the request span as the third argument. In hosted mode this hits the memo index.ts populated, so there is no second query. In BYOD mode index.ts skips the lookup and db is the storage project, so it misses, queries the same db as before, and is now traced (as a child of the request span).
  • 34 changed non-test lines. Not touched: mcp/index.ts, mcp/auth.ts, _shared/api/auth.ts (they are in another open PR), and otel.ts. _shared/telemetry/usage.ts is not a mirror pair (packages/cli/src/shared/mirror-pairs.mjs), so nothing in mcp-core needed changing.
  • No user-facing docs change: this is an internal latency and telemetry fix with no observable change to what users can do, see or configure.

Test

  • packages/mcp-core/src/mcp-guards/mcp-handler-plan-reuse.spec.ts (vitest, run by CI): a source-scan guard in the style of mcp-preamble-usage.spec.ts. On comment-stripped source it asserts that mcp-handler.ts calls getUserPlanName(db, analyticsUserId, span) and has no two-argument call, and that usage.ts memoises in a WeakMap<Span, …>. It also has an anti-vacuity check that both still exist.
    • Before the fix: npx vitest run --root packages/mcp-core src/mcp-guards/mcp-handler-plan-reuse.spec.ts gave Tests 2 failed | 1 passed (3). The two property assertions failed and the anti-vacuity check passed.
    • After the fix: Tests 3 passed (3). The existing mcp-preamble-usage.spec.ts stays green (5/5).
  • supabase/functions/_shared/telemetry/usage.plan-memo.test.ts (Deno, behavioural, not run by CI: the edge tree has no Deno test job). It uses a fake db that counts from('user_plans') calls and checks eight cases: same span + same user across two db clients gives 1 query; concurrent calls give 1; a different span gives 2; a different user gives 2; no span gives 2; a thrown failure is not memoised (null, then a retry returns 'pro'); a PostgREST error returned in the response is null and not memoised (the next call returns 'pro'); a missing row returns 'free' and is memoised.
    • Before the fix: NODE_USE_ENV_PROXY=1 deno test --no-check --node-modules-dir=none supabase/functions/_shared/telemetry/usage.plan-memo.test.ts gave FAILED | 4 passed | 3 failed, with Actual 2 / Expected 1 on the three memo cases.
    • After the fix: ok | 8 passed | 0 failed (the returned-error case was added with the review fix and failed first with ["free","free"]).
  • Also run locally:
    • Full mcp-core suite: 90 files, 2043 passed, 1 skipped.
    • Existing edge Deno tests plus the new one: 65 passed.
    • node scripts/ci/deno-check-functions.mjs: every function at 0 errors, no baseline exceeded.
    • nx targets mcp-core:typecheck, mcp-core:lint, supabase:lint, supabase:test: all pass, 0 lint errors.
    • The full nx affected run (which also includes web, web-e2e and evals through the project graph) ran out of memory in the sandbox, so only CI can confirm those projects.

How we will know it worked

  • Metric: the handler-to-first-DB-child gap query above, in ms. Lower is better.
  • Expected change: memory.write avg gap should drop from 177 ms toward ~30 ms (the handler's own code). memory.list, memory.read and memory.search should each drop by ~140 ms.
  • Re-measure: the weekly loop re-measures about 5 days after the production deploy (around 2026-11-02 if merged today).
  • The SELECT user_plans span count per tools/call will not change, because a memo hit emits no span. That is why the gap query, not the span count, is the metric.

Opened by the weekly Agent0 telemetry-driven improvement automation. It is merged automatically when the review loop converges with an approving verdict and CI is green (and, for a web UI change, when the ui-verify test passes on this PR's Vercel preview), unless it carries the needs-human-merge label.

…epeating it untraced

getUserPlanName now memoises per (request span, user) when given a span, and
tools/call passes the request span, so it reuses the user_plans lookup that
mcp/index.ts already made for the same request instead of a second serial,
untraced round trip. Where index.ts skips the lookup (BYOD) the call now runs
traced. Failed (null) lookups are not memoised; the unspanned REST path is
unchanged.

Co-authored-by: dash0-dev[bot] <257284812+dash0-dev[bot]@users.noreply.github.com>
@dash0-dev dash0-dev Bot added the agent0-weekly-improvement Opened by the weekly Agent0 telemetry-driven improvement automation label Oct 26, 2026
@dash0-dev

dash0-dev Bot commented Oct 26, 2026 •

Copy link
Copy Markdown
Contributor Author

✅ No issues found

No new commits since the last review of 8578d8e, so this run re-checked the gates only. The description now covers the 9700c48 fix (REST router gets null on a DB error, eight Deno cases), which clears the earlier description warning.

Checked: 0 of 3 dependent files traced

Progress: open review threads 1 → 0 → 0 across the last 3 reviews

What this change reaches — 3 changed exports · 3 dependent files · 0 checked · 3 not checked
flowchart LR
  subgraph pr["Changed in this PR"]
    s1["getUserPlanName<br/>signature changed"]:::changed
    s2["handleMcp<br/>body changed"]:::changed
    s3["recordUsageEvent<br/>body changed"]:::changed
  end
  s1c1["supabase/functions/_shared/api/router.ts<br/>? not checked"]:::unknown
  s1c2["supabase/functions/_shared/telemetry/usage.plan-memo.test.ts<br/>? not checked"]:::unknown
  s2c1["supabase/functions/mcp/index.ts<br/>? not checked"]:::unknown
  s3c1["supabase/functions/_shared/api/router.ts<br/>? not checked"]:::unknown
  s1 -.-> s1c1
  s1 -.-> s1c2
  s2 -.-> s2c1
  s3 -.-> s3c1
  classDef changed fill:#eef2ff,stroke:#6366f1,color:#1e1b4b
  classDef ok fill:#e7f6ec,stroke:#16a34a,color:#14532d
  classDef partial fill:#fef9c3,stroke:#ca8a04,color:#713f12
  classDef unknown fill:#f3f4f6,stroke:#9ca3af,stroke-dasharray:4 3,color:#374151
  classDef bad fill:#fde8e8,stroke:#dc2626,color:#7f1d1d
  classDef warn fill:#fff4e5,stroke:#d97706,color:#78350f
  classDef imports fill:#f8fafc,stroke:#64748b,stroke-dasharray:4 3,color:#1e293b
Loading
  • getUserPlanName (supabase/functions/_shared/telemetry/usage.ts) — signature change · 2 consumer files · 2 not traced
  • handleMcp (supabase/functions/mcp/mcp-handler.ts) — body change · 1 consumer file · 1 not traced
  • recordUsageEvent (supabase/functions/_shared/telemetry/usage.ts) — body change · 1 consumer file · 1 not traced
Review details
Gate Status Details
Description vs. code ✅ Body now matches the diff, including 9700c48: REST router gets null on a DB error, and the Deno test has 8 cases.
Prior review feedback ✅ Earlier review comments are resolved.
Documentation ✅ JSDoc, inline comments and test headers explain the per-span memo, null eviction and the BYOD traced miss.
Self-review signals ✅ No debug logs, leftover TODOs, or unreviewed stubs.
Code review ✅ The multi-lens review found no blocking issues.

Found

Quality — produced 0 → posted inline 0 · cleared 0 · carried forward 0 · deferred 0 · below-bar 0

Run

incremental · 0 lines in delta · depth checkout
Integrations — none
CI — still pending: Integration smoke (local Supabase) · 6 passed
Memories — skipped (zero-delta fast path)

Nothing to report — standards (skipped), optimality (skipped), measurability (skipped), severity, 0 files skipped.

pr-reviewer · commit 8578d8e · no code changes since 8578d8e, gate checks only · how these findings are produced · updated Oct 26, 2026 6:47am UTC

Comment thread supabase/functions/_shared/telemetry/usage.ts
dash0-dev Bot added 2 commits October 26, 2026 06:33
…memo retries

Addresses @dash0-dev[bot]'s comment: #725 (comment)

Refs: #725
Co-authored-by: dash0-dev[bot] <257284812+dash0-dev[bot]@users.noreply.github.com>
Co-authored-by: dash0-dev[bot] <257284812+dash0-dev[bot]@users.noreply.github.com>
@dash0-dev
dash0-dev Bot marked this pull request as ready for review October 26, 2026 06:48
@dash0-dev
dash0-dev Bot requested a review from mthines as a code owner October 26, 2026 06:48
@dash0-dev
dash0-dev Bot merged commit efdeb34 into main Oct 26, 2026
19 checks passed
@dash0-dev
dash0-dev Bot deleted the weekly-improve/2026-10-26-reuse-mcp-plan-lookup branch October 26, 2026 06:48
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

agent0-weekly-improvement Opened by the weekly Agent0 telemetry-driven improvement automation

Projects

None yet

Development

Successfully merging this pull request may close these issues.

0 participants