#!/usr/bin/env python3
"""#21 acceptance — 한 주행의 **시간**을 네 칸으로 가른다 (2026-08-29).

Codex 합의: 걸린 시간 「한 숫자」로는 판정할 수 없다. 같은 주행에서 넷을 봐야
「무엇이 줄었고 무엇이 안 줄었나」가 갈린다.

    ① E2E 총시간 · `scene_image_pipeline` 시간
    ② 단계별 호출 수 — ④~⑥·⑧ 이 정말 안 도는지
    ③ **롤 A/B 겹침** — PR #44 가 닿았는지 (파일 시각으로)
    ④ Gemini / Grok **개별** duration 분포 — 단일 호출 지연이 남았는지

★새 계측 코드를 안 넣는다. `ask_openrouter_structured` 가 호출 앞뒤를 재어
 DB `llm_call_log.duration_ms` 로 남기므로 이미 있는 것으로 본다.

## 왜 주행 **전에** 만드나

주행이 끝난 뒤에 도구를 만들면, 그때 없는 것이 「없었다」인지 「내가 안
남겼다」인지 못 가른다. 특히 ③ 롤 겹침은 **파일 mtime** 으로만 보이는데
그건 나중에 덮이면 사라진다.

## 읽는 법 — 겹침 판정

롤 파일 mtime 은 **쓴 시각**이다. 순차면 두 파일이 「생성 시간」만큼
떨어지고, 병렬이면 붙는다. ★가장 확실한 증거는 **b 가 a 보다 먼저**
끝나는 것이다 — 순차 생성은 a 를 쓰고 b 를 쓰므로 역전이 불가능하다.
그래서 간격뿐 아니라 **역전 건수**를 따로 센다.

usage:  run_time_breakdown.py <project_id> <episode_id> [--since ISO]
"""
from __future__ import annotations

import pathlib
import sys
from collections import Counter, defaultdict

sys.path.insert(0, str(pathlib.Path(__file__).resolve().parents[2]))
ROOT = pathlib.Path(__file__).resolve().parents[3]

KST = 9 * 3600  # 보고는 언제나 KST


def _rows(episode_id: str, since: str | None):
    from sqlalchemy import create_engine, text

    from app.core.config import settings
    eng = create_engine(settings.database_url)
    # ★`step_name` 이 아니라 `operation_type` 이 하위 단계를 갖는다.
    #  이미지 파이프라인 호출은 `step_name` 이 전부 `scene_image_pipeline`
    #  이라, 거기서 "critique"·"rejudge" 를 찾으면 **언제나 0건**이고 그
    #  0이 「안 돈다」로 읽힌다 — 내가 이 도구를 만들며 실제로 그랬다.
    #  실물: operation_type = `still_recipe_critique_observe_grok46` ·
    #  `still_recipe_judge_openrouter:xai/grok4.6` · `still_recipe_roll` …
    sql = ("SELECT step_name, model_name, duration_ms, input_tokens, "
           "output_tokens, status, created_at, operation_type "
           "FROM llm_call_log WHERE episode_id = :e")
    if since:
        sql += " AND created_at >= :s"
    with eng.connect() as c:
        p = {"e": episode_id}
        if since:
            p["s"] = since
        return c.execute(text(sql + " ORDER BY created_at"), p).fetchall()


#: 이미지 계열 스텝 — 이름은 조립부(step_manifest)에서 그대로 가져온다.
#  손으로 지어내면 0건이 나오고 그 0이 「없다」로 읽힌다.
_IMAGE_STEPS = {
    "scene_image_pipeline", "ref_image_gen", "composite_image_gen",
    "background_render", "floor_plan_render", "shot_conti_light",
}


def _p(v):
    from datetime import datetime as _dt
    return _dt.fromisoformat(v) if isinstance(v, str) else v


def _step_rows(episode_id: str):
    from sqlalchemy import create_engine, text

    from app.core.config import settings
    eng = create_engine(settings.database_url)
    with eng.connect() as c:
        return c.execute(text(
            "SELECT step_id, started_at, completed_at, status FROM step_run "
            "WHERE episode_id = :e AND started_at IS NOT NULL "
            "ORDER BY started_at"), {"e": episode_id}).fetchall()


def _pct(vals, q):
    if not vals:
        return 0
    s = sorted(vals)
    return s[min(len(s) - 1, int(len(s) * q))]


