E2E 지연 측정 — 4.3절 예산이 실제로 지켜지는가

무엇을

발화 종료 → 카드 표시까지 구간별 지연을 운영 경로에서 잰다(4.3절).

잴 수 있게 된 지 얼마 안 됐다

2026-09-14 까지는 못 쟀다. TranscriptEvent 에 이벤트 도착 시각이 없어서 발동 시각을 「발화 종료 + 346ms」로 모형화하고 있었고, 그대로 채점하면 p50 = p95 = 346 · 적절 발동률 1.0 이라는 가짜 만점이 나왔다(절대 원칙 10).

09-14 에 콜 미디에이터가 received_at_ms 를 실어 보내고 트리거가 그것을 쓰도록 고쳤다 (w4-trigger-arrival-time) — 실시간 경로의 trigger_at_ms 는 이제 측정값이다. 이 티켓은 그 값을 실제로 모으는 일이다.

⚠ 평가 하네스는 여전히 측정 불가다 — 골든셋에 도착 시각이 없다. 이 티켓은 운영 경로만 잰다.

구간

발화 종료 → STT 최종 결과 → 콜 미디에이터 수신 → 트리거 판정 → 검색 → 생성 → 브라우저 표시

내부 처리 p95 ≤1,000ms(4.1절)는 그중 「트리거 판정 → 생성」 구간이다 — 전체 E2E 와 같은 숫자가 아니다. 두 수를 섞어 적지 않는다.

완료 조건

• 구간별 p50·p95 를 표본 수와 함께 낸다 (한 통화로 잰 값을 p95 라고 부르지 않는다)
• 예산을 넘는 구간이 있으면 그 구간을 지목한다 — 「느리다」가 아니라 「어디가 느리다」
• 측정일·커밋·명령·표본 수(§5)
• 리랭킹(w4-reranker)·생성이 붙은 뒤의 값이어야 의미가 있다

설계 — 2026-09-20 (_project/decisions/119)

코드를 전수 확인해 무엇이 있고 무엇이 없는지를 구간별로 갈랐다.

e2e_latency_ms 는 컬럼·DTO 가 있는데 아무도 채우지 않아 늘 NULL 이었다(09-20 전수 grep). 서버가 모르는 값을 지어내지 않은 것이라 그 자체는 옳다 — 채울 주체를 정한 적이 없었을 뿐이다.

할 일 (순서)

• 서버(2026-09-20, 0.1.19) — recommendation_interactor 가 검색·생성을 따로 재어 RecommendationCards 에 싣는다. 스키마는 아직 안 고친다(운영 recommendation 0행 · 마이그레이션은 사람 손). 방송·로그에만 싣는다
• 콜 미디에이터(2026-09-21, 0.2.2) — 방송 직전에 e2e_latency_ms = 방송 시각 − utterance_end_ms 를 계산해 싣는다
• 측정 — scripts/persona_sim/e2e_check.py 가 구간별 p50·p95 를 표본 수와 함께 보고서에 낸다
• 보고 — 합성 통화는 STT 를 안 거쳐 ①이 0 이다. source: synthetic + 「STT 미경유」를 붙이고, ①은 V4 실측 346ms 를 더해 「추정 E2E」로 적되 합산이 추정임을 같은 줄에 쓴다(decisions/209 와 같은 규칙)
• 운영 통화가 쌓이기 시작하면 retrieval_ms·generation_ms 를 컬럼으로 승격(generate_schema_docs.py → 마이그레이션)

⚠ 하네스는 계속 「측정 불가」다 — 골든셋에 시계가 없다. 거기에 시각을 지어 넣지 않는다(절대 원칙 2).

준비 — 2026-09-21 코드 확인 (정성윤)

e2e_check.py 는 지금 구간 값을 받을 수 없다. 그래서 「측정」 칸의 첫 일은 수집 경로다.

• e2e_check.py 는 REST(/hub/calls/{id}/transcript · /record)와 DB 에서만 읽는다. DB 에는 internal_latency_ms 만 있다
• retrieval_ms · generation_ms 는 DB 컬럼이 없다(decisions/119 ③) — 응답과 방송에만 실린다
• e2e_latency_ms 는 미디에이터가 방송 직전에 채운다(call_registry.ts 564~581줄). DB 값은 여전히 NULL 이다 — 서버가 방송 전에 저장하기 때문이다
• 방송을 받는 곳은 재생기의 --watch 다(services/call-mediator/scripts/replay_persona_call.ts — /ws?call_id= 를 연다)

