altair823-org/kebab
0
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases 40 Wiki Activity

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

Browse Source 
Reviewed-on: #204
This commit was merged in pull request #204.
This commit is contained in:
altair823
2026-06-03 11:04:19 +00:00
parent 0263667684 6c9c8df43e
commit 736d791056
11 changed files with 548 additions and 83 deletions
Download Patch File Download Diff File Expand all files Collapse all files

48
Cargo.lock generated
View File

@@ -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",

2
Cargo.toml
View File

@@ -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),

1
HANDOFF.md
View File

@@ -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`.

2
README.md
View File

@@ -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` |

101
crates/kebab-app/src/ingest_progress.rs
View File

@@ -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 {

163
crates/kebab-app/src/lib.rs
View File

@@ -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

255
crates/kebab-cli/src/progress.rs
View File

@@ -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}"
);
}
}

7
crates/kebab-parse-image/src/ocr.rs
View File

@@ -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()

6
crates/kebab-tui/src/ingest_progress.rs
View File

@@ -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 { .. } => {}
}
}

13
docs/wire-schema/v1/ingest_progress.schema.json
View File

@@ -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." },

33
tasks/HOTFIXES.md
View File

@@ -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 의