Skip to content

Instantly share code, notes, and snippets.

@farice

farice/report.html

Last active April 28, 2026 13:15
Show Gist options

  • Select an option

    Learn more about clone URLs
  • Save farice/ae8ed89a1f58f7dad44d02eb57af365d to your computer and use it in GitHub Desktop.

Select an option

Learn more about clone URLs
Save farice/ae8ed89a1f58f7dad44d02eb57af365d to your computer and use it in GitHub Desktop.
Download ZIP
c4c8698a — I2C session deep audit (T3 root cause: LLM passed max_concurrent=1)
Raw
report.html
<!doctype html>
<html lang="en"><head><meta charset="utf-8">
<title>c4c8698a — I2C session deep audit</title>
<script src="https://cdn.jsdelivr.net/npm/chart.js@4.4.1/dist/chart.umd.min.js"></script>
<style>
body { font-family: -apple-system, BlinkMacSystemFont, "Segoe UI", system-ui, sans-serif;
max-width: 980px; margin: 32px auto; padding: 0 24px; color: #1f2328;
line-height: 1.55; }
h1 { border-bottom: 2px solid #d0d7de; padding-bottom: 8px; }
h2 { border-bottom: 1px solid #d0d7de; padding-bottom: 4px; margin-top: 32px; }
table { border-collapse: collapse; margin: 12px 0 18px; font-size: 14px; }
th, td { border: 1px solid #d0d7de; padding: 6px 10px; text-align: left; }
th { background: #f6f8fa; }
code, pre { font-family: ui-monospace, Menlo, Consolas, monospace; font-size: 13px; }
pre { background: #f6f8fa; padding: 12px; border-radius: 6px; overflow-x: auto; }
blockquote { border-left: 4px solid #d0d7de; margin: 8px 0; padding: 4px 12px; color: #57606a; }
.root-cause { background: #fff8c5; border-left: 4px solid #d4a72c; padding: 12px 16px;
border-radius: 4px; margin: 16px 0; }
.severity-HIGH { color: #cf222e; font-weight: 600; }
.severity-MED { color: #bf8700; font-weight: 600; }
.severity-LOW { color: #57606a; }
details { margin: 8px 0; }
summary { cursor: pointer; font-weight: 600; color: #0969da; }
.chart-wrap { background: #fff; border: 1px solid #d0d7de; border-radius: 8px;
padding: 16px; margin: 16px 0; }
</style>
</head><body>
<h1>Session <code>c4c8698a</code> — I2C extraction deep audit</h1>
<p><b>Date:</b> 2026-04-28 · <b>Spec:</b> I2C (18 pages) · <b>Wall:</b> ~50 min ·
<b>Status:</b> live audit, in <code>Pruning</code> phase as of 12:15Z.</p>
<div class="root-cause">
<h3 style="margin-top:0">Root cause (T3, proven)</h3>
<p>The 18.5-minute gap between chunk 1 and chunk 2 progress events is <b>not a bug in
the parallel chunk code path</b>. The agent (LLM) explicitly passed
<code>max_concurrent=1</code> to <code>extract_features_batch</code>, forcing the
<code>asyncio.Semaphore(max_concurrent)</code> at <code>extract.py:5039</code> to
admit one chunk at a time.</p>
<pre>2026-04-28T11:35:07.003Z conductor.agents.mcp_server
msg=&quot;extract_features_batch: pages=18 chunk_size=18 <b>max_concurrent=1</b> spec_role=primary&quot;</pre>
<p>Same conductor pod, same hour, session <code>e917a876</code> (LPDDR6) called the
same tool with default <code>max_concurrent=5</code> and ran chunks in parallel.</p>
<p><b>Regression test added:</b>
<code>tests/mango/initialize_features/parallel_progress_test.py</code> stubs the
LLM-bound chunk function and asserts both chunk progress messages fire within 1 s
when <code>max_concurrent=5</code>. <b>Passes in 5.4 s</b>.</p>
</div>
<h2>Timeline</h2>
<div class="chart-wrap">
<canvas id="rpcs" height="120"></canvas>
<p style="font-size:12px;color:#57606a;margin-top:6px;">
Pulsar RPC count per minute. The flat zone 11:40-11:53 (≤2 RPC/min) is the
14-min silent window where the agent was awaiting Quasar (n1) for chunk 1.
A second flat zone follows for chunk 2.
</p>
</div>
<h3>Milestones</h3>
<table><tr><th>Time (UTC)</th><th>Event</th></tr>
<tr><td><code>11:26</code></td><td>session created</td></tr>
<tr><td><code>11:27</code></td><td>agent step 1</td></tr>
<tr><td><code>11:30</code></td><td>convert_spec_pages</td></tr>
<tr><td><code>11:31</code></td><td>extract_markdown</td></tr>
<tr><td><code>11:35</code></td><td>extract_features START (LLM passed max_concurrent=1)</td></tr>
<tr><td><code>11:36</code></td><td>chunk 1 progress (Intro/IO/Registers)</td></tr>
<tr><td><code>11:55</code></td><td>chunk 2 progress (Op/Arch) — 18.5 min later</td></tr>
<tr><td><code>12:13</code></td><td>Consolidating</td></tr>
<tr><td><code>12:15</code></td><td>Pruning</td></tr>
</table>
<h2>Theorems and findings</h2>
<details open><summary>Render full audit doc (markdown)</summary>
<pre style="white-space:pre-wrap;"># Session c4c8698a I2C audit (as of 12:06:32Z)
**Status:** alive but stuck inside a single tool call — `extract_features` — for **31 min and counting**, with no completion.
## Hard facts
| Metric | Value | Source |
|---|---|---|
| First log | 2026-04-28T11:26:47.189Z | Loki, `{namespace="conductor"} \|= "c4c8698a"` n=1248 |
| Last log | 2026-04-28T12:06:32.693Z | same |
| Wall | **39.8 min** | derived |
| Steps observed | 20 (last `obs \| step_start step=20` at 11:35:02Z) | derived |
| LLM calls (agent loop) | 20, total **208.3s** (3.5 min), p50 4.7s, max 69.3s (step 15, out=2034) | `obs \| llm_response` |
| Tool calls completed | 29, total **233.0s** (3.9 min) | `obs \| tool_done` |
| Tool currently running | `extract_features` since **11:35:06Z = 31m26s** | no `tool_done` seen |
| Pulsar RPCs | 826, total client-side **30.6s** | `obs \| pulsar_rpc` |
| `execute_task` → `fetch_task_data` wait | n=123, **p50 3.86s, p95 12.9s, max 26.1s, total 697s (11.6 min)** | derived from RPC pairs |
| Errors / WARNs / retries | **0** in entire 40 min | grepped |
## Timeline — sequential phases observed
| Time | Phase / event | Wall |
|---|---|---|
| 11:26:47 | session created (`Client.create_workspace`, 70 ms) | 0:00 |
| 11:27:02 | setup phase 2 heartbeat (sandbox+deps) | 0:15 |
| 11:27:17 | setup phase 3 heartbeat (lfs+agent) | 0:30 |
| 11:27:44 | step 1 starts (agent loop begins) | 0:57 |
| 11:30:04 | tool: `convert_spec_pages` start | 3:17 |
| 11:30:51 | convert done, 18 pages → 38 files (46.4s) | 4:04 |
| 11:30:59 | tool: `extract_markdown` start | 4:12 |
| 11:31:19 | markdown 10/18 done | 4:32 |
| 11:31:45 | extract_markdown done (52.1s); embedding index starts | 4:58 |
| 11:35:02 | step 20 starts | 8:15 |
| 11:35:06 | step 20 LLM done (4.3s, in=20152, out=130 — single tool call) | 8:19 |
| 11:35:12 | tool: `extract_features` → progress "Classifying 18 pages…" | 8:25 |
| **11:36:28** | progress: "**Extracting features: 1 Introduction / 2 IO ports / 3 Registers**" — chunk 1 starts | 9:41 |
| **11:55:01** | progress: "**Extracting features: 4 Operation / 5 Architecture**" — chunk 2 starts | **28:14** |
| 12:06:32 | last activity (still polling `Client.fetch_task` every ~60s) | 39:45 |
## Pulsar RPC distribution (n=826)
| RPC | n | total | p50 | p95 |
|---|---|---|---|---|
| `Client.upload_file` | 329 | 17.2s | 50ms | 96ms |
| `Client.fetch_task` | 154 | 1.3s | 4ms | 17ms |
| `Client.download_file` | 126 | 6.6s | 31ms | 173ms |
| `Client.execute_task` | 123 | 3.9s | 16ms | 86ms |
| `Client.fetch_task_data` | 92 | 0.8s | 8ms | 15ms |
Per-RPC cost is **fine**. The cost is in `execute_task → fetch_task_data` deltas (the SSE/task wait), confirming the same 2.86s p50 floor I documented for Nicolas — tightened today to **p50 3.86s, p95 12.9s** across 123 tasks for **11.6 min of pure SSE wait** (29% of the 40 min wall).
## Theorems
### T1 — The session is alive, not crashed
**Proof:** `Client.fetch_task` polls fire at 12:00:02, 12:00:41, 12:01:24, 12:02:13, 12:03:16, 12:04:19, 12:05:22, 12:06:25 — even spacing of 30-60s. This is conductor's `_wait_for_task` final-probe loop after the SSE budget elapsed. Process is live; it's blocked in an `asyncio.gather` inside `extract_features_for_chunk`.
### T2 — The bottleneck is a **single tool call** that has been running for 31+ min
**Proof:** No `obs | tool_done tool=extract_features` event has fired for c4c8698a; the last `tool_done` was `get_issue` at 11:35:02 step=19. Step 20's LLM (small output, single tool call) fired `extract_features` at 11:35:06 and the tool has been running ever since.
### T3 — Chunks ran serially because the **agent itself passed `max_concurrent=1`** — RESOLVED
**Proof:** Loki query for the per-call invocation log:
```
2026-04-28T11:35:07.003Z conductor.agents.mcp_server msg="extract_features_batch:
pages=18 chunk_size=18 max_concurrent=1 spec_role=primary spec_layer=None mode=ip"
```
Cited at `src/conductor/agents/mcp_server.py:1551-1559` (the entry log right after the LLM-supplied args are bound).
The semaphore at `extract.py:5039` (`asyncio.Semaphore(max_concurrent)`) becomes `Semaphore(1)`, which **forces strict serial execution by design**. The default for the Quasar/vLLM model is `max_concurrent=5` (`capabilities.py:256`); the LLM overrode it.
Comparison: same conductor pod, same time window, session `e917a876` (LPDDR6) on the same code path:
```
Built 61 ToC-aligned chunks (586 pages, chunk_size=20)
Batch: 61 ToC-aligned chunks to process (max_concurrent=5)
```
LPDDR6 used the default `max_concurrent=5`; LPDDR6's chunks ran in parallel. Same code, different LLM-supplied arg.
**Regression test (proves the parallel code path itself works):** `tests/mango/initialize_features/parallel_progress_test.py` (added in this audit, passes in 5.4 s). Stubs the LLM-bound `extract_features_for_chunk` and asserts both chunk progress messages fire within 1 s of each other when `max_concurrent=5`.
Observed:
```
11:36:28 chunk 1 progress: "1 Introduction / 2 IO ports / 3 Registers"
11:55:01 chunk 2 progress: "4 Operation / 5 Architecture"
↑ 18.5 min gap (chunk 1's full LLM duration)
12:13:55 consolidating
↑ 18.9 min gap (chunk 2's full LLM duration)
```
**The bug is in the LLM-facing tool surface, not the code path.** See F1 (rewritten).
### T4 — The session is competing with **2 concurrent extract_features sessions** for n1/Quasar capacity
**Proof:** Loki query for `Extracting features` last 2h shows three concurrent sessions during c4c8698a's run:
| Session | spec | first extract progress | overlap with c4c8698a (11:36-now) |
|---|---|---|---|
| `e917a876` | LPDDR6 (huge spec, 37 progress events) | 11:12:52Z | 11:30:35-12:09:19+ — **continuously overlapping** |
| `c4c8698a` | I2C | 11:36:28Z | self |
| `85cefe5a` | LPDDR6 | 11:56:29Z | 11:56:29-12:04:31+ |
`e917a876` alone fired ≥15 chunk-progress events during 11:36-12:06 (one every ~2 min), implying continuous heavy n1 traffic. Process-wide `MANGO_ONTOLOGY_GLOBAL_CONCURRENT=16` (per memory) caps Instructor calls; with 3 sessions sharing it, c4c8698a's Instructor calls queue behind LPDDR6's.
### T5 — Pulsar SSE floor consumes 29% of wall but is **not** the dominant cost here
**Proof:** 697s SSE wait / 2400s wall = 29%. Compare to 40.5s setup session = 35-42% — same order of magnitude. But the dominant cost on this session is **the 31-min stall inside `extract_features`**, which is mostly Quasar/n1 wait, not Pulsar. Setup-latency PRs (#49, #50 on pulsar) attack a different bottleneck.
### T6 — The 14-min "silent" window (11:40-11:54, only 1 RPC/min) confirms the agent was queued on n1, not on Pulsar
**Proof:** `obs | pulsar_rpc` counts per minute drop from 78 (11:36) and 118 (11:39) to **1 RPC/min for 14 consecutive minutes** (11:40 through 11:53). The 1/min RPC is conductor's `_wait_for_task` final-probe poll. No sandbox interaction means the agent isn't running shell commands — it's awaiting Instructor LLM responses inside `extract_features_for_chunk`.
### T7 — No errors, no retries, no rate-limit signals — purely throughput-bound
**Proof:** Loki grep across full 40 min for `level=ERROR`, `level=WARNING`, `retry`, `timeout`, `throttle`, `rate.limit` returned **zero hits** for this session. The slowness is not from failure-recovery; it's straight queueing/serialization.
### T8 — Setup latency on this session was healthy (~57s) — not the issue
**Proof:** Workspace created 11:26:47, setup phase 3 heartbeat at 11:27:17, agent step 1 at 11:27:44 = ~57 s from session start to first agent step. Consistent with the 40s setup wall I measured for healthier sessions; the agent was in the loop within 1 min.
## Findings (file these as issues)
### F1 — `extract_features_batch` exposes `max_concurrent` to the LLM, which can (and does) tank parallelism (HIGH — confirmed root cause of c4c8698a's 38-min stall)
**Citation:** `src/conductor/agents/mcp_server.py:1481-1489` — `max_concurrent` is an LLM-settable tool arg with default `default_concurrent` (3 or 5 depending on model).
**Evidence:** Live session `c4c8698a` had the LLM pass `max_concurrent=1`, forcing strictly serial chunk execution and adding ~18 min of wall (chunk 2 waited for chunk 1). Same agent code, same tool, same hour: session `e917a876` (LPDDR6) used the default `max_concurrent=5` and ran in parallel. The LLM is not consistent.
**Fix options (in order of safety):**
1. **Recommended:** remove `max_concurrent` from the LLM-facing tool entirely. The agent has zero information advantage about provider concurrency limits — the server's `default_max_concurrent` (per-model, see `capabilities.py:254-259`) is always correct. Internal callers can still pass it.
2. **Defensive:** clamp `effective_concurrent = max(max_concurrent or default, default)` in `mcp_server.py` so the LLM cannot reduce parallelism below the server-chosen default.
3. **Soft:** stronger doc-string warning ("DO NOT pass `max_concurrent` unless explicitly told to lower it"). Weakest, since other sessions show the LLM ignores soft guidance.
`chunk_size` should get the same treatment — c4c8698a's LLM also overrode `chunk_size=18` (vs. model default `chunk_size=20` from `capabilities.py:244`). Same risk surface.
### F2 — No global concurrency cap on `extract_features` (HIGH)
The existing `MANGO_ONTOLOGY_GLOBAL_CONCURRENT=16` cap is for *ontology* extraction. `extract_features` has only the per-call `max_concurrent=5` semaphore — it does **not** participate in the global cap. So 3 concurrent sessions × 5 chunks each = 15 simultaneous chunk-extractions hammering n1, with no admission control. The PR you shipped (5b72955e4) addressed ontology; feature extraction needs the same ZSET admission treatment.
### F3 — No "extract_features started/done" structured log (MEDIUM)
I had to infer the tool was running by *absence* of `obs | tool_done`. Adding `obs | extract_start` and `obs | extract_done` with chunk counts, per-chunk durations, and Instructor-queue-depth would make this kind of audit deterministic instead of forensic.
### F4 — `obs | tool_progress` is too coarse for long-running tools (LOW)
For a 31-min `extract_features` call, only **3 progress messages** fire (classify, chunk 1, chunk 2). Per-chunk-step progress (e.g. "chunk 1: extracting feature 4/27") would let the UI show actual progress instead of looking frozen.
## What's NOT happening (refuted hypotheses)
- ❌ Session crashed → refuted by T1 (alive, polling)
- ❌ Pulsar SSE floor is dominant on this session → refuted by T5 (29% of wall, vs. 60%+ inside extract_features)
- ❌ Errors / retries causing slowdown → refuted by T7 (zero errors)
- ❌ Setup phase slow → refuted by T8 (~57s, healthy)
- ❌ Conductor agent loop slow → refuted: 20 steps in 7m 18s = 22s/step avg, 47% of which is LLM time, normal
## Bottom line
The session is **not stuck**, it's **slow by design** — the LLM picked `max_concurrent=1` for the `extract_features_batch` tool call, forcing the 2 chunks to run serially even though the parallel code path is correct (proven by `parallel_progress_test.py`, which passes with `max_concurrent=5` in 5 s).
Add to that:
- Per-chunk LLM time of ~18 min each (n1/Quasar bound, possibly amplified by F2: no global cap on extract_features means c4c8698a was queueing behind LPDDR6 sessions on the same model)
- 29% of wall in Pulsar SSE waits (T5)
**Total breakdown for 38-min `extract_features`:**
| Component | Time | Avoidable? |
|---|---|---|
| Chunk 1 LLM (serial) | 18.5 min | No — bounded by Quasar |
| Chunk 2 LLM (serial) | 18.9 min | **Yes** — would be ~0 if parallel (F1) |
| Consolidate | 1.4 min | No |
| Prune | ~5 min | Partial — known sequential exec storm in extract.py:2405-2414 |
If F1 is fixed, this exact session would have completed in ~25 min instead of ~44 min — a **~40% reduction** for I2C. For LPDDR6-style specs with 60+ chunks the impact is much larger when an LLM rolls a low `max_concurrent`.
**Filed reproducible regression test:** `tests/mango/initialize_features/parallel_progress_test.py` (passes against current `main`).
</pre>
</details>
<script>
const ctx = document.getElementById('rpcs').getContext('2d');
new Chart(ctx, {
type: 'bar',
data: {
labels: ["11:26", "11:27", "11:28", "11:29", "11:30", "11:31", "11:32", "11:33", "11:34", "11:35", "11:36", "11:37", "11:38", "11:39", "11:40", "11:41", "11:42", "11:43", "11:44", "11:45", "11:46", "11:47", "11:48", "11:49", "11:50", "11:51", "11:52", "11:53", "11:54", "11:55", "11:56", "11:57", "11:58", "11:59", "12:00", "12:01", "12:02", "12:03", "12:04", "12:05", "12:06", "12:07", "12:08", "12:09", "12:10", "12:11", "12:12", "12:13", "12:14", "12:15", "12:16", "12:17", "12:18", "12:19", "12:20", "12:21", "12:22", "12:23", "12:24"],
datasets: [{
label: 'pulsar RPCs / min',
data: [31, 189, 68, 29, 71, 90, 26, 23, 88, 70, 131, 24, 0, 120, 1, 38, 1, 2, 1, 0, 1, 1, 1, 1, 34, 1, 21, 5, 9, 21, 0, 71, 16, 1, 2, 1, 1, 29, 19, 7, 3, 5, 1, 1, 1, 1, 21, 64, 36, 83, 46, 4, 6, 8, 8, 0, 32, 12, 2],
backgroundColor: 'rgba(9,105,218,0.6)'
}]
},
options: {
plugins: { legend: { position: 'top' } },
scales: {
x: { ticks: { maxRotation: 60, autoSkip: true, maxTicksLimit: 25 } },
y: { title: { display: true, text: 'RPCs / min' } }
}
}
});
</script>
<h2>Round 2 — Autonomous deep dive</h2>
<p>After confirming the F1 root cause, three parallel audit agents mapped the rest of the pipeline:
(a) every LLM-settable arg in <code>mcp_server.py</code>, (b) the prune step, (c) <code>classify_spec_pages</code>.</p>
<h3>F5 — Five LLM-settable concurrency footguns (HIGH)</h3>
<p>The <code>extract_features_batch.max_concurrent</code> footgun is one of <strong>five</strong> identical patterns in
<code>mcp_server.py</code>. None have upper clamps; only two have a <code>&lt;1</code> floor.</p>
<table>
<tr><th>Tool</th><th>Arg</th><th>Default source</th><th>Guard</th><th>Severity</th></tr>
<tr><td><code>extract_features_batch</code> (L1458)</td><td><code>max_concurrent</code>, <code>chunk_size</code></td><td><code>caps.default_*</code></td><td><strong>none</strong></td><td class="severity-HIGH">HIGH (proven)</td></tr>
<tr><td><code>extract_markdown</code> (L1056)</td><td><code>max_concurrent</code></td><td>10–40 model-aware</td><td><code>&lt;1</code> reject</td><td class="severity-HIGH">HIGH</td></tr>
<tr><td><code>extract_ontology</code> (L1683)</td><td><code>max_concurrent</code></td><td>3–20 (peak ≈ 5×)</td><td><code>&lt;1</code> reject</td><td class="severity-HIGH">HIGH</td></tr>
<tr><td><code>initialize_assertions</code> (L1785)</td><td><code>max_concurrent</code></td><td><code>caps.default_concurrent</code></td><td><strong>none</strong></td><td class="severity-HIGH">HIGH</td></tr>
<tr><td><code>poll_subagents</code> (L691)</td><td><code>timeout</code></td><td>300 s</td><td>none</td><td>LOW</td></tr>
</table>
<p><strong>Recommended fix:</strong> drop these args from the LLM surface (use <code>caps.default_*</code>),
or clamp to <code>[max(1, default//2), default*2]</code> server-side, and rewrite Field descriptions to NOT advertise the knob.</p>
<h3>F6 — Prune "exec storm" comment is stale; real cost is LLM timeout × format-fallback (HIGH)</h3>
<p>The <code>extract.py:2403-2410</code> comment describes the prior unbatched implementation — PR #663 already batched it.
Current happy-path RPC count for N≤100: <strong>5 exec RPCs + 1 LLM call</strong>, not 100.</p>
<p>Real cost driver:</p>
<ul>
<li><code>prune_timeout_s = 300</code> (extract.py:2280)</li>
<li>Format-fallback loop: <code>max_attempts=2 × 3 formats = 6</code> attempts</li>
<li>Worst case: <strong>6 × 300 s = 30 min</strong> before fail-open returns []</li>
<li>17 min on c4c8698a ≈ ~3–4 LLM timeouts back-to-back</li>
</ul>
<p><strong>Fix sketch:</strong> lower <code>prune_timeout_s</code> to 60–90 s, wrap the fallback loop in an outer
<code>asyncio.wait_for</code> capping total wall, bump format-rejection cache on timeouts.</p>
<h3>F7 — <code>classify_spec_pages</code> is one LLM call; small-spec fast-path missing (MED)</h3>
<ul>
<li>Single <code>create_completion</code> over all pages concatenated (extract.py:2127-2141).</li>
<li>Above <code>CLASSIFY_PAGES_THRESHOLD=300</code>: <strong>skipped</strong>, fail-open to all-relevant. LPDDR6 (586 p) does not classify.</li>
<li>Below threshold: no fast-path. I2C's 18 pages still pays the full 20.7 s call.</li>
<li>Format-negotiation can amplify cold-start (up to 3 round-trips) on first call against a fresh worker.</li>
</ul>
<p><strong>Fix sketch:</strong> add small-spec bypass <code>if page_count &lt;= 30: return all_pages</code>.
Saves the entire 20.7 s for I2C-sized specs.</p>
<h3>F8 — Sequential <code>read_file</code> within a single agent step (LOW)</h3>
<p><code>conductor_agent.py:711</code> iterates tool_calls sequentially with
<code>await asyncio.wait_for(do_execute(...))</code>. For c4c8698a step 23 we observed three back-to-back
<code>read_file</code> tool_done events 2.9 s apart (each at the Pulsar SSE floor).
Trivially I/O-bound, trivially parallelizable.</p>
<h3>F9 — <code>read_testplan_tree</code> does two sequential execs (LOW)</h3>
<p><code>extract.py:307</code> (grep) and <code>:316</code> (find) are independent and sequential.
<code>asyncio.gather</code> saves one Pulsar round-trip (~3 s) per call. Same for <code>_cleanup_empty_l0s</code> at <code>:2871</code>/<code>:2892</code>.</p>
<h2>Updated bottom line</h2>
<table>
<tr><th>Phase</th><th>Current</th><th>Optimized</th><th>Saving</th></tr>
<tr><td>Setup</td><td>57 s</td><td>57 s</td><td>—</td></tr>
<tr><td>Classify (F7 small-spec bypass)</td><td>20.7 s</td><td>0 s</td><td><strong>20.7 s</strong></td></tr>
<tr><td>Chunk 1 LLM</td><td>18.5 min</td><td>18.5 min</td><td>— (Quasar bound)</td></tr>
<tr><td>Chunk 2 LLM (F5/F1: parallel)</td><td>18.9 min</td><td>~0 (overlaps)</td><td><strong>18.9 min</strong></td></tr>
<tr><td>Consolidate</td><td>1.4 min</td><td>1.4 min</td><td>—</td></tr>
<tr><td>Prune (F6: tighter timeout)</td><td>~5–17 min</td><td>≤5 min</td><td>up to <strong>12 min</strong></td></tr>
<tr><td>Post-extract reads (F8: parallel)</td><td>~9 s × 5 steps</td><td>~3 s × 5</td><td>~30 s</td></tr>
</table>
<p><strong>End-to-end I2C wall on c4c8698a: 57 min → ~22 min (62% reduction)</strong> with all fixes.
For LPDDR6 (60+ chunks, no classify, large prune surface), F1 alone is 5–10× wall savings.</p>
</body></html>
Raw
v2.html
<!doctype html><html><head><meta charset="utf-8"><title>c4c8698a deep-dive</title>
<style>
body{font:14px/1.55 -apple-system,BlinkMacSystemFont,sans-serif;max-width:980px;margin:36px auto;padding:0 20px;color:#1a1a1a}
h1,h2,h3{font-weight:600;letter-spacing:-.01em}h1{font-size:30px;margin-bottom:6px}h2{font-size:22px;margin-top:36px;border-bottom:1px solid #e1e4e8;padding-bottom:6px}h3{font-size:16px}
code,pre{font-family:"SFMono-Regular",Menlo,monospace;font-size:13px;background:#f6f8fa;padding:1px 5px;border-radius:3px}
pre{padding:12px;overflow:auto;line-height:1.45}
table{border-collapse:collapse;margin:16px 0;width:100%}
th,td{border:1px solid #d1d5da;padding:7px 11px;text-align:left;vertical-align:top;font-size:13px}
th{background:#f6f8fa;font-weight:600}
.bar{height:22px;background:linear-gradient(90deg,#fb7185,#f59e0b);border-radius:3px;display:inline-block;vertical-align:middle}
.bar.ok{background:linear-gradient(90deg,#10b981,#34d399)}
.muted{color:#666;font-size:12px}
.callout{background:#fffbeb;border-left:4px solid #f59e0b;padding:10px 14px;margin:14px 0;border-radius:0 4px 4px 0}
.callout.bad{background:#fef2f2;border-left-color:#ef4444}
.callout.ok{background:#ecfdf5;border-left-color:#10b981}
</style></head><body>
<h1>c4c8698a deep-dive: where the 93 minutes went</h1>
<p class="muted">Live staging session, I2C spec (18 pages, ToC-aligned into 5 sections / 2 chunks). Span 2026-04-28 11:26:47Z → 12:59:51Z.</p>
<div class="callout bad">
<b>Headline:</b> the prior audit's "57 min" undercounted. <b>True wall: 93.1 min.</b> A single MCP tool call (<code>extract_features_batch</code>) consumed <b>57.3 min (62%)</b> of the entire session. The remaining 35.8 min is the agent loop's own LLM calls (mean 19.7s × 58 calls = 19 min of LLM time on the agent side, plus tool overhead).
</div>
<h2>Step 20 phase breakdown (the 57-min monster)</h2>
<table>
<tr><th>Phase</th><th>Wall time</th><th>Bar</th><th>Driver</th><th>Fix</th></tr>
<tr><td>Setup + classify</td><td>1.4 min</td><td><span class="bar" style="width:9px"></span></td><td>LLM call to classify 18 pages — all return as "relevant" anyway</td><td>PR #962 (skip ≤30 pages)</td></tr>
<tr><td>Chunk 1 extract</td><td><b>18.5 min</b></td><td><span class="bar" style="width:120px"></span></td><td>1× n1-invest reasoning call, ~30k input tokens</td><td>model-bound</td></tr>
<tr><td>Chunk 2 extract</td><td><b>18.9 min</b></td><td><span class="bar" style="width:122px"></span></td><td><b>SEQUENTIAL</b> — agent passed <code>max_concurrent=1</code></td><td>PR #960 (clamp server-side)</td></tr>
<tr><td>Consolidate</td><td>1.4 min</td><td><span class="bar" style="width:9px"></span></td><td>LLM call to merge duplicates</td><td>—</td></tr>
<tr><td>Prune</td><td><b>17.0 min</b></td><td><span class="bar" style="width:110px"></span></td><td>Format-fallback loop, 300s × 6 attempts, no wall budget</td><td>PR #963 (5-min budget)</td></tr>
<tr><th>Total step 20</th><th>57.3 min</th><th></th><th></th><th></th></tr>
</table>
<h2>The previous-audit theory was wrong: Pulsar is not the bottleneck</h2>
<table>
<tr><th>Phase</th><th>Wall</th><th>Pulsar RPCs</th><th>Sum elapsed</th><th>RPC % of wall</th></tr>
<tr><td>Setup + classify</td><td>86 s</td><td>95</td><td>3.6 s</td><td>4.2%</td></tr>
<tr><td>Chunk 1 extract</td><td>1113 s</td><td>178</td><td>4.1 s</td><td><b>0.4%</b></td></tr>
<tr><td>Chunk 2 extract</td><td>1135 s</td><td>180</td><td>4.9 s</td><td><b>0.4%</b></td></tr>
<tr><td>Consolidate</td><td>84 s</td><td>79</td><td>1.7 s</td><td>2.0%</td></tr>
<tr><td>Prune</td><td>1020 s</td><td>141</td><td>3.1 s</td><td>0.3%</td></tr>
</table>
<div class="callout ok">
<b>Nicolas was right.</b> Pulsar is fast. RPC sum elapsed is &lt; 1% of wall in the dominant phases. The ~95% gap between RPCs is <b>LLM call latency</b> (n1-invest reasoning model on Quasar).
</div>
<h3>Chunk 1 RPC inter-arrival gaps (n=177)</h3>
<pre>p50=0.01s p90=18.32s p99=69.63s max=153.80s
gaps &gt; 60s: 11 (sum 795s)
gaps &gt; 30s: 16 (sum 998s)
gaps &gt; 10s: 18 (sum 1047s) ← <b>94% of wall</b></pre>
<h2>NEW finding F11: mango logs perf events at DEBUG → invisible in staging</h2>
<p>Mango computes rich timing data (<code>feature_chunk.model_call</code>, <code>classify_pages</code>, <code>prune.llm_response</code>, …) via <code>_emit_perf_event</code> but logs at <b>DEBUG</b>. Staging runs at INFO — all of it is dropped. To produce this report I had to reconstruct phase boundaries from RPC inter-arrival gaps. That should not be necessary.</p>
<p><b>Fix shipped:</b> <a href="https://github.com/normal-computing/conductor/pull/964">PR #964</a> — one-line change, <code>logger.debug</code> → <code>logger.info</code>. Future incidents resolve in 5 grep queries instead of forensic Loki archaeology.</p>
<h2>Net effect of all 5 PRs on a c4c8698a-class session</h2>
<table>
<tr><th>Phase</th><th>Current</th><th>After fixes</th><th>Saving</th></tr>
<tr><td>Classify (skip small)</td><td>1.4 min</td><td>0 min</td><td>1.4 min</td></tr>
<tr><td>Chunk 1</td><td>18.5 min</td><td>18.5 min</td><td>—</td></tr>
<tr><td>Chunk 2 (parallel w/ chunk 1)</td><td>18.9 min</td><td>~0 (overlap)</td><td>18.9 min</td></tr>
<tr><td>Consolidate</td><td>1.4 min</td><td>1.4 min</td><td>—</td></tr>
<tr><td>Prune (5-min cap)</td><td>17.0 min</td><td>≤5 min</td><td>≥12 min</td></tr>
<tr><th>Step 20 net</th><th>57.3 min</th><th>~22 min</th><th><b>~32 min (56%)</b></th></tr>
<tr><th>Whole session</th><th>93.1 min</th><th>~58 min</th><th><b>38% reduction</b></th></tr>
</table>
<h2>What's left after the fixes</h2>
<p>The remaining ~22 min in step 20 is dominated by <b>one</b> ~18-min LLM call on a reasoning model with a 30k-token prompt. That is the floor for the current model + prompt size, not a footgun. Reducing it further requires either:</p>
<ul>
<li>A smaller / non-reasoning model for extraction (quality trade-off)</li>
<li>Smaller chunks (chunk_size 10 vs 20) — already in place for OpenAI reasoning models, but <b>n1-invest is vLLM</b> and uses chunk_size=20</li>
<li>Trimming the prompt: 30k input tokens for an 18-page spec implies ~1.7k tokens/page — review what's in the prompt</li>
</ul>
<h2>Shipped PRs (all draft)</h2>
<ul>
<li><a href="https://github.com/normal-computing/conductor/pull/960">#960</a> — MCP concurrency footguns clamped (F1, F5)</li>
<li><a href="https://github.com/normal-computing/conductor/pull/961">#961</a> — <code>str_replace</code> 5 sequential RPCs → 2 parallel round-trips (F10)</li>
<li><a href="https://github.com/normal-computing/conductor/pull/962">#962</a> — Small-spec classify bypass (F7)</li>
<li><a href="https://github.com/normal-computing/conductor/pull/963">#963</a> — Prune wall-clock budget cap (F6)</li>
<li><a href="https://github.com/normal-computing/conductor/pull/964">#964</a> — Pipeline perf events at INFO (F11) ← <b>new from deep dive</b></li>
</ul>
</body></html>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment