Skip to content

observability: emit per-MCP-server sub-spans inside bundle-tools so cold-start cost is attributable #81595

Description

@mlopez14

Summary

The [trace:embedded-run] prep stages line and the timeline diagnostic (openclaw.diagnostics.v1 envelope) both expose bundle-tools as a single aggregate duration. On hosts with multiple stdio MCP servers configured, this stage routinely accounts for the dominant share of per-turn prep time — but it's a black box: there's no way to attribute the cost to a specific MCP server, plugin tool registry, or sub-step.

This makes regressions and duplicate-child situations (e.g. #75621) much harder to diagnose than they need to be, and makes proposed fixes like #80131 (tool bundling memoization) harder to verify after the fact.

Concrete observation

On a Linux/WSL host running OpenClaw 2026.5.7 with 6 stdio MCP servers configured (filesystem, github, desktop-automation via WSL→cmd.exe, and 3× graphify.serve), bundle-tools shows a bimodal distribution:

  • Fast mode: ~8 s (event loop quiet)
  • Slow mode: ~17–20 s (event loop contended by concurrent worker subagents)
  • Outliers >50 s (one timeout at the 30 s mark on filesystem MCP)
[trace:embedded-run] prep stages: phase=stream-ready totalMs=21441
  workspace-sandbox:1ms, skills:0ms, core-plugin-tools:320ms,
  bootstrap-context:27ms,
  bundle-tools:20931ms,            ← black box
  system-prompt:5ms, session-resource-loader:137ms,
  agent-session:0ms, stream-setup:20ms

All evidence points at sequential tools/list cold-start across the MCP children (re-spawned per prep cycle), with one slow child dominating, but there is no log signal that names which child is slow. Diagnosis required ad-hoc ps/strace/timing experiments.

Proposal

Emit nested sub-spans inside bundle-tools to the timeline diagnostic (openclaw.diagnostics.v1), one per MCP server / tool source. Also include a compact summary line in the existing aggregate [trace:embedded-run] prep stages log when diagnostics.flags includes timeline or a new bundle-tools.detail flag.

Suggested shape (JSONL timeline):

{"span":"bundle-tools","durationMs":20931,"children":[
  {"span":"mcp.tools_list","server":"filesystem","durationMs":3120,"toolCount":11},
  {"span":"mcp.tools_list","server":"github","durationMs":1840,"toolCount":29},
  {"span":"mcp.tools_list","server":"desktop-automation","durationMs":11420,"toolCount":6,"warn":"slow"},
  {"span":"mcp.tools_list","server":"graphify-orchestrator","durationMs":1505,"toolCount":7},
  {"span":"mcp.tools_list","server":"graphify-trader","durationMs":1490,"toolCount":7},
  {"span":"mcp.tools_list","server":"graphify-openclaw","durationMs":1456,"toolCount":7},
  {"span":"core-plugin-tools.assemble","durationMs":80}
]}

Compact one-liner (for the existing log channel):

[trace:embedded-run] bundle-tools detail: filesystem:3120ms(11) github:1840ms(29) desktop-automation:11420ms(6,slow) graphify-orchestrator:1505ms(7) graphify-trader:1490ms(7) graphify-openclaw:1456ms(7) core-plugin-tools.assemble:80ms

Either format is enough to identify the slowest server at a glance.

Why this matters now

Two open performance issues would directly benefit:

It also helps users with many MCP servers decide which servers are pulling weight vs being dead-weight cold-start cost.

Backwards compatibility

  • New sub-spans should only emit when diagnostics.flags includes timeline (already gated) or a new dedicated flag — no change to default behavior.
  • The aggregate bundle-tools value in the existing [trace:embedded-run] prep stages line stays as-is, so downstream parsers keep working.

Environment

  • OpenClaw 2026.5.7 (eeef486)
  • Node v22.22.2
  • WSL2 / Linux 6.6.87.2-microsoft-standard-WSL2
  • 6 stdio MCP servers configured (filesystem, github, desktop-automation via cmd.exe, 3× graphify.serve)
  • Channels: Discord, Telegram
  • Gateway up ~52 h, ~300 prep traces/day, no regression — the cost is structural

Offer

Happy to test patches against this workload — I already have a CSV parser of the prep-stages line and a baseline corpus across two days of bimodal traffic.

Metadata

Metadata

Assignees

No one assigned

    Labels

    P2Normal backlog priority with limited blast radius.clawsweeper:linked-pr-openClawSweeper found an open linked pull request for this issue.clawsweeper:needs-product-decisionClawSweeper marked this issue as needing a product or behavior decision.clawsweeper:no-new-fix-prClawSweeper does not recommend queueing a new automated fix PR for this issue.clawsweeper:source-reproClawSweeper found a high-confidence source-level issue reproduction.impact:otherThis issue has meaningful maintainer-visible impact outside the owned taxonomy.issue-rating: 🦞 diamond lobsterVery strong issue quality with high-confidence source-level or clear reproduction.staleMarked as stale due to inactivity

    Type

    No type

    Fields

    Priority

    None yet

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions