# Postmortem: GH-229 (Plan Cache Misdiagnosis)

> Workspace: `ws-1775617251254-23027ac1f`
> Date: 2026-04-20
> Reviewer: claude-code
> Source: GitHub issue #229

## Issue Summary

| Field | Value |
|-------|-------|
| Issue ID | GH-229 |
| Alert Type | CPU spike (user-reported) |
| Cluster ID | 10518506906906971664 |
| Cluster Type | dedicated |
| TiDB Version | v8.5.4 |
| Time Window | 2026-04-08 06:00 - 09:30 UTC+8 |
| Environment | prod |
| User Feedback | "plan cache 始终是 0，方向就开始往 plan cache 推进，但实际 prepare:exec:close 模式下 plan cache 一定是 0" |

**Issue Description**: Agent observed plan cache hit rate = 0% and CPU profile showing `generateNewPlan` at 42%, then concluded plan cache miss was the root cause. However, the application uses prepare:exec:close = 1:1:1 pattern where plan cache hit = 0 is **expected and normal** — each prepared statement is only executed once then closed, so there's nothing to cache.

## Actual Root Cause

> From user guidance in workspace conversation (round 28-30).

The actual root cause of the CPU spike was **TiDB node count reduction** (scale-in from 13 to 4 original nodes), not plan cache issues:
- Apr 7: 27 TiDB instances (13 original + 14 auto-scaler), total QPS ~73K, ~2,714/instance
- Apr 8: 18 TiDB instances (4 original + 14 auto-scaler), total QPS ~80K (+9.9%), ~4,474/instance (+65%)
- Single-node load nearly doubled, causing CPU spike

In the prepare:exec:close=1:1:1 pattern, every execution triggers a full `generateNewPlan`. This is unavoidable and identical on both days (plan cache miss = 99.6% on BOTH Apr 7 and Apr 8). The difference is purely per-node load due to fewer nodes.

## Agent Diagnosis Summary

> Diagnosis involved ~30 rounds of human-guided investigation.

The agent:

1. Found CPU profile showing `planner.Optimize` at 42%, `generateNewPlan` at 37.85%
2. Found plan cache miss rate = 100%, hit = 0 (both days)
3. **Concluded**: "Plan Cache miss → 重编译 → GC pressure → CPU spike"
4. User then guided the agent to check:
   - Prepare:Execute:Close ratio → found 1:1:1 (every prepare is used once then closed)
   - Plan cache miss was **identical on both days** (99.6%)
   - Cluster topology change: 27 → 18 nodes
   - Per-node load increase: 2,714 → 4,474/s (+65%)

**Critical failure**: Agent treated plan cache hit=0 as abnormal and a root cause, when it's actually expected behavior for the prepare:exec:close=1:1:1 pattern. The agent lacked knowledge of common TiDB usage patterns (prepare-once-execute-once vs prepare-once-execute-many).

**What agent got right** (after guidance):
- Excellent data collection: TopSQL, CPU profiles, plan cache metrics, statement summaries
- Correctly identified the 1:1:1 pattern when asked to check
- Correctly found the topology change (27 → 18 nodes)
- Good cross-day comparison methodology

## Scores

| Dimension | Score (1-5) | Notes |
|-----------|-------------|-------|
| Root Cause Accuracy | 2 | Blamed plan cache miss (normal behavior) instead of node reduction; corrected only after ~10 human interventions |
| Evidence Completeness | 4 | Excellent data collection: TopSQL, CPU profile, plan cache metrics, statement summary, per-instance breakdown |
| Causal Chain | 2 | Initial chain was wrong (plan cache miss → GC → CPU); correct chain (node reduction → per-node load increase) only after heavy guidance |
| Actionability | 3 | Data-driven analysis is strong, but recommendations targeted the wrong problem initially |
| Efficiency | 2 | ~30 rounds of human guidance; agent didn't proactively check usage patterns or compare per-node load |
| **Overall** | **2.6** | |

## Human Guidance Log