할 일 순서

1. 재생기 --watch 가 받은 recommendation 메시지의 네 값(internal_latency_ms · retrieval_ms · generation_ms · e2e_latency_ms)을 JSONL 로 남긴다 — 류준 님 스크립트라 먼저 알린다
2. e2e_check.py 가 그 파일을 읽어 구간별 p50·p95 와 표본 수를 보고서에 낸다
3. 어디서 돌리나 — 운영 DB 는 이 머신에서 닿지 않는다(RDS 는 VPC 안). 운영으로 재려면 DB 판정을 끄고 방송 값만 모으는 모드가 필요하다. 로컬 전체 스택이면 지금 그대로 된다
4. 모델이 운영 노드에 붙은 뒤 한 번 더 잰다 — 리랭커 지연이 여기서 처음 운영 값으로 나온다

2026-09-30 — 측정 준비 (정성윤)

• 운영 DB 에서 internal_latency_ms 의 엔진별 n · p50 · p95 · max 와 최근 7일 값, e2e_latency_ms 가 DB 에 비어 있는 것(방송 직전에만 채움)까지 한 번에 읽는 SELECT 스크립트를 만들었다 (scratchpad/qa-latency-check.sh — 파드 안 psycopg, 읽기 전용). 운영 DB 읽기는 사용자가 ! 로 직접 돌린다(09-30 QA 와 같은 절차). 나온 값을 §5 네 조건과 함께 여기 적는다.
• e2e_latency_ms 는 재생기 --watch --save-ws <jsonl> 로 모은다 — 한 통화로 p95 를 부르지 않으려면 대본 여러 개(dasan-v0 24건)를 돌린 파일이 필요하다. 리허설(w8-demo-rehearsal) 때 같이 모은다.
• 리랭커·생성이 붙은 값(조건 4)은 운영에 리랭커가 없어(decisions/121 운영 실구성) 지금은 낼 수 없다 — 「측정 불가 — 미구성」으로 적는다.

2026-09-30 — 운영 실측 · 내부 처리 구간 (정성윤)

네 조건 — 측정일 2026-09-30 22:55 KST(DB now()) · 운영 server 0.1.43(최근 7일 슬라이스. 전체 기간은 0.1.2x~0.1.43 여러 판이 섞여 있다) · 명령 scratchpad/qa-latency-check.sh(파드 안 psycopg SELECT, recommendation.internal_latency_ms NULL 제외 — 정성윤이 ! 로 실행) · 표본 수는 표에. 구간은 「트리거 판정 → 검색 → 생성」(서버 내부)뿐이다. STT·미디에이터·브라우저 구간은 이 값에 없다(e2e_latency_ms 는 DB 에 0행 — 방송 직전에만 채우므로 예상대로). 카드 0장 추천은 0/115 라 표본에서 빠진 것이 없다.

• 어디가 느린가 — 전체 기간 p95 를 넘긴 것은 synthetic-script 쪽(max 3,300)이다. 재생기 통화는 09-22~24 스포크 구성 실험(리랭커·Ollama 붙였다 뗀 기간, decisions/121) 중에 쌓인 것이 섞여 있어 지금 구성의 값이 아니다. 지금 구성만 보는 최근 7일(n 26)은 p95 655 로 예산 안이다. ⚠ n 26 은 통화 몇 통 분량이라 작다 — 리허설 통화가 쌓이면 다시 읽는다(같은 스크립트).
• retrieval_ms·generation_ms 는 DB 컬럼이 아니라(방송 payload 에만) 구간을 더 쪼개지 못했다 — 컬럼 승격은 아래 할 일 그대로.
• 조건 4(리랭커·생성이 붙은 값)는 측정 불가 — 운영에 리랭커·생성이 없다(decisions/121). 위 값은 「리랭커 없음」 구성의 값이라고 인용한다.

2026-10-01 — done (정성윤)

• 서버 내부 구간 p50·p95 를 표본 수와 함께 냈다(09-30, 최근 7일 n 26 · p95 655 ms · 전체 n 115). 예산 밖 구간은 「옛 실험 구성의 대본 재생」으로 지목했다.
• e2e_check.py 확장·retrieval_ms 컬럼 승격·리랭커 붙은 값은 하지 않는다 — 운영에 리랭커·생성이 없어(decisions/124) 그 값은 「측정 불가 — 미구성」이고, e2e 는 STT 를 안 타는 합성 통화라 ①이 0 이다. 이 이상은 발표 뒤(decisions/138 동결).
• 인용은 decisions/138 정본 그대로: 「최근 7일 · n 26 · server 0.1.43 · 리랭커 없음 · p95 655 ms」.

2026-10-01 — e2e 실측 (정성윤) · 완료 조건을 실측으로 채움

재생기 --watch --save-ws 로 운영에 합성 통화 6건(SYN-004·005·008·010·013·016, --speed 4)을 흘려 /ws 프레임 714줄을 모았다(data/processed/e2e-ws-2026-10-01.jsonl, gitignore). scripts/latency_from_ws.py 로 셈. 발동한 추천 47건.

어디가 느린가 — 서버 내부가 곧 검색(KoE5 dense 임베딩 + ES)이고, e2e − 내부 ≈ 700 ms(p50) 는 콜 미디에이터 채널 줄(CoalescingQueue)에서 앞 발화의 추천을 기다린 시간이다 — --speed 4 로 발화를 4배 빨리 넣어 줄이 길어졌다. 같은 날 운영 DB 의 최근 7일 값(n 26 · p50 538 · p95 655)보다 높다 — 그쪽은 사람 속도의 QA 통화다. 이 값은 「4배속 합성 통화 6건」 조건에서의 값이고, 사람 속도 통화의 상한으로 쓴다. 2 vCPU 노드에서 임베딩이 연속으로 겹치면 1초를 넘는다 — 예산을 넘는 구간은 검색(임베딩) 이다. 네 조건: 2026-10-01 11:2x KST · 운영 server 0.1.44·call-mediator 0.2.12 · 명령 위 그대로 · n 47(통화 6). 인용은 두 표(DB 7일 · 4배속 재생)를 조건과 함께 나란히 — 섞지 않는다.

2026-10-01 밤 — 최종 점검에서 정정 (정성윤) · 앞 절의 e2e 값이 재현되지 않았다

e2e 값 정정. 같은 파일(data/processed/e2e-ws-2026-10-01.jsonl)을 같은 스크립트로 다시 세니 763줄 · 발동 51건이다. 앞 절의 「714줄 · n 47」 은 마지막 재생이 끝나기 전에 읽은 값이다(운영 DB 도 재생 6통화 추천 51건 — 9·12·8·2·13·7). 고친 값:

DB 최근 7일을 다시 읽었다(10-01 밤, 운영 RDS, n 117). 09-30 의 「n 26 · p95 655」 는 그 시각의 사실이지만 오늘 통화가 쌓여 지금은 다르다.

• 예산(내부 p95 ≤ 1,000)은 음성 통화에서는 지켜지고(n 25, p95 722), 글자 채널 대본에서는 안 지켜진다. 4배속 재생만의 문제가 아니다 — 최악은 demo-act1-202609302305(server 0.1.44 배포 직후 첫 act1, 사람 속도): n 10 · p50 2,406 · max 4,719.
• 같은 대본을 다시 돌린 demo-act1-202609302313 은 p50 0 · max 4 다 — 같은 발화는 캐시에서 온다. 09-30 의 n 26 에도 이런 0~3 ms 표본이 6건(test-qa-seongyun-05) 들어 있었다.
• 원인(배포 직후 모델 예열인지, NER 과 임베딩의 CPU 경합인지)은 재지 않았다. 발표 문구는 엔진별 표로 바꾼다 — 「655 ms」 하나로 말하지 않는다.
• 네 조건: 2026-10-01 20시대 KST · 운영 server 0.1.44 · scratchpad/final-db-check2.sh·3.sh(파드 안 SELECT) · n 위 표.