Last active
April 28, 2026 11:56
-
-
Save farice/3f1dad0752533234cfd96bb61bcfb1c6 to your computer and use it in GitHub Desktop.
Conductor session-setup latency — root-cause analysis (c4c8698a, 2026-04-28)
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| <!doctype html> | |
| <html lang="en"> | |
| <head> | |
| <meta charset="utf-8"> | |
| <title>Conductor session-setup latency — root-cause analysis</title> | |
| <style> | |
| :root { | |
| --bg: #0d1117; | |
| --panel: #161b22; | |
| --border: #30363d; | |
| --fg: #c9d1d9; | |
| --muted: #8b949e; | |
| --accent: #58a6ff; | |
| --warn: #f85149; | |
| --ok: #3fb950; | |
| --code: #1f242c; | |
| } | |
| html, body { background: var(--bg); color: var(--fg); margin: 0; padding: 0; | |
| font-family: -apple-system, BlinkMacSystemFont, "SF Pro Text", Helvetica, Arial, sans-serif; | |
| line-height: 1.55; font-size: 15px; } | |
| .wrap { max-width: 1040px; margin: 0 auto; padding: 36px 28px 80px; } | |
| h1 { font-size: 28px; margin: 0 0 4px; } | |
| h2 { font-size: 20px; margin: 36px 0 12px; padding-bottom: 6px; | |
| border-bottom: 1px solid var(--border); } | |
| h3 { font-size: 16px; margin: 22px 0 8px; color: var(--accent); } | |
| .sub { color: var(--muted); font-size: 13px; margin-bottom: 24px; } | |
| code, pre { font-family: ui-monospace, SFMono-Regular, "SF Mono", Menlo, monospace; | |
| font-size: 13px; } | |
| code { background: var(--code); padding: 1px 6px; border-radius: 4px; | |
| border: 1px solid var(--border); } | |
| pre { background: var(--code); border: 1px solid var(--border); border-radius: 6px; | |
| padding: 12px 14px; overflow-x: auto; } | |
| pre code { background: transparent; border: 0; padding: 0; } | |
| .panel { background: var(--panel); border: 1px solid var(--border); | |
| border-radius: 8px; padding: 18px 20px; margin: 14px 0; } | |
| .tldr { border-left: 3px solid var(--accent); } | |
| .warn { border-left: 3px solid var(--warn); } | |
| .ok { border-left: 3px solid var(--ok); } | |
| table { border-collapse: collapse; width: 100%; margin: 10px 0 18px; font-size: 13px; } | |
| th, td { border: 1px solid var(--border); padding: 7px 10px; text-align: left; | |
| vertical-align: top; } | |
| th { background: var(--panel); } | |
| td.num { text-align: right; font-variant-numeric: tabular-nums; font-family: ui-monospace, monospace; } | |
| a { color: var(--accent); text-decoration: none; } | |
| a:hover { text-decoration: underline; } | |
| .meta { color: var(--muted); font-size: 12px; } | |
| svg { display: block; max-width: 100%; } | |
| .legend { font-size: 12px; color: var(--muted); margin-top: 6px; } | |
| .kpis { display: grid; grid-template-columns: repeat(4, 1fr); gap: 10px; margin: 14px 0; } | |
| .kpi { background: var(--panel); border: 1px solid var(--border); border-radius: 8px; | |
| padding: 14px; text-align: center; } | |
| .kpi .v { font-size: 26px; font-weight: 600; font-variant-numeric: tabular-nums; } | |
| .kpi .l { color: var(--muted); font-size: 12px; margin-top: 2px; } | |
| .kpi.bad .v { color: var(--warn); } | |
| .kpi.good .v { color: var(--ok); } | |
| ul { padding-left: 22px; } | |
| ul li { margin-bottom: 4px; } | |
| </style> | |
| </head> | |
| <body> | |
| <div class="wrap"> | |
| <h1>Conductor session-setup latency — root-cause analysis</h1> | |
| <div class="sub"> | |
| Fresh I2C session <code>c4c8698a</code> on staging · 2026-04-28 11:26:47Z · | |
| evidence from PR #950 (<code>obs | setup_timings</code>) and PR #957 (<code>obs | pulsar_rpc</code>) | |
| </div> | |
| <div class="panel tldr"> | |
| <strong>TL;DR.</strong> The dominant cost is <strong>not</strong> | |
| “non-concurrent small ops with RTT pile-up.” It is a | |
| <strong>fixed ~2.86 s Pulsar-side SSE event-delivery floor on every | |
| <code>execute_task</code></strong>. Setup of a fresh session issues 8 | |
| <code>execute_task</code> calls; even if every task ran in zero time inside | |
| the sandbox, conductor would still wait <code>8 × 2.86 = 22.9 s</code> | |
| for Pulsar to push back <code>TASK_SUCCEEDED</code>. RPC return times look | |
| ms-scale because they <em>are</em> ms — the wait happens inside the SSE stream | |
| and does not show up in <code>fetch_task</code> RPC latency. | |
| </div> | |
| <div class="kpis"> | |
| <div class="kpi bad"><div class="v">40.5s</div><div class="l">setup total wall</div></div> | |
| <div class="kpi"><div class="v">8</div><div class="l"><code>execute_task</code> in setup</div></div> | |
| <div class="kpi bad"><div class="v">2.86s</div><div class="l">median SSE wait (n=197)</div></div> | |
| <div class="kpi bad"><div class="v">~55%</div><div class="l">of wall is SSE floor</div></div> | |
| </div> | |
| <h2>1. Per-phase wall time</h2> | |
| <p>Captured from PR #950's <code>obs | setup_timings</code> log line emitted at | |
| <a href="https://github.com/normal-computing/conductor/blob/main/src/conductor/processors/setting_up.py"> | |
| <code>src/conductor/processors/setting_up.py</code></a>:</p> | |
| <pre><code>session=c4c8698a | |
| clone=0.438 agent_load=0.345 knowledge=0.570 sandbox_start=5.457 | |
| bundle_upload=14.820 deps_install=21.310 | |
| sandbox_config=7.754 agent_setup=8.630 lfs_sync=4.668 | |
| prompt=0.303 push=0.845 init_convo=0.052 | |
| total=40.499</code></pre> | |
| <h3>Phase Gantt (critical path in red)</h3> | |
| <svg viewBox="0 0 980 360" role="img" aria-label="Phase Gantt chart"> | |
| <!-- axis --> | |
| <line x1="160" y1="20" x2="160" y2="340" stroke="#30363d"/> | |
| <line x1="160" y1="340" x2="960" y2="340" stroke="#30363d"/> | |
| <!-- 5s grid --> | |
| <g font-family="ui-monospace,monospace" font-size="10" fill="#8b949e"> | |
| <!-- scale: 800px = 45s, so 1s = ~17.78px --> | |
| <g> | |
| <line x1="160" y1="20" x2="160" y2="345" stroke="#21262d"/><text x="158" y="356" text-anchor="middle">0</text> | |
| <line x1="249" y1="20" x2="249" y2="345" stroke="#21262d"/><text x="249" y="356" text-anchor="middle">5</text> | |
| <line x1="338" y1="20" x2="338" y2="345" stroke="#21262d"/><text x="338" y="356" text-anchor="middle">10</text> | |
| <line x1="427" y1="20" x2="427" y2="345" stroke="#21262d"/><text x="427" y="356" text-anchor="middle">15</text> | |
| <line x1="516" y1="20" x2="516" y2="345" stroke="#21262d"/><text x="516" y="356" text-anchor="middle">20</text> | |
| <line x1="605" y1="20" x2="605" y2="345" stroke="#21262d"/><text x="605" y="356" text-anchor="middle">25</text> | |
| <line x1="694" y1="20" x2="694" y2="345" stroke="#21262d"/><text x="694" y="356" text-anchor="middle">30</text> | |
| <line x1="783" y1="20" x2="783" y2="345" stroke="#21262d"/><text x="783" y="356" text-anchor="middle">35</text> | |
| <line x1="872" y1="20" x2="872" y2="345" stroke="#21262d"/><text x="872" y="356" text-anchor="middle">40</text> | |
| <line x1="960" y1="20" x2="960" y2="345" stroke="#21262d"/><text x="960" y="356" text-anchor="middle">45 (s)</text> | |
| </g> | |
| </g> | |
| <!-- Phase 1 group: 0 - 5.46 --> | |
| <g font-family="-apple-system,Helvetica,sans-serif" font-size="11" fill="#c9d1d9"> | |
| <text x="155" y="38" text-anchor="end">clone (0.44)</text> | |
| <rect x="160" y="28" width="7.8" height="14" fill="#3fb950" opacity="0.8"/> | |
| <text x="155" y="58" text-anchor="end">agent_load (0.35)</text> | |
| <rect x="160" y="48" width="6.2" height="14" fill="#3fb950" opacity="0.8"/> | |
| <text x="155" y="78" text-anchor="end">knowledge (0.57)</text> | |
| <rect x="160" y="68" width="10.1" height="14" fill="#3fb950" opacity="0.8"/> | |
| <text x="155" y="98" text-anchor="end">sandbox_start (5.46)</text> | |
| <rect x="160" y="88" width="97.0" height="14" fill="#f85149" opacity="0.85"/> | |
| <!-- Phase 2: 5.46 - 26.77 --> | |
| <text x="155" y="128" text-anchor="end">bundle_upload (14.82)</text> | |
| <rect x="257" y="118" width="263.5" height="14" fill="#58a6ff" opacity="0.8"/> | |
| <text x="155" y="148" text-anchor="end">deps_install (21.31)</text> | |
| <rect x="257" y="138" width="378.8" height="14" fill="#f85149" opacity="0.85"/> | |
| <!-- Phase 3: 26.77 - 39.19 --> | |
| <!-- sandbox_config 7.75 then lfs_sync 4.67 (sequential within branch) --> | |
| <text x="155" y="178" text-anchor="end">sandbox_config (7.75)</text> | |
| <rect x="636" y="168" width="137.7" height="14" fill="#f85149" opacity="0.85"/> | |
| <text x="155" y="198" text-anchor="end">lfs_sync (4.67)</text> | |
| <rect x="773" y="188" width="83.0" height="14" fill="#f85149" opacity="0.85"/> | |
| <text x="155" y="218" text-anchor="end">agent_setup (8.63)</text> | |
| <rect x="636" y="208" width="153.4" height="14" fill="#58a6ff" opacity="0.8"/> | |
| <!-- Phase 4: 39.19 - 40.40 --> | |
| <text x="155" y="248" text-anchor="end">prompt (0.30)</text> | |
| <rect x="857" y="238" width="5.4" height="14" fill="#f85149" opacity="0.85"/> | |
| <text x="155" y="268" text-anchor="end">push (0.85)</text> | |
| <rect x="862" y="258" width="15.0" height="14" fill="#f85149" opacity="0.85"/> | |
| <text x="155" y="288" text-anchor="end">init_convo (0.05)</text> | |
| <rect x="877" y="278" width="0.9" height="14" fill="#f85149" opacity="0.85"/> | |
| <!-- phase boundaries --> | |
| <line x1="257" y1="22" x2="257" y2="305" stroke="#8b949e" stroke-dasharray="3 3"/> | |
| <text x="259" y="320" font-size="10" fill="#8b949e">P1→P2 (5.5s)</text> | |
| <line x1="635" y1="22" x2="635" y2="305" stroke="#8b949e" stroke-dasharray="3 3"/> | |
| <text x="637" y="320" font-size="10" fill="#8b949e">P2→P3 (26.8s)</text> | |
| <line x1="857" y1="22" x2="857" y2="305" stroke="#8b949e" stroke-dasharray="3 3"/> | |
| <text x="859" y="320" font-size="10" fill="#8b949e">P3→P4 (39.2s)</text> | |
| <line x1="878" y1="22" x2="878" y2="305" stroke="#8b949e" stroke-dasharray="3 3"/> | |
| <text x="813" y="320" font-size="10" fill="#8b949e">end (40.4s)</text> | |
| </g> | |
| </svg> | |
| <div class="legend"> | |
| <span style="color:#f85149">■</span> long pole (defines the phase wall) | |
| <span style="color:#58a6ff">■</span> parallel sibling (overlapped) | |
| <span style="color:#3fb950">■</span> fast op | |
| </div> | |
| <table> | |
| <thead><tr><th>Phase</th><th>Members (parallel)</th><th>Group wall</th></tr></thead> | |
| <tbody> | |
| <tr><td>1</td><td>clone, agent_load, knowledge, <strong>sandbox_start</strong></td><td class="num">5.46s</td></tr> | |
| <tr><td>2</td><td>bundle_upload, <strong>deps_install</strong></td><td class="num">21.31s</td></tr> | |
| <tr><td>3</td><td>(sandbox_config → lfs_sync) ∥ <strong>agent_setup</strong></td><td class="num">12.42s</td></tr> | |
| <tr><td>4</td><td>prompt → push → init_convo</td><td class="num">1.20s</td></tr> | |
| <tr><td colspan="2"><strong>Critical path total</strong></td><td class="num"><strong>40.39s</strong> ≈ 40.50s ✓</td></tr> | |
| </tbody> | |
| </table> | |
| <h2>2. The SSE event-delivery floor (the actual root cause)</h2> | |
| <p>Every Pulsar task follows this pattern in | |
| <a href="https://github.com/normal-computing/conductor/blob/main/src/conductor/environments/pulsar.py#L858"><code>src/conductor/environments/pulsar.py:858</code></a> | |
| (<code>_wait_for_task</code>):</p> | |
| <ol> | |
| <li><code>execute_task</code> RPC submits the task — returns in <strong>milliseconds</strong> (this <em>is</em> what shows in <code>obs | pulsar_rpc</code>).</li> | |
| <li>Pre-check via <code>fetch_task</code> for the “already SUCCESSFUL” fast path (line 877-885).</li> | |
| <li>Otherwise, call <code>_wait_for_event</code> (<a href="https://github.com/normal-computing/conductor/blob/main/src/conductor/environments/pulsar.py#L669"><code>pulsar.py:669-755</code></a>), | |
| which blocks on <code>for _, event in client.watch_events(...)</code> — an SSE iterator. | |
| <strong>This wait emits no log line.</strong></li> | |
| <li>Once <code>TASK_SUCCEEDED</code> arrives over SSE, conductor calls <code>fetch_task_data</code> (logged).</li> | |
| </ol> | |
| <p>So the gap <code>execute_task → fetch_task_data</code> is exactly “Pulsar took this long to push us the success event over SSE.” | |
| Sampled across <strong>197 task pairs from 3 staging sessions</strong>:</p> | |
| <h3>Distribution of SSE waits (n = 197)</h3> | |
| <svg viewBox="0 0 920 280" role="img" aria-label="SSE wait histogram"> | |
| <g font-family="ui-monospace,monospace" font-size="11" fill="#8b949e"> | |
| <line x1="100" y1="20" x2="100" y2="240" stroke="#30363d"/> | |
| <line x1="100" y1="240" x2="900" y2="240" stroke="#30363d"/> | |
| <!-- y-axis labels (count, max=99) --> | |
| <text x="92" y="244" text-anchor="end">0</text> | |
| <text x="92" y="194" text-anchor="end">25</text> | |
| <text x="92" y="144" text-anchor="end">50</text> | |
| <text x="92" y="94" text-anchor="end">75</text> | |
| <text x="92" y="44" text-anchor="end">100</text> | |
| <line x1="98" y1="194" x2="900" y2="194" stroke="#21262d"/> | |
| <line x1="98" y1="144" x2="900" y2="144" stroke="#21262d"/> | |
| <line x1="98" y1="94" x2="900" y2="94" stroke="#21262d"/> | |
| <line x1="98" y1="44" x2="900" y2="44" stroke="#21262d"/> | |
| <text x="50" y="135" text-anchor="middle" transform="rotate(-90 50 135)">count</text> | |
| </g> | |
| <!-- bins: each bar 88px wide; counts: 4, 37, 99, 19, 13, 20, 3, 1 | |
| y-scale: 200px range = 100 count; bar_h = count * 2 --> | |
| <g> | |
| <rect x="110" y="232" width="80" height="8" fill="#3fb950" opacity="0.85"/> | |
| <rect x="200" y="166" width="80" height="74" fill="#58a6ff" opacity="0.85"/> | |
| <rect x="290" y="42" width="80" height="198" fill="#f85149" opacity="0.95"/> | |
| <rect x="380" y="202" width="80" height="38" fill="#58a6ff" opacity="0.85"/> | |
| <rect x="470" y="214" width="80" height="26" fill="#58a6ff" opacity="0.85"/> | |
| <rect x="560" y="200" width="80" height="40" fill="#f8c149" opacity="0.85"/> | |
| <rect x="650" y="234" width="80" height="6" fill="#f8c149" opacity="0.85"/> | |
| <rect x="740" y="238" width="80" height="2" fill="#f8c149" opacity="0.85"/> | |
| </g> | |
| <!-- count labels above bars --> | |
| <g font-family="ui-monospace,monospace" font-size="11" fill="#c9d1d9" text-anchor="middle"> | |
| <text x="150" y="226">4</text> | |
| <text x="240" y="160">37</text> | |
| <text x="330" y="36" font-weight="600">99</text> | |
| <text x="420" y="196">19</text> | |
| <text x="510" y="208">13</text> | |
| <text x="600" y="194">20</text> | |
| <text x="690" y="228">3</text> | |
| <text x="780" y="232">1</text> | |
| </g> | |
| <!-- x-axis labels --> | |
| <g font-family="ui-monospace,monospace" font-size="10" fill="#8b949e" text-anchor="middle"> | |
| <text x="150" y="258">2.0–2.5</text> | |
| <text x="240" y="258">2.5–2.8</text> | |
| <text x="330" y="258" fill="#f85149" font-weight="600">2.8–3.0</text> | |
| <text x="420" y="258">3.0–3.5</text> | |
| <text x="510" y="258">3.5–5.0</text> | |
| <text x="600" y="258">5–10</text> | |
| <text x="690" y="258">10–20</text> | |
| <text x="780" y="258">20–30</text> | |
| <text x="500" y="275" font-size="11">SSE wait band (seconds)</text> | |
| </g> | |
| <!-- median annotation --> | |
| <line x1="330" y1="20" x2="330" y2="42" stroke="#f85149" stroke-dasharray="3 3"/> | |
| <text x="330" y="14" font-family="ui-monospace,monospace" font-size="10" fill="#f85149" text-anchor="middle">median 2.86s</text> | |
| </svg> | |
| <table> | |
| <thead><tr><th>quantile</th><th>p10</th><th>p25</th><th>median</th><th>p75</th><th>p90</th><th>max</th></tr></thead> | |
| <tbody> | |
| <tr><td>SSE wait (s)</td><td class="num">2.72</td><td class="num">2.81</td><td class="num"><strong>2.86</strong></td><td class="num">3.10</td><td class="num">5.64</td><td class="num">24.79</td></tr> | |
| </tbody> | |
| </table> | |
| <div class="panel warn"> | |
| <strong>Why this rules out RTT pile-up.</strong> RTT to staging Pulsar from conductor pods is sub-100 ms. | |
| The 2.86 s floor holds uniformly across <strong>no-op shell commands</strong> (e.g. <code>cat /...checksum</code>) and | |
| <strong>multi-GB tarball extracts</strong> — same band. That is incompatible with RTT or task work; it is | |
| event-emission latency on the Pulsar side. The 50% of all samples landing in a single 200 ms window | |
| (2.8–3.0 s) is consistent with a fixed poll cycle or batch-flush interval upstream of the SSE stream. | |
| </div> | |
| <h2>3. SSE floor × task count = most of the setup wall</h2> | |
| <p>Setup of <code>c4c8698a</code> issued <strong>8 <code>execute_task</code> calls</strong> at offsets:</p> | |
| <svg viewBox="0 0 980 110" role="img" aria-label="execute_task timeline"> | |
| <line x1="40" y1="60" x2="940" y2="60" stroke="#30363d"/> | |
| <g font-family="ui-monospace,monospace" font-size="10" fill="#8b949e"> | |
| <text x="40" y="92" text-anchor="middle">0</text> | |
| <text x="240" y="92" text-anchor="middle">10</text> | |
| <text x="440" y="92" text-anchor="middle">20</text> | |
| <text x="640" y="92" text-anchor="middle">30</text> | |
| <text x="840" y="92" text-anchor="middle">40</text> | |
| <text x="940" y="92" text-anchor="middle">45 s</text> | |
| </g> | |
| <!-- offsets: 5.60 5.69 14.89 15.40 21.00 26.89 27.60 34.82 | |
| 1s = 20px, origin x=40 --> | |
| <g fill="#f85149"> | |
| <circle cx="152" cy="60" r="6"/> | |
| <circle cx="153.8" cy="60" r="6"/> | |
| <circle cx="337.8" cy="60" r="6"/> | |
| <circle cx="348" cy="60" r="6"/> | |
| <circle cx="460" cy="60" r="6"/> | |
| <circle cx="577.8" cy="60" r="6"/> | |
| <circle cx="592" cy="60" r="6"/> | |
| <circle cx="736.4" cy="60" r="6"/> | |
| </g> | |
| <g font-family="ui-monospace,monospace" font-size="10" fill="#c9d1d9" text-anchor="middle"> | |
| <text x="153" y="40">5.6</text> | |
| <text x="153" y="30" fill="#8b949e">5.7</text> | |
| <text x="338" y="40">14.9</text> | |
| <text x="348" y="30" fill="#8b949e">15.4</text> | |
| <text x="460" y="40">21.0</text> | |
| <text x="578" y="40">26.9</text> | |
| <text x="592" y="30" fill="#8b949e">27.6</text> | |
| <text x="736" y="40">34.8</text> | |
| </g> | |
| </svg> | |
| <p><code>8 × 2.86 s = 22.9 s</code> of pure SSE-floor wait. After phase parallelism overlap, | |
| <strong>~14–17 s lands on the critical path</strong> — i.e. <strong>35–42% of the 40.5 s setup wall is | |
| Pulsar event-emission delay</strong>, not anything conductor is doing in code.</p> | |
| <h2>4. Where the 40.5 s actually goes</h2> | |
| <table> | |
| <thead><tr><th>Phase</th><th>Wall</th><th>SSE floor</th><th>Real work</th><th>Notes</th></tr></thead> | |
| <tbody> | |
| <tr><td>sandbox_start</td><td class="num">5.46</td><td class="num">~2.8</td><td class="num">~2.6</td><td>workspace-ready SSE wait + create_workspace RPC (70 ms)</td></tr> | |
| <tr><td>bundle_upload</td><td class="num">14.82</td><td class="num">~5.7</td><td class="num">~9.1</td><td>host <code>git bundle create --all</code> + upload + sandbox <code>git clone --no-checkout</code> (2 tasks)</td></tr> | |
| <tr><td>deps_install</td><td class="num">21.31</td><td class="num">~2.8</td><td class="num">~18.5</td><td>full upload+extract; <strong>prebake cache miss on staging sandbox image</strong></td></tr> | |
| <tr><td>sandbox_config</td><td class="num">7.75</td><td class="num">~2.8</td><td class="num">~5.0</td><td>single coalesced <code>env.exec</code> of 7 git ops (already optimized)</td></tr> | |
| <tr><td>agent_setup</td><td class="num">8.63</td><td class="num">~2.8</td><td class="num">~5.8</td><td>upload_dir burst is 0.65 s; rest is 1×UPLOAD_FILES task wait</td></tr> | |
| <tr><td>lfs_sync</td><td class="num">4.67</td><td class="num">~2.8</td><td class="num">~1.9</td><td>LFS upload_dir + 1 task wait</td></tr> | |
| <tr><td>prompt+push+init_convo</td><td class="num">1.20</td><td class="num">~0</td><td class="num">~1.2</td><td>—</td></tr> | |
| </tbody> | |
| </table> | |
| <h2>5. What the prior framing got wrong</h2> | |
| <table> | |
| <thead><tr><th>Claim</th><th>First-principles check</th></tr></thead> | |
| <tbody> | |
| <tr> | |
| <td>“Workspace creation in 2.8 s.”</td> | |
| <td><code>create_workspace</code> RPC returns in 70 ms. The 2.8 s figure is | |
| one SSE event-delivery cycle for the workspace-ready event — consistent with the broader | |
| 2.86 s floor we now see on every task.</td> | |
| </tr> | |
| <tr> | |
| <td>“Operations terminating in milliseconds.”</td> | |
| <td>RPC <em>returns</em> are ms. <strong>SSE waits inside <code>_wait_for_task</code> are 2.86 s | |
| median each</strong> and emit no <code>pulsar_rpc</code> log line. ~55% of setup time is invisible to a view that only looks at RPC return times.</td> | |
| </tr> | |
| <tr> | |
| <td>“~30 s to UI ready.”</td> | |
| <td><code>setup_timings.total = 40.5 s</code>. UI-ready may fire on an earlier SSE | |
| message (before <code>init_convo</code>), so 30 s ≈ 40 s ± UI marker placement.</td> | |
| </tr> | |
| <tr> | |
| <td>“Many non-concurrent small ops, RTT delays piling up.”</td> | |
| <td>Wrong attribution. Setup is <strong>4 sequential phases with internal parallelism</strong> | |
| (<code>asyncio.gather</code> per phase), issuing <strong>8 tasks</strong>. Each task pays a | |
| <strong>Pulsar-side event-delivery floor</strong>, not RTT (RTT is sub-100 ms; floor is 2.86 s).</td> | |
| </tr> | |
| <tr> | |
| <td>“Run a script doing everything instead of separate commands.”</td> | |
| <td>Already done where possible. <code>_configure_sandbox_impl</code> at | |
| <a href="https://github.com/normal-computing/conductor/blob/main/src/conductor/processors/setting_up.py#L525"><code>setting_up.py:525-530</code></a> | |
| coalesces 7 git ops into a single <code>env.exec</code>. The remaining 8 tasks are | |
| upload, clone, extract, lfs-sync, agent-bundle-upload — each must complete before its | |
| dependents start. <strong>Coalescing is not the lever; killing the tasks via image prebake is.</strong></td> | |
| </tr> | |
| <tr> | |
| <td>“CPU not the bottleneck” (verified at 2.5×).</td> | |
| <td>Consistent. Long pole is SSE wait, not CPU.</td> | |
| </tr> | |
| </tbody> | |
| </table> | |
| <h2>6. Fix candidates (ranked by ROI)</h2> | |
| <div class="panel ok"> | |
| <strong>1. Pulsar-side: shorten the gap between task SUCCESSFUL transition and <code>TASK_SUCCEEDED</code> SSE emission.</strong> | |
| Currently ≥ 2.8 s with very tight clustering (looks like a fixed poll cycle or batch-flush interval). | |
| Cutting it to <500 ms saves <strong>~14 s</strong> off setup wall <em>with zero conductor change</em>. | |
| Highest-ROI lever. | |
| </div> | |
| <div class="panel ok"> | |
| <strong>2. Pulsar-side: ship the prebaked deps inside the workspace image used by <code>executor_type=SERVER</code>.</strong> | |
| Conductor's Dockerfile (<a href="https://github.com/normal-computing/conductor/blob/main/Dockerfile#L79"><code>Dockerfile:79-88</code></a>) | |
| extracts <code>agent_script_deps.tar.gz</code> into <code>/sandbox/.normal_sandbox/agent_deps/</code> with a <code>.checksum</code> marker. | |
| At runtime, <a href="https://github.com/normal-computing/conductor/blob/main/src/conductor/processors/utils.py#L511"><code>processors/utils.py:511-515</code></a> | |
| probes that marker and short-circuits when it matches the host checksum. Conductor's | |
| <code>CreateWorkspaceRequest</code> at <a href="https://github.com/normal-computing/conductor/blob/main/src/conductor/environments/pulsar.py#L987"><code>pulsar.py:987-991</code></a> | |
| only passes <code>executor_type=SERVER</code> — <strong>the workspace image is Pulsar-controlled, not conductor-controlled</strong>. | |
| Whatever image Pulsar pins for the SERVER executor on staging does not contain the prebaked tarball at <code>/sandbox/.normal_sandbox/agent_deps/.checksum</code>, | |
| so the probe misses 100% of the time and conductor pays the full upload+extract every session. Fixing it drops <code>deps_install</code> to ~2.86 s (one SSE floor). | |
| Saves <strong>~18 s</strong>. <em>See “Verification” section below for the cache-miss proof.</em> | |
| </div> | |
| <div class="panel"> | |
| <strong>3. Same prebake pattern for <code>host_agent_dir</code>.</strong> | |
| Removes one <code>execute_task</code> entirely and ~5.8 s of upload work. Saves <strong>~8 s</strong>. | |
| </div> | |
| <div class="panel"> | |
| <strong>4. Shallower bundle in <code>_init_sandbox_repo_impl</code></strong> | |
| (<code>setting_up.py</code>). <code>git bundle create --all</code> packs the entire history; | |
| <code>--branches HEAD</code> would cut bundle creation and clone time. Saves several seconds depending on repo size. | |
| </div> | |
| <div class="panel"> | |
| <strong>5. Bump <code>_PULSAR_FILE_CONCURRENCY</code> from 5</strong> | |
| (<a href="https://github.com/normal-computing/conductor/blob/main/src/conductor/environments/pulsar.py#L269"><code>pulsar.py:269</code></a>). | |
| <em>Not on the setup critical path</em> — <code>agent_setup</code>'s 60-file upload finishes in 0.65 s wall. | |
| Worth doing for tools that fan out 1000+ file reads (observed mid-tool-call), but irrelevant to setup latency. | |
| </div> | |
| <h3>Projection</h3> | |
| <table> | |
| <thead><tr><th>Scenario</th><th>Setup wall</th><th>Δ</th></tr></thead> | |
| <tbody> | |
| <tr><td>Today (staging)</td><td class="num">40.5s</td><td class="num">—</td></tr> | |
| <tr><td>(1) Pulsar SSE floor → <500 ms</td><td class="num">~25s</td><td class="num">–15s</td></tr> | |
| <tr><td>(2) Deps prebake cache hit</td><td class="num">~23s</td><td class="num">–18s</td></tr> | |
| <tr><td>(1) + (2) + (3)</td><td class="num"><strong>~12–15s</strong></td><td class="num"><strong>–25 to –28s</strong></td></tr> | |
| </tbody> | |
| </table> | |
| <h2>7. Verification: the deps-prebake cache misses 100%</h2> | |
| <p>The cache-miss is observable in two independent ways: the <code>deps_install</code> phase wall and the per-RPC sequence pattern.</p> | |
| <h3>A. <code>deps_install</code> distribution across all setups with <code>setup_timings</code> deployed</h3> | |
| <table> | |
| <thead><tr><th>Session</th><th>deps_install</th><th>total</th><th>verdict</th></tr></thead> | |
| <tbody> | |
| <tr><td><code>c4c8698a</code> (I2C, fresh)</td><td class="num">21.31s</td><td class="num">40.50s</td><td>MISS</td></tr> | |
| <tr><td><code>d2a2abd7</code> (I2C, fresh)</td><td class="num">21.50s</td><td class="num">41.14s</td><td>MISS</td></tr> | |
| </tbody> | |
| </table> | |
| <p><strong>2/2 = 100% miss</strong>, both times within 0.2 s of each other — consistent with a ~70-200 MB tarball upload + extract every session. (PR #950 not yet merged, so <code>setup_timings</code> only fires on the dev-branch deployment; sample size is small but signal is unambiguous.)</p> | |
| <p>Cache-hit projection: probe is a single <code>cat /sandbox/.normal_sandbox/agent_deps/.checksum</code> via <code>env.exec</code> — one <code>execute_task</code>, one SSE wait ≈ <strong>2.86 s</strong>. The 18.5 s of real work would vanish.</p> | |
| <h3>B. RPC sequence at the deps_install boundary in <code>c4c8698a</code></h3> | |
| <pre><code>+ 5.48s execute_task (cat .checksum probe — returns 86 ms) | |
| + 5.49s fetch_task (fast-path pre-check — task not yet SUCCESSFUL, 4 ms) | |
| + 5.51s upload_file (deps tarball upload kicked off — 73 ms) ← would NOT happen on cache HIT | |
| + 5.58s execute_task (tar xz extract command — 69 ms) ← would NOT happen on cache HIT | |
| + 5.58s fetch_task (4 ms) | |
| ... [SSE waits over watch_events stream — invisible in pulsar_rpc] ... | |
| +14.75s fetch_task_data (TASK_SUCCEEDED arrived — total 9 s wait = ~6 s real tar work + ~3 s SSE floor)</code></pre> | |
| <p>The presence of <code>upload_file</code> + a second <code>execute_task</code> immediately after the probe RPC is the signature of <code>install_agent_script_deps</code> falling through past the | |
| <a href="https://github.com/normal-computing/conductor/blob/main/src/conductor/processors/utils.py#L511">checksum short-circuit at <code>utils.py:511-515</code></a>. | |
| On a cache HIT the function returns at line 515 and these two RPCs would not be issued.</p> | |
| <h3>C. Why this is Pulsar-side, not conductor-side</h3> | |
| <p>Conductor's request to create a workspace passes only the executor type:</p> | |
| <pre><code>// src/conductor/environments/pulsar.py:987-991 | |
| resp = await _pulsar_call( | |
| get_pulsar_client().create_workspace, | |
| core.api.pulsar.CreateWorkspaceRequest( | |
| executor_type=core.api.pulsar.ExecutorType.SERVER, | |
| ), | |
| ... | |
| )</code></pre> | |
| <p>No image, no command, no volume override. The container image used for SERVER-executor workspaces is configured Pulsar-side. Whatever image is currently pinned on staging does not have <code>/sandbox/.normal_sandbox/agent_deps/.checksum</code> in it — either it’s a different image entirely, or <code>/sandbox</code> is a fresh volume mount that masks the baked layer.</p> | |
| <p>Conductor’s side of this contract (<code>Dockerfile</code> prebake + runtime checksum probe) is wired correctly. The fix is on Pulsar: either base the SERVER executor image on the conductor image, or copy the prebaked tarball + checksum into whatever base image Pulsar uses.</p> | |
| <h2>8. Reproducing this analysis</h2> | |
| <p>All evidence is queryable in Loki:</p> | |
| <pre><code>{namespace="conductor"} |= "obs | setup_timings" |= "session=c4c8698a" | |
| {namespace="conductor"} |= "obs | setup_progress" |= "session=c4c8698a" | |
| {namespace="conductor"} |= "obs | pulsar_rpc" |= "session=c4c8698a"</code></pre> | |
| <p>Per-RPC timing is from PR #957 (merged 2026-04-28). Per-phase wall and the 5 s heartbeat are from PR #950.</p> | |
| <h2>Code citations</h2> | |
| <ul> | |
| <li><a href="https://github.com/normal-computing/conductor/blob/main/src/conductor/environments/pulsar.py#L669"><code>pulsar.py:669-755</code></a> — <code>_wait_for_event</code>, blocks on <code>client.watch_events(...)</code> SSE iterator (no log line)</li> | |
| <li><a href="https://github.com/normal-computing/conductor/blob/main/src/conductor/environments/pulsar.py#L858"><code>pulsar.py:858-911</code></a> — <code>_wait_for_task</code>, with fast-path pre-check at lines 877-885</li> | |
| <li><a href="https://github.com/normal-computing/conductor/blob/main/src/conductor/environments/pulsar.py#L269"><code>pulsar.py:269</code></a> — <code>_PULSAR_FILE_CONCURRENCY = 5</code></li> | |
| <li><a href="https://github.com/normal-computing/conductor/blob/main/src/conductor/processors/setting_up.py#L525"><code>setting_up.py:525-530</code></a> — coalesced sandbox config (7 git ops, 1 exec)</li> | |
| <li><a href="https://github.com/normal-computing/conductor/blob/main/src/conductor/processors/utils.py#L498"><code>utils.py:498-529</code></a> — <code>install_agent_script_deps</code> with checksum short-circuit at 511-515</li> | |
| <li><a href="https://github.com/normal-computing/conductor/blob/main/Dockerfile#L79"><code>Dockerfile:79-88</code></a> — prebake of <code>agent_deps</code> tarball + <code>.checksum</code> marker</li> | |
| <li><a href="https://github.com/normal-computing/conductor/blob/main/src/conductor/environments/pulsar.py#L987"><code>pulsar.py:987-991</code></a> — <code>create_workspace</code> request passes only <code>executor_type=SERVER</code>; image is Pulsar-controlled</li> | |
| </ul> | |
| <div class="meta" style="margin-top:42px"> | |
| Generated 2026-04-28 from session <code>c4c8698a</code> on staging. | |
| SSE-floor distribution sampled across 197 <code>execute_task → fetch_task_data</code> pairs from 3 sessions. | |
| </div> | |
| </div> | |
| </body> | |
| </html> |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment