# task-2945 — 봇 기동(spawn) 지연 실측 리포트

- **팀/담당**: 개발1팀 헤르메스 (dev1-team)
- **일자**: 2026-08-13 11:23 ~ 12:20 (KST)
- **성격**: 측정 전용. 대상 코드(dispatch / spawn_verification / team_prompts) **무수정**. 머지 없음.
- **목적**: task-2942 가 근거 없이 정한 총 대기 **25초**(cron offset 10 + marker 예산 15)를 실측으로 확정한다.

---

## S · 상황

task-2942 는 `dispatch()` 반환 직전에 spawn-confirmed marker 기반 검증을 결선했다. 그러나 총 대기 25초는 실측 없이 산정됐고, Codex 도 "cron 등록 시각 ~ 마커 생성 시각을 상관 수집해 분포 확인 후 확정"을 권고했다.

## C · 복잡성

실측을 시작하자마자 **25초 문제보다 심각한 결함**이 드러났다. `dispatch()` 경로로 발사한 **11건 전부가 marker 를 영원히 만들지 않았다**(300초 grace 에도 0건). 원인을 추적한 결과 대기 시간과 무관한 **프롬프트 4096자 초과 silent drop** 이었고, 그 절벽을 넘긴 주범이 **task-2942 자신이 주입한 마커 지시 블록(197자)** 이었다.

## Q · 질문

1. 정상 spawn 의 실제 지연 분포는?
2. 25초는 충분한가, 오판은 몇 건인가?
3. 권장 대기값은 얼마이며 근거는?

## A · 답

25초는 **불충분**하다(정상 spawn 10건 중 2건 오판). 다만 **더 시급한 것은 대기값이 아니라 4096자 절벽**이며, 이를 먼저 고치지 않으면 대기값을 아무리 키워도 dispatch 는 전건 DISPATCH_FALSE_OK 로 떨어진다.

---

## 1. 측정 방법

| 항목 | 내용 |
|---|---|
| harness | `scripts/measure/task2945_spawn_latency.py` (dispatch 경로), `scripts/measure/task2945_direct_cron_probe.py` (cron 직접 경로) |
| 더미 태스크 | "마커 생성 명령 1개만 실행 후 즉시 종료" (파일생성·보고·finish-task·콜백 전면 금지) |
| 관측 앵커 | `t0`=호출 직전 / `t_fire`=cron `--at`(=t0+10s) / `t_marker`=marker 파일 **최초 목격** |
| marker 관측 | 별도 watcher 스레드가 `memory/events/*.spawn-confirmed-*.json` 을 **0.2초 간격** 폴링. dispatch 가 25초에 포기해도 계속 관측하므로 *진짜 지연*과 *오판*을 동시에 획득 |
| 대상 봇 | dev3·dev4·dev5·dev7·dev8 (dev1=측정 주체 제외, dev2=선점 세션 보유, **dev6=상시 사용금지**) |
| 교차검증 | `~/.cokacdir/schedule_history/*.log` 실행기록 + `/proc/<pid>/cwd` 라이브 세션 + 스케줄 잔존 여부 |

## 2. 결과 ①: dispatch() 경로 — 11건 전건 미spawn

| 구분 | 건수 | dispatch 판정 | marker | 실행기록(schedule_history) | 라이브 세션 |
|---|---|---|---|---|---|
| 파일럿(dev2) | 1 | DISPATCH_FALSE_OK | 없음 | 없음 | 없음(스케줄 40분+ 잔존) |
| 본run(dev3·4·5·7·8) | 10 | DISPATCH_FALSE_OK ×10 | 0/10 | 0/10 | 0/10 |

- dispatch 반환 소요: 25.79 ~ 28.38초 (검증이 25초를 통째로 블로킹).
- 11:20 이후 `schedule_history` 에 남은 실행기록은 **내가 직접 발사한 cron 12건뿐**이며 dispatch 경로 11건은 **0건**이다. 스케줄 파일은 소비(삭제)됐는데 세션은 뜨지 않았다 = **silent drop 확정**.
- ★ 즉 이 11건의 `DISPATCH_FALSE_OK` 는 **오판이 아니라 정탐**이다. task-2942 의 검증 로직은 실제 결함을 정확히 잡아냈다.

## 3. 결과 ②: 정상 spawn 지연 분포 (cron 직접 발사, n=10)

marker 를 실제로 만든 10건 (모두 4096자 미만 프롬프트, 유휴 봇):

| task | bot | prompt(B) | 호출→마커(s) | 발사→마커(s) |
|---|---|---|---|---|
| task-99033 | dev5 | 216 | 19.38 | 10.15 |
| task-99081 | dev5 | 6734 | 21.16 | 12.04 |
| task-99082 | dev7 | 7034 | 21.18 | 12.05 |
| task-99035 | dev8 | 216 | 21.32 | 12.16 |
| task-99032 | dev4 | 216 | 21.78 | 12.53 |
| task-99080 | dev4 | 6236 | 22.35 | 13.18 |
| task-99036 | dev3 | 216 | 22.85 | 13.72 |
| task-99031 | dev3 | 216 | 23.77 | 14.49 |
| task-99034 | dev7 | 216 | **25.10** | **15.91** |
| task-99083 | dev8 | 9236 | **79.41** | **70.27** |

**분포**

| 지표 | 호출→마커 (총대기 대응) | 발사→마커 (marker 예산 대응) |
|---|---|---|
| n | 10 | 10 |
| 최소 | 19.38 | 10.15 |
| 평균 | 27.83 | 18.65 |
| 중앙 | 22.07 | 12.86 |
| p95 | 79.41 | 70.27 |
| **최대** | **79.41** | **70.27** |
| 최대(79초 건 제외, n=9) | 25.10 | 15.91 |

**꼬리 해석**: 79.41초 건(task-99083)은 *실패가 아니라 느린 정상 spawn* 이다. 4건을 **동시 발사**한 상황에서 가장 큰 프롬프트(9236B)를 받은 케이스로, 동시성 부하 + 프롬프트 입력량이 겹치면 지연이 3배 이상 늘어난다는 증거다. 병렬 위임 시 실제로 재현되는 조건이므로 이상치로 버릴 수 없다.

**보조 관측**: task-99092(발사→마커 ≈17.0초, 세션 프로세스 기동 4초 + 첫 명령 실행까지 13초)도 15초 예산을 초과했다.

## 4. 오판(false positive) 판정

| 기준값 | 정상 spawn 인데 FALSE_OK 로 오판 | 비율 |
|---|---|---|
| 현행 총대기 **25초** | **2 / 10** | 20% |
| marker 예산 15초 (발사 기준) | 2 / 10 | 20% |
| 60초 | 1 / 10 | 10% |
| 90초 | 0 / 10 | 0% |

25.10초 건은 현행 기본값을 **0.1초 차이로** 넘겼다. 즉 25초는 실측 분포의 최대치에 정확히 걸쳐 있어 안전마진이 사실상 0이다.

## 5. ★★ 근본원인: 프롬프트 4096자 절벽 (대기값과 무관)

drop 조건을 브래킷 테스트로 특정했다. 기준은 **바이트가 아니라 문자 수**다.

| 프롬프트 | 문자 수 | 바이트 | spawn |
|---|---|---|---|
| 최소 | 약 100 | 216 | ✅ |
| 패딩 | 약 2,400 | 7,034 | ✅ |
| 패딩 | 약 3,200 | 9,236 | ✅ (79초) |
| 경계 C | **4,000** | 11,764 | ✅ |
| 경계 D | **4,200** | 12,364 | ❌ |
| dispatch 실제 프롬프트 | **4,239** | 6,768 | ❌ (12/12) |

- **11,764바이트(4,000자)는 뜨고 6,768바이트(4,239자)는 안 뜬다** → 임계는 문자 수 약 4,096자(Telegram 메시지 한도)다.
- 슬래시로 시작하는 줄, 모델 필드, 프롬프트 바이트 크기는 **모두 원인이 아님**을 개별 테스트로 배제했다.

### 5.1 task-2942 가 절벽을 넘긴 장본인

`build_prompt()` 실측 (level=normal, task_type=coding):

| 팀 | 마커블록 제외 | 현재(2942 적용) | 판정 |
|---|---|---|---|
| dev1 | 4,041 | 4,238 | 2942 가 절벽 넘김 ★ |
| dev2 | 4,037 | 4,234 | 2942 가 절벽 넘김 ★ |
| dev3 | 4,066 | 4,263 | 2942 가 절벽 넘김 ★ |
| dev4 | 4,044 | 4,241 | 2942 가 절벽 넘김 ★ |
| dev5 | 4,040 | 4,237 | 2942 가 절벽 넘김 ★ |
| dev6 | 4,038 | 4,235 | 2942 가 절벽 넘김 ★ |
| dev7 | 4,042 | 4,239 | 2942 가 절벽 넘김 ★ |
| dev8 | 4,432 | 4,629 | **2942 이전부터 이미 초과** |

- dev1~dev7 은 절벽 아래 **여유 30~59자**로 아슬아슬하게 버티고 있었다. task-2942 가 주입한 마커 지시 블록 **197자**가 전 팀을 한 번에 한도 밖으로 밀어냈다.
- dev8 은 4,432자로 **task-2942 이전부터 이미 초과** 상태였다(별도 선행 결함).
- 결과적으로 검증을 ON 으로 머지하면 **모든 dev 팀 위임이 100% 미spawn → 전건 DISPATCH_FALSE_OK** 가 된다.

## 6. 두 번째 교란변수: 봇 선점(occupancy)

파일럿 대상 dev2 는 10:47 부터 세션을 점유 중이었고, 11:26:57 에 등록한 스케줄은 **40분 이상 pending** 상태로 발사되지 않았다(측정 종료 시점까지). 봇이 이미 세션 중이면 스케줄러는 두 번째 세션을 띄우지 않는다.

→ **선점 상태에서 spawn 지연은 상한이 없다.** 어떤 고정 대기값으로도 커버 불가능하며, dispatch 의 기존 봇 충돌 검사(`task-timers.json` 기반)는 이 라이브 세션을 **감지하지 못했다**(busy_bots=[] 로 통과).

## 7. 권장 대기값 (근거 명시)

| 안 | 값 | 근거 | 비고 |
|---|---|---|---|
| **권장** | **총 90초** (offset 10 + marker 예산 80) | 관측 최대 79.41초 + 안전마진 약 13% → 오판 0/10 | 동기 블로킹 시 dispatch 호출당 최대 90초 정지 = 과중 |
| 절충 | 총 60초 | 오판 1/10 (79초 건 실패) | 동시 발사 부하에서 오판 잔존 |
| 현행 | 총 25초 | 오판 2/10 (20%) | **부적합 — 실측 최대치에 0.1초 차로 걸침** |

**최종 권고**: 값만 90초로 올리는 것은 차선이다. dispatch 호출마다 90초를 블로킹하는 비용이 크므로 **비동기/지연 검증으로 전환**(task-2942 가 이미 2차 범위로 지목)한 뒤 판정 시한을 90초로 두는 편이 옳다. 동기 유지가 불가피하면 90초를 기본값으로 하되 `DISPATCH_SPAWN_VERIFY_WAIT_SEC` 로 조정 가능하게 둔다.

**추가 권고 2건**

1. **선점 봇은 검증 대상에서 제외**하거나 별도 상태(`SPAWN_DEFERRED_BOT_BUSY`)로 분리한다. 선점 시 지연 상한이 없어 반드시 오판한다. 이때 선점 판정은 `task-timers.json` 이 아니라 **라이브 세션(`/proc/<pid>/cwd`)** 기준이어야 한다.
2. **프롬프트 4096자 가드**를 dispatch 발사 직전에 넣는다(초과 시 즉시 error 반환 또는 자동 축약). 현재는 초과분이 조용히 사라져 관측 자체가 불가능하다.