def main() -> int:
    argv = [a for a in sys.argv[1:] if not a.startswith("--")]
    since = None
    for a in sys.argv[1:]:
        if a.startswith("--since="):
            since = a.split("=", 1)[1]
    if len(argv) < 2:
        print(__doc__)
        return 2
    project_id, episode_id = argv[0], argv[1]

    from app.core.config import settings

    rows = _rows(episode_id, since)
    print(f"llm_call_log {len(rows)}건" + (f" (since {since})" if since else ""))
    if not rows:
        print("★내 조회로는 못 찾았다 — 「없다」로 읽지 마라. episode_id 와 "
              "since 를 확인하라")
        return 1

    # ── ① 총시간 ────────────────────────────────────────────────
    #
    # ★`llm_call_log` 만 보면 **분석 단계가 통째로 빠진다** — 분석은
    #  litellm→Opik 으로 가고 DB 에는 이미지 계열만 남는다. 그래서 E2E
    #  총시간은 `step_run` 의 started_at/completed_at 으로 잰다.
    _steps = _step_rows(episode_id)
    print("\n① 실제로 걸린 시간")
    if _steps:
        s0 = min(r[1] for r in _steps if r[1])
        s1 = max(r[2] for r in _steps if r[2])
        print(f"   E2E (step_run)  {s0} → {s1}")
        print(f"                   {(_p(s1) - _p(s0)).total_seconds() / 60:.1f}분"
              f"   · 스텝 {len(_steps)}개")
        img = [r for r in _steps if r[0] in _IMAGE_STEPS]
        for sid, a, b, _st in sorted(img, key=lambda r: r[1] or ""):
            if a and b:
                print(f"   {sid:26s} {(_p(b) - _p(a)).total_seconds() / 60:7.1f}분")
    else:
        print("   ★내 조회로는 step_run 을 못 찾았다 — 「없다」로 읽지 마라")

    t0, t1 = rows[0][6], rows[-1][6]
    print(f"\n   llm_call_log 첫~마지막 (이미지 계열만)")
    print(f"   {t0} → {t1}")
    # ★DB 가 시각을 문자열로 돌려주는 경우가 있다 — 뺄셈을 조용히 건너뛰면
    #  「총시간 없음」이 되어 이 칸이 통째로 빈다. `_p` 가 파싱한다.
    print(f"   {(_p(t1) - _p(t0)).total_seconds() / 60:.1f}분")

    # ── ② 단계별 호출 수 ────────────────────────────────────────
    by_step = Counter(r[7] or r[0] or "(없음)" for r in rows)
    print("\n② 단계별 호출 수 — `operation_type` 기준 (상위 16)")
    for s, n in by_step.most_common(16):
        print(f"   {n:5d}  {s}")

    # ★꺼 둔 단계가 정말 안 도는지 — 이름을 조립부에서 가져온다
    off = {
        "still_recipe_critique_enabled": ["critique", "observe", "compose",
                                          "_fix", "rejudge"],
        "still_cine_verify_enabled": ["cine_verify"],
    }
    # ★★여기는 **지금 설정**으로 **그때 데이터**를 보는 자리다.
    #  주행이 플래그 변경 **이전** 것이면 「껐는데 호출 0」이 당연히 나오고,
    #  그걸 「수정이 들었다」로 읽으면 거짓 초록이다. 그래서 판정하지 않고
    #  두 사실을 나란히 적기만 한다 — 읽는 사람이 시각을 보고 가른다.
    print("\n   ★아래는 **지금 설정** 대 **그때 호출**이다 —")
    print("    주행이 플래그 변경 전이면 「0」은 수정의 증거가 아니다.")
    print(f"    이 주행: {t0} ~ {t1}")
    for flag, needles in off.items():
        on = bool(getattr(settings, flag, False))
        hit = {s: n for s, n in by_step.items()
               if any(w in s for w in needles)}
        state = "ON" if on else "OFF"
        print(f"   {flag}={state}  →  "
              f"{hit if hit else '이 낱말들을 담은 operation_type 0건'}")
        if not hit:
            print(f"      (찾은 낱말: {needles} — 0건이 「안 돈다」인지 "
                  "「내 낱말이 안 맞는다」인지는 위 ② 목록과 대조하라)")
        if not on and hit:
            print("      ★지금 껐는데 그때 돌았다 — 주행이 변경 전이면 "
                  "당연하고, 변경 후면 플래그가 그 자리에 안 닿는 것이다")

    # ── ④ 모델별 duration 분포 ─────────────────────────────────
    by_model = defaultdict(list)
    for r in rows:
        if r[2] is not None:
            by_model[r[1] or "(없음)"].append(int(r[2]))
    print(f"\n④ 모델별 duration (초) — n · 중앙 · p90 · 최대")
    for m, v in sorted(by_model.items(), key=lambda kv: -len(kv[1])):
        print(f"   {len(v):5d}  {_pct(v,.5)/1000:7.1f}  {_pct(v,.9)/1000:7.1f}"
              f"  {max(v)/1000:7.1f}   {m}")

    # ── ③ 롤 A/B 겹침 ─────────────────────────────────────────
    recipe = (pathlib.Path(settings.projects_dir) / project_id / "images"
              / episode_id / "scene" / "recipe")
    print(f"\n③ 롤 A/B 겹침  ({recipe})")
    if not recipe.is_dir():
        print("   ★내 조회로는 폴더를 못 찾았다 — 경로를 확인하라")
        return 0
    pairs, gaps, reversed_n = 0, [], 0
    for a in sorted(recipe.glob("*_a.png")):
        b = a.with_name(a.name[:-6] + "_b.png")
        if not b.exists():
            continue
        pairs += 1
        ta, tb = a.stat().st_mtime, b.stat().st_mtime
        gaps.append(abs(tb - ta))
        if tb < ta:
            reversed_n += 1
    if not pairs:
        print("   ★쌍이 0개다 — 「겹쳤다」고 말할 수 없다. 이 칸은 미측정")
        return 0
    gaps.sort()
    print(f"   쌍 {pairs}개 · 간격 중앙 {gaps[len(gaps)//2]:.1f}초 · "
          f"최대 {gaps[-1]:.1f}초")
    print(f"   ★b 가 a 보다 먼저 끝난 쌍: {reversed_n}/{pairs} "
          f"— 순차 생성으로는 불가능하다(병렬의 직접 증거)")
    if reversed_n == 0:
        print("   ★역전이 0이면 병렬이라고 단정하지 마라 — 간격이 작아도 "
              "생성이 빨랐을 뿐일 수 있다. 그때는 Opik span 으로 본다")
    return 0


if __name__ == "__main__":
    raise SystemExit(main())