Wizard AI-Obs: instrument skill on traces; fix Pattern-A subagent context grind (track active time, not wall-clock)

Summary

Two different things make a wizard run "long" in AI Observability. Only one is a problem.

• ⚠️ Pattern A — subagent Bash-grind (the problem). A run spawns a subagent that grinds through hundreds of Bash calls with a context that balloons to ~229K tokens. ~350 generations, ~20–28 min of real LLM compute, $15–22 per run.
• ✅ Pattern B — waiting on the human (expected, not a problem). The run is idle on wizard_ask while the user runs a build / clicks a test button / verifies in PostHog. Wall-clock looks huge (~58 min) but active LLM time is ~3 min. This is by design — do not optimize or alarm on it.

Two asks:

1. Track active LLM time + cost + generations per skill — not wall-clock. Wall-clock conflates expected human waiting (B) with real slowness (A) and overstates the problem.
2. Attack Pattern A (the subagent context grind).

There's also a blocking instrumentation gap (below): we can't slice any of this by skill today.

Headline numbers (project 2, ai_product = wizard, last 30d, n=19,959)

Metric	P50	P95	P99
Wall-clock	5.7 min	15.4 min	35 min
Active LLM time	3.1 min	7.5 min	–
Generations	54	120	–
Cost	–	$5.82	–

Slow tail (wall > 20 min), by pattern:

Pattern	Traces	Wall P50/P95	Active LLM P50/P95	Median gens	Verdict
A — subagent grind	115	38 / 51 min	20 / 28 min	350	⚠️ real cost
B — human-wait	383	28 / 58 min	6 / 14 min	97	✅ expected, ignore

2.4% of all runs spawn a subagent; 9.2% are idle-dominated (wall > 2× active).

Instrumentation gap (blocks per-skill analysis)

Wizard runs are tagged only with ai_product = wizard. No event/trace property records which skill produced the run (self-driving-setup, error-tracking-setup, integration-*, audit-*). The skill id lives only inside the install_skill tool-call payload, and that blob is NULL in ClickHouse (length(toString(properties.$ai_input)) → None) — served by the trace API but not queryable. Worse, the slowest runs (383–534 gens, ~20–40 MB) exceed the trace-API size limit, so the worst offenders can't even be labeled by fetching+grepping.

Fix (small, at the source): when the agent run starts, set trace properties from session — wizard_skill_id, wizard_program_id, wizard_command, wizard_framework — on the same trace-property bag that already carries ai_product/variant (src/utils/analytics.ts + agent-runner). Also emit a wizard_waiting_on_human marker (or wizard_ask count) so human-wait time can be subtracted. Then per-skill latency/cost is a GROUP BY.

Referenced traces

Deep link: https://us.posthog.com/project/2/ai-observability/traces/<id>. Raw payloads + per-generation timeline saved locally under /tmp/wizard-traces/.

⚠️ Pattern A — subagent Bash-grind — 92def4a3

383 gens · 51 min wall · ~28 min active · $17.64. From the timeline:

1. Main agent reads repo; context climbs 1.3K → 158K tokens.
2. At 158K it calls Agent → subagent starts fresh at ~18K tokens.
3. Subagent runs hundreds of sequential Bash calls, context growing 18K → 229K (near the 200K window), with periodic 22–33 s Writes; one generation stalls 285 s.
4. Cost driver: 383 generations each re-reading a 100–229K-token cached context.

Same-shape cohort (30d, has_agent=1, 340–534 gens, $13–22): a0087986 ($22.13), a6880647 ($20.86), 0e512d5f ($19.32), 2391e836 ($18.82), e2355d41 ($17.68), a0ba73d7 ($17.31), 9d4c94c1 ($16.65), e69d1361 ($16.61), 06b24f46 ($16.52), 962c4c16 ($15.40), d4b4358b ($19.29), 5bcf496e ($14.16).

✅ Pattern B — human-wait (EXPECTED) — a4c8a3ad

skill error-tracking-upload-source-maps-nextjs · 46 gens · 58.3 min wall · 3.2 min active · $1.98. 55 of 58 min are idle on wizard_ask while the user builds, triggers a test error, and verifies the stack trace. Working as designed. Included only to show why the "error-tracking ~47 min" wall-clock figure is misleading — that's the human, not the wizard.

Baseline — healthy run — fa7764c8

skill integration-nextjs-app-router · 70 gens · 10.9 min wall ≈ active · $3.18 · 0 errors. LLM-bound, no idle, no subagent grind.

Reproduce

SELECT properties.$ai_trace_id AS tid,
       dateDiff('second', min(timestamp), max(timestamp)) AS wall_s,
       sum(toFloat(properties.$ai_latency))               AS active_s,
       count() AS gens,
       sum(toFloat(properties.$ai_total_cost_usd))        AS cost,
       max(position(toString(properties.$ai_tools_called), 'Agent') > 0) AS subagent
FROM events
WHERE event = '$ai_generation' AND properties.ai_product = 'wizard'
  AND timestamp > now() - INTERVAL 30 DAY
GROUP BY tid ORDER BY active_s DESC;

Start with src/utils/analytics.ts and the agent-runner path that starts a wizard run; inspect how existing ai_product and variant trace properties are populated from session. Use the supplied SQL query and trace examples to verify skill, program, command, framework, active-time, cost, generation, and human-wait data are queryable per run. Done means per-skill analysis is possible and Pattern A's subagent context grind is addressed without treating Pattern B as a problem.