## 8. 처리 순서 제안 (회장 결정 대상)

1. **P0 — 4096자 절벽 해소**: 마커 지시 블록 197자를 축약하거나(예: 한 줄 명령만) 프롬프트 본문에서 상쇄 감축. 미해소 시 task-2942 를 **ON 으로 머지하면 전 팀 위임이 즉시 마비**된다.
2. **P0 — dev8 선행 초과(4,432자)** 별도 축약.
3. **P1 — 대기값 90초 + 비동기 검증 전환.**
4. **P1 — 선점 봇 예외 처리 + 라이브 세션 기반 충돌 검사.**

> 긴급 무력화는 코드 변경 없이 `DISPATCH_SPAWN_VERIFY_ENABLED=0` 으로 가능하다. 단 이는 검증만 끄는 것이며, **4096자 절벽으로 인한 실제 미spawn 은 그대로 남는다**(검증을 끄면 조용한 false-OK 로 되돌아갈 뿐이다).

## 9. 산출물 / 원상복구

**산출물**

- 본 리포트 `memory/reports/task-2945.md`
- 원자료 `memory/reports/task-2945-raw.jsonl`(dispatch 경로 10건), `task-2945-pilot.jsonl`(1건), `task-2945-direct.jsonl`(6건), `task-2945-bracket.jsonl`(4건)
- harness `scripts/measure/task2945_spawn_latency.py`, `scripts/measure/task2945_direct_cron_probe.py` (신규 · 측정 전용 · 미추적 파일. 재현용으로 남겨둠, 불필요 시 삭제 가능)

**대상 코드 변경 0건** — dispatch / spawn_verification / team_prompts / classifier 모두 무수정(측정 시작 시점의 task-2942 적용 워크트리를 그대로 사용).

**정리한 부수효과**

- `memory/.task-counter`: 더미 task_id(99001…) 때문에 99002 로 튀어 원래 값 **2942 로 복구**
- 더미 산출물 제거: `memory/tasks/task-99*.md`, `memory/events/task-99*`(marker·handoff·allow-no-scope 로그), `memory/task-timers.json` 의 task-99xxx 항목
- 잔여 스케줄 제거: 미발사 스케줄 정리(단, dev2 선점으로 pending 인 건은 상태를 보고에 남김)

## 10. 확신 등급

| 결론 | 등급 | 근거 |
|---|---|---|
| 정상 spawn 지연 분포(n=10, 최대 79.41초) | **높음** | 0.2초 폴링 실측 + schedule_history 교차검증 |
| 25초 오판 2/10 | **높음** | 동일 실측 |
| 4096자 절벽 = drop 원인 | **높음** | 4,000자 성공 / 4,200자 실패 경계 재현, 바이트·슬래시·모델 배제 |
| task-2942 197자가 dev1~7 을 절벽 밖으로 밀어냄 | **높음** | `build_prompt()` 직접 계측 8팀 전수 |
| 권장값 90초 | **중간** | n=10 기준. 4096자 해소 후 *실제 dispatch 프롬프트*로 재측정하면 값이 더 커질 수 있음(프롬프트가 길수록 지연 증가 경향 관측) |
| 선점 시 지연 무한 | **중간** | 관측 1건(40분+ pending). 상한 미확정 |

## 11. 남은 한계 (정직 고지)

- 실제 dispatch 프롬프트(4,239자)로는 **단 1건도 정상 spawn 을 관측하지 못했다**. 따라서 권장 90초는 *4096자 미만 프롬프트* 기준이다. 절벽 해소 후 재측정이 필요하다.
- 표본 n=10 은 p95 를 논하기엔 작다. 꼬리(79초)는 단일 관측이다.
- 선점 봇의 지연 상한은 미측정(하한 40분).