diff --git a/Cargo.lock b/Cargo.lock index 860e41a..91a8535 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -4724,7 +4724,7 @@ dependencies = [ [[package]] name = "kebab-app" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "base64 0.22.1", @@ -4772,7 +4772,7 @@ dependencies = [ [[package]] name = "kebab-chunk" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "blake3", @@ -4790,7 +4790,7 @@ dependencies = [ [[package]] name = "kebab-cli" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "clap", @@ -4811,7 +4811,7 @@ dependencies = [ [[package]] name = "kebab-config" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "dirs 5.0.1", @@ -4827,7 +4827,7 @@ dependencies = [ [[package]] name = "kebab-core" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "blake3", @@ -4841,7 +4841,7 @@ dependencies = [ [[package]] name = "kebab-embed" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "blake3", @@ -4855,7 +4855,7 @@ dependencies = [ [[package]] name = "kebab-embed-candle" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "candle-core", @@ -4875,7 +4875,7 @@ dependencies = [ [[package]] name = "kebab-embed-local" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "fastembed", @@ -4888,7 +4888,7 @@ dependencies = [ [[package]] name = "kebab-embed-ollama" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "kebab-config", @@ -4903,7 +4903,7 @@ dependencies = [ [[package]] name = "kebab-eval" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "kebab-app", @@ -4922,7 +4922,7 @@ dependencies = [ [[package]] name = "kebab-llm" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "kebab-core", @@ -4931,7 +4931,7 @@ dependencies = [ [[package]] name = "kebab-llm-local" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "kebab-config", @@ -4948,7 +4948,7 @@ dependencies = [ [[package]] name = "kebab-mcp" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "kebab-app", @@ -4966,7 +4966,7 @@ dependencies = [ [[package]] name = "kebab-nli" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "hf-hub", @@ -4981,7 +4981,7 @@ dependencies = [ [[package]] name = "kebab-parse-code" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "gix", @@ -5004,7 +5004,7 @@ dependencies = [ [[package]] name = "kebab-parse-image" -version = "0.26.0" +version = "0.27.0" dependencies = [ "ab_glyph", "anyhow", @@ -5028,7 +5028,7 @@ dependencies = [ [[package]] name = "kebab-parse-md" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "kebab-core", @@ -5045,7 +5045,7 @@ dependencies = [ [[package]] name = "kebab-parse-pdf" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "blake3", @@ -5060,7 +5060,7 @@ dependencies = [ [[package]] name = "kebab-rag" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "blake3", @@ -5082,7 +5082,7 @@ dependencies = [ [[package]] name = "kebab-search" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "globset", @@ -5101,7 +5101,7 @@ dependencies = [ [[package]] name = "kebab-source-fs" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "blake3", @@ -5119,7 +5119,7 @@ dependencies = [ [[package]] name = "kebab-store-sqlite" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "blake3", @@ -5139,7 +5139,7 @@ dependencies = [ [[package]] name = "kebab-store-vector" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "arrow", @@ -5163,7 +5163,7 @@ dependencies = [ [[package]] name = "kebab-tui" -version = "0.26.0" +version = "0.27.0" dependencies = [ "anyhow", "crossterm", diff --git a/Cargo.toml b/Cargo.toml index dfccea5..ac443f9 100644 --- a/Cargo.toml +++ b/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. 기본 동작 불변(provider=fastembed e5), arctic 은 opt-in, embedding_version cascade(arctic-cls / ollama:{model} 태그). — CLAUDE.md §Release +version = "0.27.0" # v0.27.0 — 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), diff --git a/HANDOFF.md b/HANDOFF.md index 977d949..c20f7d0 100644 --- a/HANDOFF.md +++ b/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.27.0. 이미지/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` 추가. 기본 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`. diff --git a/README.md b/README.md index 91605e0..1fad986 100644 --- a/README.md +++ b/README.md @@ -83,7 +83,7 @@ Markdown · PDF · 이미지(OCR + caption) · 소스코드(Rust/Python/TS/JS/Go | 명령 | 동작 | |------|------| | `kebab init` | XDG 경로에 데이터 디렉토리 + config.toml 생성 | -| `kebab ingest []` | 워크스페이스 스캔 후 새/변경 문서 색인 (idempotent · incremental, `--force-reingest` 로 강제 재처리). 미지원 확장자는 자동 skip. 진행바는 문서별 청크 수 · 문서 종료 시 phase별 소요시간(parse/chunk/embed/store)을 표시 (`--json` 은 `asset_chunked`/`asset_timings` 이벤트로) | +| `kebab ingest []` | 워크스페이스 스캔 후 새/변경 문서 색인 (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 ` | 단일 파일 ingest (workspace 외부 가능 — `_external/` 로 deterministic copy) | | `kebab ingest-stdin --title ` | stdin 의 markdown 본문 ingest | | `kebab search --mode {lexical,vector,hybrid} "" [flags]` | 검색 (default hybrid = RRF fusion, citation 포함). 필터/budget flag 는 `--help` | diff --git a/crates/kebab-app/src/ingest_progress.rs b/crates/kebab-app/src/ingest_progress.rs index 46ad000..d5eb8ef 100644 --- a/crates/kebab-app/src/ingest_progress.rs +++ b/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.0 (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, + }, /// 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.0) are additive with serde default 0 + /// so pre-v0.26.0 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.0 additive: a pre-v0.26.0 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.0 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 { diff --git a/crates/kebab-app/src/lib.rs b/crates/kebab-app/src/lib.rs index 1419a0b..6beb1f7 100644 --- a/crates/kebab-app/src/lib.rs +++ b/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.0: surface the embed phase + model so a long embed run reads as + // "embedding()…" 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 = Vec::new(); + // v0.26.0: 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.0: 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.0: 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 diff --git a/crates/kebab-cli/src/progress.rs b/crates/kebab-cli/src/progress.rs index 0e2783e..1175fae 100644 --- a/crates/kebab-cli/src/progress.rs +++ b/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.0: 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, + /// v0.26.0 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>>, + /// v0.26.0: workspace path of the asset currently in flight — set on + /// `AssetStarted`, reused by `AssetPhase` to render `{path} · {phase}…`. + current_path: Option, + /// v0.26.0 slowest summary: idx → path, captured from `AssetStarted` + /// so `AssetTimings` (which only carries `idx`) can name the asset. + asset_paths: HashMap, + /// v0.26.0 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.0: 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.0: 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.0: (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.0: 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.0: 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.0: 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.0: 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.0: 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.0: 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.0: 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::(); + format!("…{tail}") +} + +/// v0.26.0: 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 { @@ -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}" + ); + } } diff --git a/crates/kebab-parse-image/src/ocr.rs b/crates/kebab-parse-image/src/ocr.rs index 3143b42..64ea1dd 100644 --- a/crates/kebab-parse-image/src/ocr.rs +++ b/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() diff --git a/crates/kebab-tui/src/ingest_progress.rs b/crates/kebab-tui/src/ingest_progress.rs index 76f56b2..1ba1931 100644 --- a/crates/kebab-tui/src/ingest_progress.rs +++ b/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.0 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 { .. } => {} } } diff --git a/docs/wire-schema/v1/ingest_progress.schema.json b/docs/wire-schema/v1/ingest_progress.schema.json index 4919754..ee3dd2a 100644 --- a/docs/wire-schema/v1/ingest_progress.schema.json +++ b/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.0): 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.0): 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.0, 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.0, 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." }, diff --git a/tasks/HOTFIXES.md b/tasks/HOTFIXES.md index f0046ae..2f8313a 100644 --- a/tasks/HOTFIXES.md +++ b/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.27.0) + +**무엇을 왜 추가했나.** 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 의