Merge pull request 'feat(ingest): 진행 로그 개선 — 파일명/phase/heartbeat/slowest 요약' (#204) from feat/ingest-log-improve into main

Reviewed-on: #204

CLAUDE.md

@@ -82,7 +82,10 @@ Release 절차:
 
 1. `gitea-release v<X.Y.Z>` (gitea-ops skill) 으로 tag + push + release notes.
 2. release notes 는 사용자 도그푸딩에 영향이 가는 surface 변경을 위주로 — wire schema 추가, CLI flag 신규, TUI 키 변경, V00X migration 등 — 다룬다. 이때 추가된 기능과 변경사항은 유저가 이해할 수 있도록 친절하고 자세하게 풀어서 설명해야 하며, 단순히 commit subject 를 나열하는 형태로 끝내면 안 된다. 필요하다면 도그푸딩이나 테스트 결과도 함께 적어 둔다.
-3. 프리-1.0 (`0.x.y`) 단계: minor bump 시 wire schema additive / surface 변경 누적, patch bump 시 bug fix only.
+3. 프리-1.0 (`0.x.y`) 단계 bump 규칙 — **기능(behavior) 또는 인터페이스(interface) 변경 여부**로 판정:
+   - **minor bump** (`0.x.0`): 기능 또는 인터페이스에 *실질적* 변경이 있을 때. 인터페이스 = 신규/변경/삭제된 CLI subcommand·flag, config 키, wire schema 의 **breaking** 변경, 임베딩/검색/RAG 등 사용자가 받는 **결과·동작**의 변화, V00X migration, frozen 설계 변경. 기능 = 새 source 형식·검색 모드·백엔드 등 *할 수 있는 일*의 추가/변경.
+   - **patch bump** (`0.x.y`): 기능·인터페이스 변경이 **없을** 때. bug fix, 내부 refactor, 성능 개선, 로깅/진행표시 등 **관측성(observability) 개선**, **additive-only wire 변경**(backward-compat 신규 필드/이벤트라 기존 소비자 무영향), 문서. ← 즉 "결과가 같고 새 명령/플래그/config 도 없으면 patch".
+   - 경계 예: 진행 로그에 phase/파일명 추가 + additive wire 이벤트(asset_phase) = **patch** (검색·색인 결과 불변, 새 명령/플래그/config 없음). arctic 임베더 provider + 신규 config 키 = **minor** (인터페이스 추가). 별칭 기능 제거 + migration = **minor** (동작·인터페이스 변경).
 
 **bump 시점 = release 시점 같은 commit**. 즉 commit `chore: bump version 0.x → 0.y` 직후 같은 commit 에 tag. v0.1.0 (`2319206`) 처럼 bump 없이 tag 만 찍는 패턴은 후속 release 가 대상 commit 을 헷갈리게 함 — pre-release snapshot 은 SHA reference 로 충분.
 

Cargo.lock

@@ -4724,7 +4724,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-app"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "base64 0.22.1",
@@ -4772,7 +4772,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-chunk"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "blake3",
@@ -4790,7 +4790,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-cli"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "clap",
@@ -4811,7 +4811,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-config"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "dirs 5.0.1",
@@ -4827,7 +4827,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-core"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "blake3",
@@ -4841,7 +4841,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-embed"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "blake3",
@@ -4855,7 +4855,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-embed-candle"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "candle-core",
@@ -4875,7 +4875,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-embed-local"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "fastembed",
@@ -4888,7 +4888,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-embed-ollama"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "kebab-config",
@@ -4903,7 +4903,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-eval"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "kebab-app",
@@ -4922,7 +4922,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-llm"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "kebab-core",
@@ -4931,7 +4931,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-llm-local"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "kebab-config",
@@ -4948,7 +4948,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-mcp"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "kebab-app",
@@ -4966,7 +4966,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-nli"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "hf-hub",
@@ -4981,7 +4981,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-parse-code"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "gix",
@@ -5004,7 +5004,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-parse-image"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "ab_glyph",
  "anyhow",
@@ -5028,7 +5028,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-parse-md"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "kebab-core",
@@ -5045,7 +5045,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-parse-pdf"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "blake3",
@@ -5060,7 +5060,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-rag"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "blake3",
@@ -5082,7 +5082,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-search"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "globset",
@@ -5101,7 +5101,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-source-fs"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "blake3",
@@ -5119,7 +5119,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-store-sqlite"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "blake3",
@@ -5139,7 +5139,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-store-vector"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "arrow",
@@ -5163,7 +5163,7 @@ dependencies = [
 
 [[package]]
 name = "kebab-tui"
-version = "0.26.0"
+version = "0.26.1"
 dependencies = [
  "anyhow",
  "crossterm",

Cargo.toml

@@ -32,7 +32,7 @@ edition       = "2024"
 rust-version  = "1.85"
 license       = "MIT OR Apache-2.0"
 repository    = "https://github.com/altair823/kebab"
-version       = "0.26.0"   # v0.26.0 — arctic-embed-l-v2.0 임베더 통합: kebab-embed-candle 다중 모델 레지스트리(e5 mean + arctic CLS, 모델별 pooling/prefix 분기) + 신규 kebab-embed-ollama 크레이트(provider="ollama", POST /api/embed, L2 정규화, batch+fail-soft). config models.embedding.provider 에 "ollama" 추가 + endpoint: Option<String>. 기본 동작 불변(provider=fastembed e5), arctic 은 opt-in, embedding_version cascade(arctic-cls / ollama:{model} 태그). — CLAUDE.md §Release
+version       = "0.26.1"   # v0.26.1 — ingest 진행 로그 개선: TTY 진행바에 현재 파일명 + 느린 phase(ocr/caption/embed)+모델명 실시간 + 경과초 heartbeat `(Ns)`, 종료 시 최장 소요 파일 top-5 요약. 신규 wire 이벤트 `asset_phase{idx,total,phase,model}` + `asset_timings.ocr_ms`/`caption_ms` 추가(additive, ingest_progress.v1 유지, serde default 0). 기본 동작 불변. — CLAUDE.md §Release
 
 # pre-v0.18 workspace-wide cleanup: enable clippy::pedantic group with
 # intentional allow-list. The allowed lints are either cosmetic (doc style),

HANDOFF.md

@@ -35,6 +35,7 @@ P0~P5 직렬. P6~P9 P5 이후 병렬 가능.
 
 머지 후 발견된 모든 deviation / hotfix 의 dated 로그는 [tasks/HOTFIXES.md](tasks/HOTFIXES.md). 본 요약은 \"누군가가 인수받을 때 알아두면 시간을 많이 절약하는\" 항목만:
 
+- **2026-06-03 ingest 진행 로그 개선** — v0.26.1. 이미지/PDF + OCR/caption on 볼트 ingest 가 "멈춘 듯" 보이던 문제 해소: TTY 진행바에 현재 파일명 + 느린 phase(ocr/caption/embed)+모델명 + 경과초 `(Ns)` heartbeat, 종료 시 최장 소요 파일 top-5 요약. 신규 wire `asset_phase{idx,total,phase,model}` + `asset_timings.ocr_ms`/`caption_ms`(additive, `ingest_progress.v1` 유지, serde default 0). 이미지·PDF 경로도 `asset_timings` emit(이전 markdown 만). 기본 동작 불변. 자세한 내용: `tasks/HOTFIXES.md` (2026-06-03 ingest 진행 로그), spec/plan `docs/superpowers/{specs,plans}/2026-06-03-ingest-log-improve-*.md`.
 - **2026-06-03 arctic-embed-l-v2.0 임베더 통합** — v0.26.0. 별칭 제거 후 설명형 query recall 보강(측정 recall@10 130/132, e5 +7). `kebab-embed-candle` 모델 레지스트리화(e5 mean + `snowflake-arctic-embed-l-v2.0` CLS, 모델별 pooling/prefix) + 신규 `kebab-embed-ollama`(`provider="ollama"`, `/api/embed`). config `endpoint: Option<String>` 추가. 기본 e5 유지(opt-in), arctic 전환은 embedding_version cascade → 재색인. candle↔Ollama cosine>0.99 게이트로 pooling/prefix 정확성 고정(`#[ignore]`). 자세한 내용: `tasks/HOTFIXES.md` (2026-06-03 arctic), spec `docs/superpowers/specs/2026-06-03-arctic-embedder-spec.md`.
 - **2026-06-03 doc-side expansion(별칭) 기능 완전 제거** — v0.25.0. 아래 2026-05-31 항목의 색인-시 청크당 LLM 별칭 생성 + 별칭 검색 채널을 **전부 제거**(ROI 음수: cross-lingual 은 e5-large 단독으로 충분, 기여는 설명형 +2 그룹뿐인데 대가가 청크당 색인-시 LLM). `Chunk.aliases`/`expansion.rs`/`IngestExpansionCfg`/alias lexical arm/`expansion_progress` wire kind 제거, 신규 마이그레이션 **V013** 이 `chunk_aliases_fts`+`chunks.aliases` DROP. 별칭 default-off 였어 사용자 체감 0, 기존 KB 도 재색인 불요(잔존 별칭 벡터는 `strip_alias_suffix` graceful 매핑/`reset` 정리). `AssetTimings.expansion_ms` 는 wire 호환 위해 값 0 으로 유지. 자세한 내용: `tasks/HOTFIXES.md` (2026-06-03), spec `docs/superpowers/specs/2026-06-03-remove-doc-expansion-spec.md`.
 - **2026-05-31 Phase 2 doc-side expansion 별칭(개별 dense 벡터) + 파생물 캐시(V012)** — v0.21.0 cut. 색인 시 LLM 이 청크별 별칭("같은 의미 다른 표현")을 생성, 줄별 **개별 dense 벡터**(sentinel `{chunk}#alias#N`)로 색인 (묶음 1벡터는 평균화 희석으로 회귀 → 폐기) + boilerplate 청크 skip. `[ingest.expansion]` default off. 측정(나무위키 ~1000 문서 CS corpus): 변형 일관성 14/18 → **16/18**, spread 0.222→0.111, 대조군 false-positive 별칭 무죄. 비용 병목(별칭 18문서 2.5h)은 **파생물 캐시(V012, 청크 내용 해시 키)**로 해소 — 정답 3개 cold 1879s → warm 13s **≈ 145배**, embedding+별칭 LLM 캐싱, version_key cascade 정합. search/ask 가 `kebab.sqlite`+`lancedb` 만으로 동작 → 외부 서버 색인 후 DB 만 복사하는 이식 워크플로 가능. **결정/known limitation**: grounded/refusal 판정이 부분 인용을 grounded 로 오분류(정직한 거부가 false-positive 로 집계) — 별도 개선 후보. stack·svm 설명형 2개 잔존. 자세한 내용: `tasks/HOTFIXES.md` (2026-05-31), 측정: `docs/superpowers/handoffs/2026-05-31-namu-wiki-alias-cache-study.md`.

README.md

@@ -83,7 +83,7 @@ Markdown · PDF · 이미지(OCR + caption) · 소스코드(Rust/Python/TS/JS/Go
 | 명령 | 동작 |
 |------|------|
 | `kebab init` | XDG 경로에 데이터 디렉토리 + config.toml 생성 |
-| `kebab ingest [<path>]` | 워크스페이스 스캔 후 새/변경 문서 색인 (idempotent · incremental, `--force-reingest` 로 강제 재처리). 미지원 확장자는 자동 skip. 진행바는 문서별 청크 수 · 문서 종료 시 phase별 소요시간(parse/chunk/embed/store)을 표시 (`--json` 은 `asset_chunked`/`asset_timings` 이벤트로) |
+| `kebab ingest [<path>]` | 워크스페이스 스캔 후 새/변경 문서 색인 (idempotent · incremental, `--force-reingest` 로 강제 재처리). 미지원 확장자는 자동 skip. 진행바는 현재 **파일명** · 느린 **phase(ocr/caption/embed)+모델명** · **경과초**`(Ns)` · 문서별 청크 수 · phase별 소요시간(parse/chunk/ocr/caption/embed/store)을 표시하고, 종료 시 **최장 소요 파일 top-5** 를 요약한다 (`--json` 은 `asset_phase`/`asset_chunked`/`asset_timings` 이벤트로, 사람용 요약은 미출력) |
 | `kebab ingest-file <path>` | 단일 파일 ingest (workspace 외부 가능 — `_external/` 로 deterministic copy) |
 | `kebab ingest-stdin --title <T>` | stdin 의 markdown 본문 ingest |
 | `kebab search --mode {lexical,vector,hybrid} "<query>" [flags]` | 검색 (default hybrid = RRF fusion, citation 포함). 필터/budget flag 는 `--help` |

crates/kebab-app/src/ingest_progress.rs

@@ -96,14 +96,33 @@ pub enum IngestEvent {
     /// `idx/total` while its per-chunk phases churn. `chunks` is the chunk
     /// count for asset `idx`.
     AssetChunked { idx: u32, total: u32, chunks: u32 },
+    /// v0.26.1 (additive): emitted when an asset enters a *slow* internal
+    /// phase, so the interactive progress bar can show **which** phase
+    /// (and which model) is currently running instead of looking frozen.
+    /// `phase` ∈ {`"ocr"`, `"caption"`, `"embed"`}; short phases
+    /// (parse / chunk / store) are intentionally *not* emitted to avoid
+    /// noise. `model` is the model performing the phase — the vision LLM
+    /// id for `ocr` / `caption`, the embedder `model_id` for `embed`
+    /// (`None` when the phase runs without a configured model, e.g. embed
+    /// with no embedder wired). Emitted once per (asset, phase); no
+    /// throttle needed (low frequency). Wire v1 consumers that predate
+    /// this variant simply ignore the unknown `asset_phase` kind.
+    AssetPhase {
+        idx: u32,
+        total: u32,
+        phase: String,
+        model: Option<String>,
+    },
     /// v0.24.0 (additive): per-phase wall-clock (milliseconds) for asset
-    /// `idx`, emitted once the asset's markdown pipeline finishes. Lets a
-    /// user see *where* the time went (parse / chunk / embed / store)
-    /// without parsing logs. Only the markdown path emits this; the
-    /// image / PDF paths surface `AssetChunked` but skip phase timing (their
-    /// phase shapes differ — OCR / caption). `expansion_ms` is retained for
-    /// wire compatibility but is always 0 since doc-side expansion was
-    /// removed (HOTFIXES 2026-06-03).
+    /// `idx`, emitted once the asset's pipeline finishes. Lets a user see
+    /// *where* the time went (parse / chunk / ocr / caption / embed /
+    /// store) without parsing logs. The markdown path leaves `ocr_ms` /
+    /// `caption_ms` at 0 (no image analysis); the image / PDF paths fill
+    /// them so the slowest-asset summary attributes vision-model time
+    /// correctly. `expansion_ms` is retained for wire compatibility but is
+    /// always 0 since doc-side expansion was removed (HOTFIXES 2026-06-03).
+    /// `ocr_ms` / `caption_ms` (v0.26.1) are additive with serde default 0
+    /// so pre-v0.26.1 consumers deserialize cleanly.
     AssetTimings {
         idx: u32,
         total: u32,
@@ -112,6 +131,10 @@ pub enum IngestEvent {
         expansion_ms: u64,
         embed_ms: u64,
         store_ms: u64,
+        #[serde(default)]
+        ocr_ms: u64,
+        #[serde(default)]
+        caption_ms: u64,
     },
     /// Run finished normally. `counts` is the final aggregate.
     Completed { counts: AggregateCounts },
@@ -261,19 +284,23 @@ mod tests {
             expansion_ms: 45_000,
             embed_ms: 800,
             store_ms: 20,
+            ocr_ms: 1_200,
+            caption_ms: 3_400,
         };
         let v = serde_json::to_value(&ev).unwrap();
         assert_eq!(
             v.get("kind").and_then(|s| s.as_str()),
             Some("asset_timings")
         );
-        // All five phase fields are present (plain u64, always serialized).
+        // All phase fields are present (plain u64, always serialized).
         for (field, want) in [
             ("parse_ms", 12u64),
             ("chunk_ms", 3),
             ("expansion_ms", 45_000),
             ("embed_ms", 800),
             ("store_ms", 20),
+            ("ocr_ms", 1_200),
+            ("caption_ms", 3_400),
         ] {
             assert_eq!(
                 v.get(field).and_then(serde_json::Value::as_u64),
@@ -283,6 +310,64 @@ mod tests {
         }
     }
 
+    #[test]
+    fn asset_timings_ocr_caption_default_to_zero_for_legacy_wire() {
+        // v0.26.1 additive: a pre-v0.26.1 wire payload omits ocr_ms /
+        // caption_ms; serde `default` must fill 0 so old producers stay
+        // compatible.
+        let legacy = serde_json::json!({
+            "kind": "asset_timings",
+            "idx": 1, "total": 1,
+            "parse_ms": 5, "chunk_ms": 2, "expansion_ms": 0,
+            "embed_ms": 10, "store_ms": 3
+        });
+        let ev: IngestEvent = serde_json::from_value(legacy).unwrap();
+        match ev {
+            IngestEvent::AssetTimings {
+                ocr_ms,
+                caption_ms,
+                embed_ms,
+                ..
+            } => {
+                assert_eq!(ocr_ms, 0);
+                assert_eq!(caption_ms, 0);
+                assert_eq!(embed_ms, 10);
+            }
+            other => panic!("unexpected event: {other:?}"),
+        }
+    }
+
+    #[test]
+    fn asset_phase_serializes_with_discriminator() {
+        // v0.26.1 additive variant — `kind` must be snake_case
+        // `asset_phase`, `phase` is the slow-phase label, `model` the
+        // model id (nullable).
+        let ev = IngestEvent::AssetPhase {
+            idx: 4,
+            total: 12,
+            phase: "ocr".into(),
+            model: Some("gemma4:e4b".into()),
+        };
+        let v = serde_json::to_value(&ev).unwrap();
+        assert_eq!(v.get("kind").and_then(|s| s.as_str()), Some("asset_phase"));
+        assert_eq!(v.get("idx").and_then(serde_json::Value::as_u64), Some(4));
+        assert_eq!(v.get("phase").and_then(|s| s.as_str()), Some("ocr"));
+        assert_eq!(v.get("model").and_then(|s| s.as_str()), Some("gemma4:e4b"));
+    }
+
+    #[test]
+    fn asset_phase_model_none_serializes_as_null() {
+        let ev = IngestEvent::AssetPhase {
+            idx: 1,
+            total: 1,
+            phase: "embed".into(),
+            model: None,
+        };
+        let v = serde_json::to_value(&ev).unwrap();
+        assert_eq!(v.get("phase").and_then(|s| s.as_str()), Some("embed"));
+        assert!(v.get("model").is_some_and(serde_json::Value::is_null));
+    }
+
     #[test]
     fn ingest_event_completed_has_counts() {
         let ev = IngestEvent::Completed {

crates/kebab-app/src/lib.rs

@@ -1350,6 +1350,17 @@ fn ingest_one_asset(
     let store_ms = u64::try_from(t_store.elapsed().as_millis()).unwrap_or(u64::MAX);
 
     // Embed + vector upsert (only when both sides are configured).
+    // v0.26.1: surface the embed phase + model so a long embed run reads as
+    // "embedding(<model>)…" rather than a frozen bar (markdown path too).
+    crate::ingest_progress::emit(
+        progress,
+        crate::ingest_progress::IngestEvent::AssetPhase {
+            idx,
+            total,
+            phase: "embed".to_string(),
+            model: embedder.map(|e| e.model_id().0),
+        },
+    );
     let t_embed = std::time::Instant::now();
     // Stale-vector purge is LanceDB I/O, so it belongs to the embed/vector
     // phase — not the SQLite `store` phase. Keeping it here makes `store_ms`
@@ -1414,7 +1425,8 @@ fn ingest_one_asset(
 
     let embed_ms = u64::try_from(t_embed.elapsed().as_millis()).unwrap_or(u64::MAX);
 
-    // v0.24.0: phase-timing breakdown for this asset (markdown path only).
+    // v0.24.0: phase-timing breakdown for this asset (markdown path).
+    // ocr_ms / caption_ms are 0 — markdown has no image-analysis phases.
     crate::ingest_progress::emit(
         progress,
         crate::ingest_progress::IngestEvent::AssetTimings {
@@ -1425,6 +1437,8 @@ fn ingest_one_asset(
             expansion_ms,
             embed_ms,
             store_ms,
+            ocr_ms: 0,
+            caption_ms: 0,
         },
     );
 
@@ -1545,9 +1559,11 @@ fn ingest_one_image_asset(
         workspace_root: &workspace_root,
         config: &extract_config,
     };
+    let t_parse = std::time::Instant::now();
     let mut canonical = app
         .extract_for(&asset.media_type, &ctx, &bytes)
         .context("kb-app::extract_for (image)")?;
+    let parse_ms = u64::try_from(t_parse.elapsed().as_millis()).unwrap_or(u64::MAX);
 
     // 2 + 3. Apply OCR / caption when their adapters exist. Both are
     //        Lenient — failure is captured into Provenance Warning,
@@ -1562,44 +1578,74 @@ fn ingest_one_image_asset(
     let lang_hint = lang_hint_from_doc(&canonical);
     let now = time::OffsetDateTime::now_utc();
     let mut warning_notes: Vec<String> = Vec::new();
+    // v0.26.1: vision phases (OCR / caption) are the usual bottleneck on an
+    // image-heavy vault and emitted no progress before — so the bar looked
+    // frozen. Surface each as an `AssetPhase` and measure its wall-clock for
+    // the slowest-asset summary.
+    let mut ocr_ms = 0_u64;
+    let mut caption_ms = 0_u64;
     match canonical.blocks.first_mut() {
         Some(Block::ImageRef(block)) => {
-            if let Some(engine) = ocr_engine
-                && let Err(e) = apply_ocr(
+            if let Some(engine) = ocr_engine {
+                crate::ingest_progress::emit(
+                    progress,
+                    crate::ingest_progress::IngestEvent::AssetPhase {
+                        idx,
+                        total,
+                        phase: "ocr".to_string(),
+                        model: Some(engine.model().to_string()),
+                    },
+                );
+                let t_ocr = std::time::Instant::now();
+                let res = apply_ocr(
                     engine,
                     &bytes,
                     block,
                     lang_hint.as_ref(),
                     &mut canonical.provenance.events,
-                )
-            {
-                record_image_analysis_failure(
-                    asset,
-                    &mut canonical.provenance.events,
-                    &mut warning_notes,
-                    "OcrFailed",
-                    e,
-                    now,
                 );
+                ocr_ms = u64::try_from(t_ocr.elapsed().as_millis()).unwrap_or(u64::MAX);
+                if let Err(e) = res {
+                    record_image_analysis_failure(
+                        asset,
+                        &mut canonical.provenance.events,
+                        &mut warning_notes,
+                        "OcrFailed",
+                        e,
+                        now,
+                    );
+                }
             }
-            if let Some(llm) = caption_llm
-                && let Err(e) = apply_caption(
+            if let Some(llm) = caption_llm {
+                crate::ingest_progress::emit(
+                    progress,
+                    crate::ingest_progress::IngestEvent::AssetPhase {
+                        idx,
+                        total,
+                        phase: "caption".to_string(),
+                        model: Some(llm.model_ref().id),
+                    },
+                );
+                let t_caption = std::time::Instant::now();
+                let res = apply_caption(
                     llm,
                     &bytes,
                     block,
                     lang_hint.as_ref(),
                     &app.config,
                     &mut canonical.provenance.events,
-                )
-            {
-                record_image_analysis_failure(
-                    asset,
-                    &mut canonical.provenance.events,
-                    &mut warning_notes,
-                    "CaptionFailed",
-                    e,
-                    now,
                 );
+                caption_ms = u64::try_from(t_caption.elapsed().as_millis()).unwrap_or(u64::MAX);
+                if let Err(e) = res {
+                    record_image_analysis_failure(
+                        asset,
+                        &mut canonical.provenance.events,
+                        &mut warning_notes,
+                        "CaptionFailed",
+                        e,
+                        now,
+                    );
+                }
             }
         }
         // P6-1 contract: image documents always have exactly one
@@ -1634,12 +1680,13 @@ fn ingest_one_image_asset(
     //    `Block::ImageRef` arm already produces a single chunk per
     //    image (P1-5). The chunk text now follows the (β) plain-concat
     //    contract per the kebab-chunk render_block_text update.
+    let t_chunk = std::time::Instant::now();
     let chunks = MdHeadingV1Chunker
         .chunk(&canonical, chunk_policy)
         .context("kb-chunk::MdHeadingV1Chunker::chunk (image)")?;
+    let chunk_ms = u64::try_from(t_chunk.elapsed().as_millis()).unwrap_or(u64::MAX);
 
-    // v0.24.0: surface chunk count for the image path too (phase timing is
-    // markdown-only, but AssetChunked is consistent across media).
+    // v0.24.0: surface chunk count for the image path too.
     crate::ingest_progress::emit(
         progress,
         crate::ingest_progress::IngestEvent::AssetChunked {
@@ -1656,6 +1703,7 @@ fn ingest_one_image_asset(
     if let Some(emb) = embedder {
         canonical.last_embedding_version = Some(emb.model_version());
     }
+    let t_store = std::time::Instant::now();
     purge_vector_orphans_for_workspace_path(app, asset, vector_store)?;
     app.sqlite
         .put_asset_with_bytes(asset, &bytes)
@@ -1669,7 +1717,18 @@ fn ingest_one_image_asset(
     app.sqlite
         .put_chunks(&canonical.doc_id, &chunks)
         .context("DocumentStore::put_chunks (image)")?;
+    let store_ms = u64::try_from(t_store.elapsed().as_millis()).unwrap_or(u64::MAX);
 
+    crate::ingest_progress::emit(
+        progress,
+        crate::ingest_progress::IngestEvent::AssetPhase {
+            idx,
+            total,
+            phase: "embed".to_string(),
+            model: embedder.map(|e| e.model_id().0),
+        },
+    );
+    let t_embed = std::time::Instant::now();
     if let (Some(emb), Some(vec_store)) = (embedder, vector_store)
         && !chunks.is_empty()
     {
@@ -1710,6 +1769,25 @@ fn ingest_one_image_asset(
             .upsert(&records)
             .context("VectorStore::upsert (image)")?;
     }
+    let embed_ms = u64::try_from(t_embed.elapsed().as_millis()).unwrap_or(u64::MAX);
+
+    // v0.26.1: per-phase timing for the image path — ocr_ms / caption_ms
+    // carry the vision-model cost so the slowest-asset summary attributes
+    // an image-heavy run's bottleneck correctly.
+    crate::ingest_progress::emit(
+        progress,
+        crate::ingest_progress::IngestEvent::AssetTimings {
+            idx,
+            total,
+            parse_ms,
+            chunk_ms,
+            expansion_ms: 0,
+            embed_ms,
+            store_ms,
+            ocr_ms,
+            caption_ms,
+        },
+    );
 
     let kind = if existing_doc_ids.contains(&canonical.doc_id.0) {
         kebab_core::IngestItemKind::Updated
@@ -2053,9 +2131,11 @@ fn ingest_one_pdf_asset(
         workspace_root: &workspace_root,
         config: &extract_config,
     };
+    let t_parse = std::time::Instant::now();
     let mut canonical = app
         .extract_for(&asset.media_type, &ctx, &bytes)
         .context("kb-app::extract_for (pdf)")?;
+    let parse_ms = u64::try_from(t_parse.elapsed().as_millis()).unwrap_or(u64::MAX);
 
     // v0.20 sub-item 1: post-extract OCR enrichment (PR #187 registry
     // dispatch invariant 보존 — extract_for 가 normal entry).
@@ -2191,9 +2271,11 @@ fn ingest_one_pdf_asset(
     // validates every block carries `SourceSpan::Page`; failure here
     // means the parser drifted from its contract.
     let chunker = PdfPageV1Chunker;
+    let t_chunk = std::time::Instant::now();
     let chunks = chunker
         .chunk(&canonical, chunk_policy)
         .context("kb-chunk::PdfPageV1Chunker::chunk")?;
+    let chunk_ms = u64::try_from(t_chunk.elapsed().as_millis()).unwrap_or(u64::MAX);
 
     // v0.24.0: surface chunk count for the PDF path too.
     crate::ingest_progress::emit(
@@ -2212,6 +2294,7 @@ fn ingest_one_pdf_asset(
         canonical.last_embedding_version = Some(emb.model_version());
     }
 
+    let t_store = std::time::Instant::now();
     purge_vector_orphans_for_workspace_path(app, asset, vector_store)?;
     app.sqlite
         .put_asset_with_bytes(asset, &bytes)
@@ -2225,7 +2308,18 @@ fn ingest_one_pdf_asset(
     app.sqlite
         .put_chunks(&canonical.doc_id, &chunks)
         .context("DocumentStore::put_chunks (pdf)")?;
+    let store_ms = u64::try_from(t_store.elapsed().as_millis()).unwrap_or(u64::MAX);
 
+    crate::ingest_progress::emit(
+        progress,
+        crate::ingest_progress::IngestEvent::AssetPhase {
+            idx,
+            total,
+            phase: "embed".to_string(),
+            model: embedder.map(|e| e.model_id().0),
+        },
+    );
+    let t_embed = std::time::Instant::now();
     if let (Some(emb), Some(vec_store)) = (embedder, vector_store)
         && !chunks.is_empty()
     {
@@ -2264,6 +2358,25 @@ fn ingest_one_pdf_asset(
             .upsert(&records)
             .context("VectorStore::upsert (pdf)")?;
     }
+    let embed_ms = u64::try_from(t_embed.elapsed().as_millis()).unwrap_or(u64::MAX);
+
+    // v0.26.1: per-phase timing for the PDF path. `ocr_ms` reuses the
+    // page-OCR total already computed above so a scanned-PDF run's OCR cost
+    // shows up in the slowest-asset summary; caption is markdown/image-only.
+    crate::ingest_progress::emit(
+        progress,
+        crate::ingest_progress::IngestEvent::AssetTimings {
+            idx,
+            total,
+            parse_ms,
+            chunk_ms,
+            expansion_ms: 0,
+            embed_ms,
+            store_ms,
+            ocr_ms: pdf_ocr_ms_total.unwrap_or(0),
+            caption_ms: 0,
+        },
+    );
 
     let kind = if existing_doc_ids.contains(&canonical.doc_id.0) {
         kebab_core::IngestItemKind::Updated

crates/kebab-cli/src/progress.rs

@@ -19,16 +19,23 @@
 //! `Sender` end is dropped (i.e. when `ingest_with_config_progress`
 //! returns).
 
+use std::collections::HashMap;
 use std::io::{IsTerminal, Write};
 use std::sync::mpsc::Receiver;
+use std::sync::{Arc, Mutex};
+use std::time::Instant;
 
-use indicatif::{ProgressBar, ProgressDrawTarget, ProgressStyle};
+use indicatif::{ProgressBar, ProgressDrawTarget, ProgressState, ProgressStyle};
 use kebab_app::IngestEvent;
 use time::OffsetDateTime;
 use time::format_description::well_known::Rfc3339;
 
 use crate::wire;
 
+/// v0.26.1: number of slowest assets surfaced in the end-of-run summary.
+/// Constant for now (spec defers the config knob).
+const SLOWEST_TOP_N: usize = 5;
+
 /// Rendering mode for `ProgressDisplay`. The mode is fixed at
 /// construction — each `kebab ingest` invocation is a single mode
 /// (chosen from `--json` plus `IsTerminal` detection).
@@ -65,11 +72,33 @@ impl ProgressMode {
 pub struct ProgressDisplay {
     mode: ProgressMode,
     bar: Option<ProgressBar>,
+    /// v0.26.1 heartbeat: start `Instant` of the asset currently in
+    /// flight, shared with the bar's steady-tick custom template key so
+    /// the `(Ns)` elapsed counter advances *between* events (the drain
+    /// loop blocks on `recv()`, so without the ticker the counter would
+    /// freeze). `None` while scanning / between assets / after completion.
+    asset_start: Arc<Mutex<Option<Instant>>>,
+    /// v0.26.1: workspace path of the asset currently in flight — set on
+    /// `AssetStarted`, reused by `AssetPhase` to render `{path} · {phase}…`.
+    current_path: Option<String>,
+    /// v0.26.1 slowest summary: idx → path, captured from `AssetStarted`
+    /// so `AssetTimings` (which only carries `idx`) can name the asset.
+    asset_paths: HashMap<u32, String>,
+    /// v0.26.1 slowest summary: (path, total_ms) per asset that reported
+    /// `AssetTimings`. Sorted + truncated to top-N on `Completed`.
+    timings: Vec<(String, u64)>,
 }
 
 impl ProgressDisplay {
     pub fn new(mode: ProgressMode) -> Self {
-        Self { mode, bar: None }
+        Self {
+            mode,
+            bar: None,
+            asset_start: Arc::new(Mutex::new(None)),
+            current_path: None,
+            asset_paths: HashMap::new(),
+            timings: Vec::new(),
+        }
     }
 
     /// Block until `rx` returns `Err` (sender dropped). Renders one
@@ -120,15 +149,43 @@ impl ProgressDisplay {
             }
             IngestEvent::ScanCompleted { total } => {
                 if let Some(bar) = self.bar.as_mut() {
-                    bar.disable_steady_tick();
                     bar.set_length(u64::from(*total));
                     bar.set_position(0);
+                    // v0.26.1: a custom `{asset_elapsed}` key reads the shared
+                    // per-asset start `Instant` and appends ` (Ns)`. Combined
+                    // with the steady tick below, the elapsed counter advances
+                    // even while the drain loop is blocked on `recv()` waiting
+                    // for the next (possibly very slow) phase event.
+                    let asset_start = Arc::clone(&self.asset_start);
                     bar.set_style(
-                        ProgressStyle::with_template("ingest [{bar:30}] {pos}/{len} {wide_msg}")
-                            .unwrap()
-                            .progress_chars("=> "),
+                        ProgressStyle::with_template(
+                            "ingest [{bar:30}] {pos}/{len} {wide_msg}{asset_elapsed}",
+                        )
+                        .unwrap()
+                        .with_key(
+                            "asset_elapsed",
+                            move |_: &ProgressState, w: &mut dyn std::fmt::Write| {
+                                if let Ok(guard) = asset_start.lock()
+                                    && let Some(started) = *guard
+                                {
+                                    let secs = started.elapsed().as_secs();
+                                    // Only show once the asset has been running
+                                    // a moment — avoids `(0s)` flicker on fast
+                                    // assets.
+                                    if secs >= 1 {
+                                        let _ = write!(w, " ({secs}s)");
+                                    }
+                                }
+                            },
+                        )
+                        .progress_chars("=> "),
                     );
                     bar.set_message("");
+                    if tty && !quiet {
+                        bar.enable_steady_tick(std::time::Duration::from_secs(1));
+                    } else {
+                        bar.disable_steady_tick();
+                    }
                 }
                 if !tty && !quiet {
                     let mut err = std::io::stderr().lock();
@@ -141,11 +198,22 @@ impl ProgressDisplay {
                 path,
                 media,
             } => {
+                // v0.26.1: remember the path so AssetPhase can render it and
+                // the slowest summary (keyed by idx in AssetTimings) can name
+                // the asset.
+                self.current_path = Some(path.clone());
+                self.asset_paths.insert(*idx, path.clone());
+                // v0.26.1: (re)start the per-asset heartbeat clock.
+                if let Ok(mut guard) = self.asset_start.lock() {
+                    *guard = Some(Instant::now());
+                }
                 if let Some(bar) = self.bar.as_ref() {
-                    // One draw per file: position only. set_message() would
-                    // trigger a second independent draw and pollute TTY scrollback.
-                    // Filename is visible in the non-TTY plain-line path below.
                     bar.set_position(u64::from(idx.saturating_sub(1)));
+                    // v0.26.1: show the current filename on the bar (TTY).
+                    // Previously position-only — the interactive user couldn't
+                    // tell which file was in flight. The steady tick redraws
+                    // in place, so this no longer pollutes scrollback.
+                    bar.set_message(abbreviate_path(path));
                 }
                 if !tty && !quiet {
                     let mut err = std::io::stderr().lock();
@@ -154,8 +222,35 @@ impl ProgressDisplay {
             }
             IngestEvent::AssetFinished { .. } => {
                 // Position is advanced in AssetStarted; bar.finish_and_clear()
-                // in Completed handles the final state. No per-asset bar update
-                // here avoids the duplicate-frame artifact in TTY scrollback.
+                // in Completed handles the final state. v0.26.1: stop the
+                // heartbeat clock so the bar doesn't show a stale `(Ns)` in the
+                // gap before the next AssetStarted.
+                if let Ok(mut guard) = self.asset_start.lock() {
+                    *guard = None;
+                }
+                self.current_path = None;
+            }
+            // v0.26.1: an asset entered a slow internal phase (ocr / caption /
+            // embed). Surface which phase + model is running so a multi-second
+            // vision-model call no longer looks frozen.
+            IngestEvent::AssetPhase {
+                idx,
+                total,
+                phase,
+                model,
+            } => {
+                let label = match model {
+                    Some(m) => format!("{phase}({m})"),
+                    None => phase.clone(),
+                };
+                if let Some(bar) = self.bar.as_ref() {
+                    let path = self.current_path.as_deref().unwrap_or("");
+                    bar.set_message(format!("{} · {label}…", abbreviate_path(path)));
+                }
+                if !tty && !quiet {
+                    let mut err = std::io::stderr().lock();
+                    let _ = writeln!(err, "ingest: {idx}/{total} · {label}…");
+                }
             }
             // v0.24.0: asset-internal phase visibility. AssetChunked uses the
             // bar *message* (live sub-progress for the current asset) —
@@ -172,31 +267,50 @@ impl ProgressDisplay {
                 }
             }
             IngestEvent::AssetTimings {
+                idx,
                 parse_ms,
                 chunk_ms,
                 embed_ms,
                 store_ms,
+                ocr_ms,
+                caption_ms,
                 ..
             } => {
+                // v0.26.1: accumulate (path, total_ms) for the slowest summary.
+                // total = every measured phase (expansion_ms is always 0).
+                let total_ms = parse_ms + chunk_ms + embed_ms + store_ms + ocr_ms + caption_ms;
+                if let Some(path) = self.asset_paths.get(idx) {
+                    self.timings.push((path.clone(), total_ms));
+                }
                 if let Some(bar) = self.bar.as_ref() {
                     bar.set_message("");
                 }
                 if !quiet {
                     let mut err = std::io::stderr().lock();
-                    let _ = writeln!(
-                        err,
-                        "  ⏱ parse {} · chunk {} · embed {} · store {}",
-                        fmt_ms(*parse_ms),
-                        fmt_ms(*chunk_ms),
-                        fmt_ms(*embed_ms),
-                        fmt_ms(*store_ms),
-                    );
+                    // v0.26.1: only print ocr / caption when they actually ran
+                    // (markdown leaves them 0) so the text path stays uncluttered.
+                    let mut parts = vec![
+                        format!("parse {}", fmt_ms(*parse_ms)),
+                        format!("chunk {}", fmt_ms(*chunk_ms)),
+                    ];
+                    if *ocr_ms > 0 {
+                        parts.push(format!("ocr {}", fmt_ms(*ocr_ms)));
+                    }
+                    if *caption_ms > 0 {
+                        parts.push(format!("caption {}", fmt_ms(*caption_ms)));
+                    }
+                    parts.push(format!("embed {}", fmt_ms(*embed_ms)));
+                    parts.push(format!("store {}", fmt_ms(*store_ms)));
+                    let _ = writeln!(err, "  ⏱ {}", parts.join(" · "));
                 }
             }
             IngestEvent::Completed { counts } => {
                 if let Some(bar) = self.bar.take() {
                     bar.finish_and_clear();
                 }
+                if let Ok(mut guard) = self.asset_start.lock() {
+                    *guard = None;
+                }
                 // Always emit summary in both TTY and non-TTY (unless quiet).
                 // Bug fix: previously TTY had no summary line after bar.finish_and_clear().
                 if !quiet {
@@ -206,6 +320,10 @@ impl ProgressDisplay {
                         "ingest: complete (scanned={} new={} updated={} skipped={} errors={})",
                         counts.scanned, counts.new, counts.updated, counts.skipped, counts.errors,
                     );
+                    // v0.26.1: slowest-asset summary. Useful in both TTY and
+                    // non-TTY (it pinpoints the bottleneck file), so it prints
+                    // unless --quiet. --json mode never reaches here (emit_json).
+                    let _ = write_slowest_summary(&mut err, &self.timings, SLOWEST_TOP_N);
                 }
             }
             IngestEvent::Aborted { counts } => {
@@ -286,6 +404,48 @@ fn fmt_ms(ms: u64) -> String {
     }
 }
 
+/// v0.26.1: shorten an over-long workspace path for the progress-bar
+/// message so the live `(Ns)` heartbeat suffix stays visible on a narrow
+/// terminal. Keeps the tail (filename + a couple of parents) — that's the
+/// distinguishing part — and prefixes `…` when truncated. Paths up to the
+/// budget pass through verbatim.
+fn abbreviate_path(path: &str) -> String {
+    const MAX: usize = 48;
+    let char_count = path.chars().count();
+    if char_count <= MAX {
+        return path.to_string();
+    }
+    // Keep the last MAX-1 chars (1 reserved for the leading ellipsis).
+    let tail: String = path
+        .chars()
+        .skip(char_count - (MAX - 1))
+        .collect::<String>();
+    format!("…{tail}")
+}
+
+/// v0.26.1: render the end-of-run "slowest assets" summary. Sorts
+/// `(path, total_ms)` descending by time, takes the top `n`, and writes a
+/// compact table to `w`. No-op (writes nothing) when `timings` is empty so
+/// a run with no per-asset timing (e.g. all-skipped) prints no stray header.
+fn write_slowest_summary(
+    w: &mut impl Write,
+    timings: &[(String, u64)],
+    n: usize,
+) -> std::io::Result<()> {
+    if timings.is_empty() {
+        return Ok(());
+    }
+    let mut sorted: Vec<&(String, u64)> = timings.iter().collect();
+    // desc by ms; ties broken by path for deterministic output.
+    sorted.sort_by(|a, b| b.1.cmp(&a.1).then_with(|| a.0.cmp(&b.0)));
+    let top = &sorted[..sorted.len().min(n)];
+    writeln!(w, "⏱ 최장 소요 top-{}:", top.len())?;
+    for (rank, (path, ms)) in top.iter().enumerate() {
+        writeln!(w, "  {}. {} — {}", rank + 1, path, fmt_ms(*ms))?;
+    }
+    Ok(())
+}
+
 /// Format the current wall-clock as RFC 3339 — used by `wire_ingest_progress`
 /// so every emitted event carries an `ts` field per §2.4a / the wire schema.
 pub(crate) fn now_rfc3339() -> anyhow::Result<String> {
@@ -348,4 +508,61 @@ mod tests {
         // well-formed RFC 3339 string.
         OffsetDateTime::parse(&s, &Rfc3339).expect("RFC 3339 round-trip");
     }
+
+    #[test]
+    fn abbreviate_path_passes_short_paths_through() {
+        assert_eq!(abbreviate_path("notes/foo.md"), "notes/foo.md");
+    }
+
+    #[test]
+    fn abbreviate_path_keeps_tail_with_ellipsis() {
+        let long = "a/very/deeply/nested/directory/structure/that/exceeds/the/budget/file.md";
+        let out = abbreviate_path(long);
+        assert!(out.starts_with('…'), "should be prefixed with ellipsis: {out}");
+        assert!(out.ends_with("file.md"), "should keep the filename tail: {out}");
+        // 48-char budget: 1 ellipsis + 47 tail chars.
+        assert_eq!(out.chars().count(), 48);
+    }
+
+    #[test]
+    fn write_slowest_summary_empty_writes_nothing() {
+        let mut buf = Vec::new();
+        write_slowest_summary(&mut buf, &[], 5).unwrap();
+        assert!(buf.is_empty());
+    }
+
+    #[test]
+    fn write_slowest_summary_sorts_desc_and_truncates() {
+        let timings = vec![
+            ("a.md".to_string(), 100),
+            ("b.png".to_string(), 5_000),
+            ("c.pdf".to_string(), 2_000),
+            ("d.md".to_string(), 50),
+        ];
+        let mut buf = Vec::new();
+        write_slowest_summary(&mut buf, &timings, 2).unwrap();
+        let out = String::from_utf8(buf).unwrap();
+        assert!(out.contains("top-2:"), "{out}");
+        // b (5s) ranks first, c (2s) second; a/d excluded.
+        let b_pos = out.find("b.png").expect("b.png present");
+        let c_pos = out.find("c.pdf").expect("c.pdf present");
+        assert!(b_pos < c_pos, "b before c: {out}");
+        assert!(!out.contains("a.md"), "a.md excluded by top-2: {out}");
+        assert!(out.contains("5.0s"), "b renders as 5.0s: {out}");
+    }
+
+    #[test]
+    fn write_slowest_summary_tie_breaks_by_path() {
+        let timings = vec![
+            ("z.md".to_string(), 1_000),
+            ("a.md".to_string(), 1_000),
+        ];
+        let mut buf = Vec::new();
+        write_slowest_summary(&mut buf, &timings, 5).unwrap();
+        let out = String::from_utf8(buf).unwrap();
+        assert!(
+            out.find("a.md").unwrap() < out.find("z.md").unwrap(),
+            "equal ms ties break alphabetically: {out}"
+        );
+    }
 }

crates/kebab-parse-image/src/ocr.rs

@@ -209,6 +209,13 @@ impl OllamaVisionOcr {
         self.max_pixels
     }
 
+    /// The Ollama model id this engine drives (e.g. `gemma4:e4b`).
+    /// Surfaced so the ingest progress display can name the model
+    /// running a slow OCR phase (`AssetPhase{phase:"ocr", model}`).
+    pub fn model(&self) -> &str {
+        &self.model
+    }
+
     fn build_prompt(&self, lang_hint: Option<&Lang>) -> String {
         let langs = if self.languages.is_empty() {
             "any".to_string()

crates/kebab-tui/src/ingest_progress.rs

@@ -160,7 +160,11 @@ fn apply_event(state: &mut IngestState, event: IngestEvent) {
         // per-asset counters, not sub-asset phase progress, so these are
         // no-ops here (the CLI / --json surfaces render them).
         | IngestEvent::AssetChunked { .. }
-        | IngestEvent::AssetTimings { .. } => {}
+        | IngestEvent::AssetTimings { .. }
+        // v0.26.1 slow-phase hint (ocr / caption / embed): the CLI bar uses
+        // it for a live phase message; the TUI status-bar reducer tracks only
+        // per-asset counters, so it's a no-op here.
+        | IngestEvent::AssetPhase { .. } => {}
     }
 }
 

docs/superpowers/plans/2026-06-03-ingest-log-improve-plan.md

@@ -0,0 +1,33 @@
+# Plan: ingest 로그 개선 구현
+
+spec: `docs/superpowers/specs/2026-06-03-ingest-log-improve-spec.md`. 브랜치 `feat/ingest-log-improve`. 빌드 `CARGO_TARGET_DIR=/build/out/cargo-target -j 4`(전체 test `-j 1`). cli 통합테스트용 `target` 심링크 후 정리.
+
+## Task 1 — wire 이벤트 (kebab-app/src/ingest_progress.rs)
+- `IngestEvent` 에 `AssetPhase { idx: u32, total: u32, phase: String, model: Option<String> }` variant 추가(serde tag 규약 기존과 동일, snake `asset_phase`).
+- `AssetTimings` 에 `ocr_ms: u64`, `caption_ms: u64` 필드 추가(기존 필드 뒤, serde default 0 → 구 소비자 호환).
+- 직렬화 테스트 추가(asset_phase, 확장 timings).
+
+## Task 2 — emit 지점 (kebab-app/src/lib.rs)
+- 이미지 경로: `apply_ocr` 직전 `AssetPhase{phase:"ocr", model: <ocr model>}`, `apply_caption` 직전 `AssetPhase{phase:"caption", model: <llm model>}` emit. 각 호출 시간 측정 → `ocr_ms`/`caption_ms`.
+- 임베딩 루프 진입 직전 `AssetPhase{phase:"embed", model: embedder.model_id}` emit(텍스트 포함 전 asset).
+- `AssetTimings` 생성부에 ocr_ms/caption_ms 전달.
+- 짧은 phase(parse/chunk/store)는 emit 안 함.
+
+## Task 3 — CLI 렌더 (kebab-cli/src/progress.rs)
+- **파일명**: AssetStarted TTY 핸들러 `bar.set_message(<path>)` (현재 위치-only 주석/로직 교체; path 길면 말미 축약). 비-TTY 줄 유지.
+- **phase+모델**: AssetPhase 수신 → `bar.set_message(format!("{path} · {phase}({model})…"))`. 현재 path 를 핸들러 상태로 보관(AssetStarted 에서 저장).
+- **heartbeat**: AssetStarted 에서 `Instant::now()` 보관 + `bar.enable_steady_tick(1s)` + 메시지 렌더에 경과초 `(Ns)`. AssetFinished/다음 AssetStarted 에서 리셋. (indicatif steady-tick + 커스텀 메시지.)
+- **slowest 요약**: 핸들러에 `Vec<(path, total_ms)>` 누적 — AssetStarted 로 idx→path, AssetTimings 로 idx→sum(parse+chunk+embed+store+ocr+caption). `Completed` 수신 시 상위 5개 stderr 표 출력(`⏱ 최장 소요:`). `--json` 모드 미출력, quiet 여도 요약은 출력.
+- `fmt_ms`(기존) 재사용.
+
+## Task 4 — wire schema + 문서
+- `docs/wire-schema/v1/ingest_progress.schema.json`: `asset_phase` kind(phase enum, model) + `ocr_ms`/`caption_ms` 필드 추가(additive). verbatim 일치.
+- README(있으면 진행 표시 한 줄), HANDOFF 1줄, tasks/HOTFIXES dated entry, Cargo.toml version minor bump(+Cargo.lock).
+
+## Task 5 — 검증
+- clippy 0, 전체 test 통과(기존 progress 테스트 갱신).
+- 스모크: 이미지/PDF 포함 임시 폴더 ingest → TTY 파일명+phase+모델+경과, 종료 top-N. 비-TTY 줄+요약. `--json` ndjson(asset_phase/ocr_ms) 확인, 사람텍스트 미혼입.
+- 결과 요약 `/tmp/ingestlog-result.md`(게이트 + 스모크 캡처).
+
+## 리뷰 루프
+완료 → 리더 clippy/test 독립 재확인 → `gitea-pr`(title `feat(ingest): 진행 로그 개선 — 파일명/phase/heartbeat/slowest 요약`) → 리뷰 루프 → 사용자 머지. 머지 후 Obsidian 볼트 도그푸딩.

docs/superpowers/specs/2026-06-03-ingest-log-improve-spec.md

@@ -0,0 +1,60 @@
+# Spec: ingest 로그 개선 (파일명·phase·heartbeat·slowest 요약)
+
+**날짜**: 2026-06-03
+**유형**: feature (관측성/UX, additive wire)
+**근거**: arctic 도그푸딩 중 Obsidian 볼트(이미지/PDF 혼재 + OCR/caption on)에서 ingest 가 중간부터 느려졌는데, **TTY 진행바가 파일명·현재 phase·모델·경과시간을 안 보여줘** "멈춘 것처럼" 보였다. 원인(비전 모델 스와핑)을 로그만으로 파악 불가. v0.24.0 상세 진행 로깅의 후속 — 느린 phase(특히 이미지 OCR/caption)와 병목 파일을 가시화한다.
+
+## 현재 한계 (코드 근거)
+- `kebab-cli/src/progress.rs:145` — TTY 에서 AssetStarted 는 **위치만 갱신, 파일명 메시지 미설정**(의도적; 비-TTY 줄에만 파일명). → 인터랙티브 실행 시 현재 파일 안 보임.
+- 이미지 **OCR/caption 진행 이벤트 없음** — `PdfOcrStarted/Finished`(PDF 페이지)만 존재. 이미지 OCR/caption(gemma 비전, 느림)은 무이벤트 → 진행바 정지처럼 보임(`lib.rs` apply_ocr/apply_caption 호출 주변).
+- 한 asset 이 오래 걸려도 **경과시간 heartbeat 없음**(완료 후 `AssetTimings` ⏱ 한 번).
+- 병목 파일을 **사후 파악할 요약 없음**.
+
+## 목표 (사용자 결정: 1+2+3+4)
+1. **파일명**을 TTY 진행바 메시지에 표시.
+2. 느린 **phase(OCR/caption/embed) + 모델명** 실시간 표시.
+3. 현재 asset **경과시간 heartbeat**.
+4. 종료 시 **가장 오래 걸린 파일 top-N 요약**.
+
+## 작업
+
+### A. wire 이벤트 (additive, ingest_progress.v1)
+- **신규 `AssetPhase { idx, total, phase, model }`** — asset 이 느린 phase 진입 시 emit. `phase: &str` ∈ {`"ocr"`,`"caption"`,`"embed"`}; `model: Option<String>`(그 phase 를 수행하는 모델 — OCR/caption=비전 LLM 모델 id, embed=임베더 model_id). 짧은 phase(parse/chunk/store)는 emit 안 함(노이즈 방지).
+- **`AssetTimings` 확장**: `ocr_ms`, `caption_ms` 필드 추가(additive, 기본 0). 기존 parse/chunk/embed/store/expansion_ms 유지. → top-N 요약의 정확한 per-asset 총시간 계산 근거.
+- `PdfOcrStarted/Finished`(기존) 유지 — PDF 페이지 단위 진행은 이미 있음.
+- wire schema `docs/wire-schema/v1/ingest_progress.schema.json`: `asset_phase` kind + `phase`/`model` + `ocr_ms`/`caption_ms` 필드 문서화(additive, v1 유지).
+
+### B. emit 지점 (kebab-app)
+- `ingest_one_asset` / 이미지·미디어 경로(`apply_ocr`/`apply_caption` 호출 직전, `lib.rs:~1568/1586`): 각각 `AssetPhase{phase:"ocr"|"caption", model}` emit. 임베딩 루프 진입 시 `AssetPhase{phase:"embed", model:embedder.model_id}` emit(텍스트 asset 도 적용).
+- OCR/caption 소요를 측정해 `AssetTimings.ocr_ms`/`caption_ms` 채움.
+
+### C. CLI 렌더 (kebab-cli/src/progress.rs)
+1. **파일명**: AssetStarted TTY 핸들러에서 `bar.set_message(<path 축약>)`(현재 위치-only 주석 제거). 비-TTY 줄은 그대로.
+2. **phase+모델**: AssetPhase 수신 시 `bar.set_message("{path} · {phase}({model})…")`.
+3. **heartbeat**: AssetStarted 에서 현재 asset 시작 시각 기록 + steady-tick(예: 1s)으로 메시지 끝에 `(Ns)` 경과 갱신. asset 전환/완료 시 리셋.
+4. **slowest 요약**: AssetStarted(idx→path) + AssetTimings(idx→총ms=parse+chunk+embed+store+ocr+caption) 를 누적, `Completed` 수신 시 stderr 에 `⏱ 최장 소요 top-N`(기본 N=5) 표 출력. 비-TTY/quiet 에서도 요약은 출력(유용), `--json` 모드는 미출력(ndjson 오염 방지).
+
+### 결정 사항
+- 모두 **additive wire** → `ingest_progress.v1` 유지(major bump 없음). 신규 소비자는 `asset_phase` 부재 허용.
+- AssetPhase 는 **emit 스로틀 불필요**(asset·phase 당 1회, 빈도 낮음). PDF 페이지 OCR 은 기존 PdfOcrStarted 가 담당(페이지 많으면 그쪽 스로틀은 별도 — 본 spec 비범위).
+- top-N 의 N: 상수 5(후속에 config 화 가능, 본 spec 비범위).
+- `--quiet` 시 진행바·phase 메시지는 억제하되 **slowest 요약은 출력**(짧고 유용). `--json` 은 전부 ndjson 으로만.
+
+## 검증 기준
+- clippy 0 / 전체 test 통과(기존 진행 렌더 테스트 갱신 + 신규 이벤트 직렬화 테스트).
+- TTY 스모크: 이미지/PDF 포함 폴더 ingest 시 진행바에 **파일명 + OCR/caption/embed phase + 모델 + 경과초** 표시, 종료 시 **top-N 요약**.
+- 비-TTY: 기존 줄 로그 유지 + 종료 요약.
+- `--json`: `asset_phase`/확장 `asset_timings` ndjson 출력, 사람용 텍스트 미혼입.
+- wire schema 문서 동기화 + verbatim 일치(CI diff-check 있으면).
+
+## 도그푸딩 (별도)
+사용자 Obsidian 볼트(이미지/PDF + OCR on)로 재현 — 느린 구간에서 어떤 파일·phase·모델인지 즉시 보이는지, 종료 요약이 병목 파일을 짚는지 확인. HOTFIXES + release notes.
+
+## 문서 동기화 (같은 PR)
+- `docs/wire-schema/v1/ingest_progress.schema.json` (asset_phase, ocr_ms/caption_ms).
+- README(진행 표시 설명 있으면 갱신, 명령표 영향 없음), HANDOFF 1줄, tasks/HOTFIXES dated entry, Cargo.toml version minor bump.
+
+## 비범위
+- PDF 페이지 OCR 진행 스로틀/요약(기존 이벤트 유지).
+- 모델 스와핑 자체 해결(그건 Ollama 설정/OCR off — 본 작업은 가시화만).
+- top-N 의 config 화.

docs/wire-schema/v1/ingest_progress.schema.json

@@ -15,6 +15,7 @@
         "asset_started",
         "asset_finished",
         "asset_chunked",
+        "asset_phase",
         "asset_timings",
         "embed_batch_started",
         "embed_batch_finished",
@@ -36,11 +37,15 @@
       "description": "asset_finished: per-asset outcome (mirrors `ingest_report.v1.items[].kind`)."
     },
     "chunks":       { "type": "integer", "minimum": 0, "description": "asset_finished / asset_chunked (v0.24.0): chunk count produced for this asset." },
-    "parse_ms":     { "type": "integer", "minimum": 0, "description": "asset_timings (v0.24.0, additive): parse phase wall-clock (ms). Markdown path only." },
-    "chunk_ms":     { "type": "integer", "minimum": 0, "description": "asset_timings (v0.24.0, additive): chunk phase wall-clock (ms). Markdown path only." },
+    "phase":        { "type": "string", "enum": ["ocr", "caption", "embed"], "description": "asset_phase (v0.26.1): the slow internal phase the asset just entered. Short phases (parse/chunk/store) are not emitted." },
+    "model":        { "type": ["string", "null"], "description": "asset_phase (v0.26.1): model performing the phase — vision LLM id for ocr/caption, embedder model_id for embed. null when the phase runs without a configured model." },
+    "parse_ms":     { "type": "integer", "minimum": 0, "description": "asset_timings (v0.24.0, additive): parse phase wall-clock (ms). Emitted by markdown / image / PDF paths." },
+    "chunk_ms":     { "type": "integer", "minimum": 0, "description": "asset_timings (v0.24.0, additive): chunk phase wall-clock (ms). Emitted by markdown / image / PDF paths." },
     "expansion_ms": { "type": "integer", "minimum": 0, "description": "asset_timings (v0.24.0, additive): retained for wire compatibility but always 0 — doc-side expansion was removed (HOTFIXES 2026-06-03)." },
-    "embed_ms":     { "type": "integer", "minimum": 0, "description": "asset_timings (v0.24.0, additive): embed + vector phase wall-clock (ms) — embedding, vector upsert, and stale-vector purge. Markdown path only." },
-    "store_ms":     { "type": "integer", "minimum": 0, "description": "asset_timings (v0.24.0, additive): SQLite persist phase wall-clock (ms) — put_asset/document/blocks/chunks only. Markdown path only." },
+    "embed_ms":     { "type": "integer", "minimum": 0, "description": "asset_timings (v0.24.0, additive): embed + vector phase wall-clock (ms) — embedding, vector upsert, and stale-vector purge." },
+    "store_ms":     { "type": "integer", "minimum": 0, "description": "asset_timings (v0.24.0, additive): SQLite persist phase wall-clock (ms) — put_asset/document/blocks/chunks only." },
+    "ocr_ms":       { "type": "integer", "minimum": 0, "description": "asset_timings (v0.26.1, additive, default 0): image/PDF OCR phase wall-clock (ms). 0 on the markdown path (no OCR)." },
+    "caption_ms":   { "type": "integer", "minimum": 0, "description": "asset_timings (v0.26.1, additive, default 0): image caption phase wall-clock (ms). 0 on markdown / PDF paths." },
     "n_chunks":     { "type": "integer", "minimum": 0, "description": "embed_batch_started / embed_batch_finished: chunks in this embedding batch." },
     "ms":           { "type": "integer", "minimum": 0, "description": "embed_batch_finished / pdf_ocr_finished: wall-clock duration (ms). pdf_ocr_finished skip path 의 의미는 mixed (DCTDecode 부재 시 0, engine 실패 시 latency-before-bail)." },
     "chars":        { "type": "integer", "minimum": 0, "description": "pdf_ocr_finished: char count of OCR result. Skip 시 0." },

tasks/HOTFIXES.md

@@ -14,6 +14,39 @@ historical contract that was implemented; this file accumulates the
 deltas so phase 5+ readers can find the live behavior without diffing
 git history.
 
+## 2026-06-03 — ingest 진행 로그 개선: 파일명·phase·heartbeat·slowest 요약 (v0.26.1)
+
+**무엇을 왜 추가했나.** arctic 도그푸딩 중 이미지/PDF 혼재 + OCR/caption on 볼트에서
+ingest 가 중간부터 느려졌는데, TTY 진행바가 **파일명·현재 phase·모델·경과시간**을 안 보여
+"멈춘 것처럼" 보였다. 원인(비전 모델 스와핑)을 진행 표시만으로 파악 불가. v0.24.0 상세
+진행 로깅의 후속으로 느린 phase 와 병목 파일을 가시화했다. spec/plan:
+`docs/superpowers/specs/2026-06-03-ingest-log-improve-spec.md` / `…/plans/2026-06-03-ingest-log-improve-plan.md`.
+
+**무엇이 바뀌었나 (additive, `ingest_progress.v1` 유지 — major bump 없음).**
+
+- 신규 wire 이벤트 `asset_phase { idx, total, phase, model }` — asset 이 느린 phase
+  (`ocr` / `caption` / `embed`) 진입 시 1회 emit. `model` 은 그 phase 의 모델 id
+  (ocr/caption = 비전 LLM, embed = 임베더 model_id), 없으면 `null`. 짧은 phase
+  (parse/chunk/store) 는 노이즈 방지로 미emit.
+- `asset_timings` 에 `ocr_ms` / `caption_ms` 필드 추가 (serde `default` 0 → 구 소비자
+  호환). 이미지·PDF 경로도 이제 `asset_timings` 를 emit (이전엔 markdown 만) — slowest
+  요약이 비전-모델 병목을 정확히 집계.
+- CLI 렌더(`kebab-cli/src/progress.rs`): AssetStarted 시 진행바 메시지에 파일명(긴 path 는
+  말미 축약), AssetPhase 시 `{path} · {phase}({model})…`, steady-tick 1s 커스텀 키로
+  경과초 `(Ns)` 라이브 갱신, `Completed` 시 stderr 에 `⏱ 최장 소요 top-5` 표.
+  `--quiet` 여도 요약은 출력, `--json` 은 ndjson 만(사람텍스트 미혼입).
+
+**emit 지점.** `kebab-app/src/lib.rs` — 이미지 경로 `apply_ocr`/`apply_caption` 직전
++ ocr/caption 시간 측정, markdown/이미지/PDF 임베딩 루프 직전 `embed` phase, 각 경로
+`asset_timings` 에 측정값 채움. PDF `ocr_ms` 는 기존 page-OCR 총합 재사용.
+
+**알려진 한계.** code asset 경로는 진행 이벤트(AssetChunked/Timings) 무emit 이라 slowest
+요약에 미포함(기존 동작 유지, 비범위). top-N 의 N=5 상수(config 화 비범위). PDF 페이지
+OCR 진행은 기존 `pdf_ocr_started/finished` 가 담당(본 작업 비범위).
+
+**도그푸딩 (별도).** 사용자 Obsidian 볼트(이미지/PDF + OCR on) 재현 — 느린 구간의
+파일·phase·모델 즉시 가시 + 종료 요약이 병목 파일을 짚는지. release notes + 본 entry 갱신.
+
 ## 2026-06-03 — arctic-embed-l-v2.0 임베더 통합 (candle + Ollama) (v0.26.0)
 
 **무엇을 왜 추가했나.** 별칭(doc-side expansion) 제거(v0.25.0) 후 설명형 query 의