### Intervention 1: Check Prepare:Execute:Close ratio
- **Round**: #24
- **User said**: "查询 Prepare/Execute/Close rate，计算 Prepare:Execute 比值，判断是否存在 prepare once execute once 模式"
- **Agent's mistake**: Never checked usage pattern; assumed plan cache should be working
- **Correct behavior**: For plan cache investigation, first check if the application pattern even supports caching (prepare-many/execute-many vs prepare-once/execute-once)
- **Skill**: `tidb-clinic-diagnosis`
- **Deficiency type**: KNOWLEDGE

### Intervention 2: Compare miss rate across days
- **Round**: #28
- **User said**: Strict A/B comparison of plan_cache_miss and plan_cache_hit
- **Agent's mistake**: Didn't notice plan cache miss rate was identical on both days (99.6% vs 99.58%)
- **Correct behavior**: If investigating "why did X change on day A vs day B", first check if X actually changed
- **Skill**: `tidb-clinic-diagnosis`
- **Deficiency type**: REASONING

### Intervention 3: Check cluster topology
- **Round**: #31-35
- **User said**: Per-instance resource/request distribution, original vs auto-scaler grouping
- **Agent's mistake**: Didn't check if node count changed between the two days
- **Correct behavior**: For CPU spike diagnosis, check if capacity (node count) changed, not just load
- **Skill**: `tidb-clinic-diagnosis`
- **Deficiency type**: FLOW

## Skill Deficiencies

### ISS-0041: Agent 缺乏 TiDB 常见使用模式的知识（prepare:exec:close 模式）

- **Type**: KNOWLEDGE
- **Skill**: `tidb-clinic-diagnosis`
- **Current behavior**: Agent sees plan cache hit=0 and assumes it's abnormal, directs diagnosis toward "fix plan cache"
- **Expected behavior**: Agent should recognize prepare:exec:close=1:1:1 as a valid application pattern where plan cache hit=0 is expected
- **Suggested fix**: Add usage pattern recognition to SKILL.md: "Before concluding plan cache is broken, check StmtPrepare:StmtExecute:StmtClose ratio. If ≈1:1:1, plan cache miss is expected — this is prepare-once-execute-once pattern, not a bug."
- **Priority**: P1-high
- **Status**: open

### ISS-0042: Agent 在 A/B 对比中未检查"变量是否真的变了"

- **Type**: REASONING
- **Skill**: `tidb-clinic-diagnosis`
- **Current behavior**: Agent observes a metric is "bad" (plan cache miss=100%) and blames it, without checking if it was equally "bad" in the baseline period
- **Expected behavior**: In A/B analysis, first verify the suspected cause actually changed between A and B. If plan cache miss=100% on BOTH days, it's not the differentiator.
- **Suggested fix**: Add A/B reasoning rule: "For any metric blamed as root cause, verify it differs significantly between the problem period and baseline. If it's the same in both, it's a constant — not the cause of the change."
- **Priority**: P1-high
- **Status**: open

## Data Source Coverage

- [x] Metrics (CPU, GC, malloc rate, compile duration)
- [x] TopSQL TiDB
- [x] Continuous Profiling (CPU + heap)
- [x] Plan cache metrics (miss/hit/plan_num/memory)
- [x] Statement summary (slow_query_logs via Data Proxy)
- [x] Per-instance breakdown
- [x] Cluster topology / node count
- [ ] Activity Hub events (not checked for scale-in)

## Lessons Learned

1. **Plan cache hit=0 is not always a problem** — in prepare:exec:close=1:1:1 pattern, it's expected. Agent needs to understand application usage patterns before diagnosing plan cache issues.
2. **A/B analysis must verify the suspected cause actually changed** — if a metric is the same in both the problem and baseline periods, it's not the differentiator. The real cause is what changed (node count, QPS distribution, etc.).
3. **Capacity changes are a top suspect for load-per-node spikes** — when CPU per node increases but total QPS is stable, check if node count decreased (scale-in, node failure, maintenance).
4. **Agent's data collection was excellent** — despite wrong initial conclusion, the agent gathered comprehensive evidence (TopSQL, profiles, plan cache metrics, per-instance data). The gap was in reasoning, not data access.