diff --git a/crates/kebab-app/src/ingest.rs b/crates/kebab-app/src/ingest.rs index 96ad13c..2bb7638 100644 --- a/crates/kebab-app/src/ingest.rs +++ b/crates/kebab-app/src/ingest.rs @@ -1018,13 +1018,19 @@ fn unsupported_media_warning(path: &str) -> String { /// a cache that looks free. #[derive(Default)] pub(crate) struct CacheStats { + /// Chunks whose embedding was already cached. pub hit: usize, + /// Chunks whose embedding had to be computed. pub miss: usize, /// Keys that hit, for the batched `last_used_at` bump the caller runs /// after the vector upsert. pub touch_keys: Vec, - /// Lookup + decode + insert + touch, in **microseconds**. Not the - /// embedder call the misses trigger. + /// Cache-key hashing + lookup + hit/miss split + insert + touch, in + /// **microseconds**. Not the embedder call the misses trigger. + /// + /// The blake3 key hashing is inside the timer on purpose: it hashes + /// every chunk's full text and is pure CPU, so a label that said only + /// "lookup" would misattribute it on a miss-heavy run. /// /// Microseconds because a per-asset millisecond truncation loses the /// measurement entirely: a document's cache work is routinely @@ -1068,8 +1074,8 @@ fn embed_with_cache( let mut miss_indices: Vec = Vec::new(); let mut miss_inputs: Vec> = Vec::new(); - // Decoding a hit's payload back into `Vec` is part of what the - // cache costs, so it is inside the timer too — a metric that stopped + // The hit/miss split, including decoding a hit's payload back into + // `Vec`, is part of what the cache costs — a metric that stopped // at the SQL boundary would flatter the cache. let t_decode = std::time::Instant::now(); for (i, text) in texts.iter().enumerate() { @@ -1484,7 +1490,7 @@ fn ingest_one_asset( caption_ms: 0, cache_hit: u32::try_from(emb_cache.hit).unwrap_or(u32::MAX), cache_miss: u32::try_from(emb_cache.miss).unwrap_or(u32::MAX), - cache_ms: emb_cache.us / 1_000, + cache_ms: emb_cache.us.div_ceil(1_000), }, ); @@ -1895,7 +1901,7 @@ fn ingest_one_image_asset( caption_ms, cache_hit: u32::try_from(emb_cache.hit).unwrap_or(u32::MAX), cache_miss: u32::try_from(emb_cache.miss).unwrap_or(u32::MAX), - cache_ms: emb_cache.us / 1_000, + cache_ms: emb_cache.us.div_ceil(1_000), }, ); @@ -2789,7 +2795,7 @@ fn ingest_one_pdf_asset( caption_ms: 0, cache_hit: u32::try_from(emb_cache.hit).unwrap_or(u32::MAX), cache_miss: u32::try_from(emb_cache.miss).unwrap_or(u32::MAX), - cache_ms: emb_cache.us / 1_000, + cache_ms: emb_cache.us.div_ceil(1_000), }, ); diff --git a/crates/kebab-app/src/ingest_progress.rs b/crates/kebab-app/src/ingest_progress.rs index 15ed993..97cbcfd 100644 --- a/crates/kebab-app/src/ingest_progress.rs +++ b/crates/kebab-app/src/ingest_progress.rs @@ -154,9 +154,15 @@ pub enum IngestEvent { cache_hit: u32, #[serde(default)] cache_miss: u32, - /// Lookup, payload decode, insert, and the `last_used_at` touch - /// that every hit triggers — everything the cache costs except - /// the embedder call the misses go on to make. + /// Cache-key hashing, lookup, payload decode, insert, and the + /// `last_used_at` touch that every hit triggers — everything the + /// cache costs except the embedder call the misses go on to make. + /// + /// Rounded **up** to the millisecond. An asset's cache work is + /// routinely sub-millisecond, so truncating would report zero for + /// most assets and make any sum a systematic undercount; the cost + /// of rounding up is at most 1 ms per asset in the other + /// direction, which does not hide a cache that is expensive. /// /// The touch is counted deliberately: issue #231's sharpest claim /// is that a read-only cache hit generates write traffic, and a diff --git a/docs/DOGFOOD.md b/docs/DOGFOOD.md index ea6385c..3fc2be0 100644 --- a/docs/DOGFOOD.md +++ b/docs/DOGFOOD.md @@ -278,7 +278,7 @@ echo "# stdin content" | "$RELEASE_BIN" ingest-stdin --title "from stdin" --conf - sweep 이 끝난 뒤 진행바가 asset 분모·라벨로 돌아오는가 (TTY). sweep 이 같은 바를 빌려 쓰므로 복구가 빠지면 색인 구간 내내 `sweep [..] 4213/21` 로 그려진다. - ndjson 로그에 `purge` 줄과 `sweep_summary` 가 남는가 (이슈 #228 이전에는 이 구간이 0바이트였다). purge 실패 시 `purge_failed`. - sweep 중 Ctrl-C 한 번에 실제로 멈추는가. `sweep_completed.checked` 가 예고한 `total` 이 아니라 실제 검사한 수로 나와야 한다. -- `asset_timings` 의 `cache_hit` / `cache_miss` / `cache_ms` (v0.32.1, issue #231). warm 재색인이면 `cache_miss == 0` 이어야 한다. `cache_ms` 는 **`embed_ms` 에 포함된** 값이라 phase 를 합산할 때 이중 계상하지 말 것. 임베딩 kind 만 세므로 이미지·PDF 위주 코퍼스에서는 캐시가 한 일을 과소 표현한다. code 자산은 `asset_timings` 자체를 emit 하지 않는다. +- `asset_timings` 의 `cache_hit` / `cache_miss` / `cache_ms` (v0.32.1, issue #231). `--force-reingest` 로 warm 재색인하면 `cache_miss == 0` 이어야 한다(그냥 재색인하면 변경 없는 문서가 통째로 skip 되어 `asset_timings` 자체가 안 나온다). `cache_ms` 는 **`embed_ms` 에 포함된** 값이라 phase 를 합산할 때 이중 계상하지 말 것. 임베딩 kind 만 세므로 이미지·PDF 위주 코퍼스에서는 캐시가 한 일을 과소 표현한다. code 자산은 `asset_timings` 자체를 emit 하지 않는다. --- diff --git a/docs/wire-schema/v1/ingest_progress.schema.json b/docs/wire-schema/v1/ingest_progress.schema.json index d412971..a438bcd 100644 --- a/docs/wire-schema/v1/ingest_progress.schema.json +++ b/docs/wire-schema/v1/ingest_progress.schema.json @@ -235,7 +235,7 @@ "cache_ms": { "type": "integer", "minimum": 0, - "description": "asset_timings: what the derivation-cache path cost — lookup, payload decode, insert, and the last_used_at touch — excluding the embedder call the misses trigger. INCLUDED IN embed_ms rather than additional to it: the embed timer spans the whole vector phase, so summing the phase fields double-counts this one." + "description": "asset_timings: what the derivation-cache path cost — cache-key hashing, lookup, payload decode, insert, and the last_used_at touch — excluding the embedder call the misses trigger. Rounded UP to the millisecond, because an asset's cache work is routinely sub-millisecond and truncating would make any sum a systematic undercount. INCLUDED IN embed_ms rather than additional to it: the embed timer spans the whole vector phase, so summing the phase fields double-counts this one." } } } diff --git a/tasks/HOTFIXES.md b/tasks/HOTFIXES.md index 57a8b68..35169b3 100644 --- a/tasks/HOTFIXES.md +++ b/tasks/HOTFIXES.md @@ -20,16 +20,25 @@ git history. #231 은 "캐시가 히트하는데도 캐시를 우회하고 전량 재임베딩하는 편이 더 빠르다" 고 보고하면서, 본문에 **"⚠️ 정량 실측 보완 필요 … 수치 미기록"** 이라고 표를 비워 뒀다. 그 표를 채운 것이 이 항목이다. -측정 환경: 나무위키 문서 792건 / chunk 16,379개, ollama + snowflake-arctic-embed2 (1024-dim), `--force-reingest` 로 전 문서 full re-process. 캐시 우회는 `derivation_cache` 테이블을 비워 전량 미스로 만들었다. +측정 환경을 먼저 정확히 적는다 — 리뷰에서 두 표의 모수가 어긋난다는 지적을 받아 바로잡은 것이다. -| 조건 | 총 소요 | chunk/초 | -|---|---|---| -| 캐시 히트 경로 | **139.1초** | 236 | -| 캐시 우회(전량 재임베딩) | **1179.6초** | 28 | +- 코퍼스: 나무위키 마크다운 **1,157 파일**. 그중 730개는 확장자가 없어 skip 되고, 나머지가 색인된다. +- **측정 설정의 artifact**: 이 시험용 config 는 `[[workspace.sources]]` 두 개(`wiki` / `jira`)가 **같은 root 를 가리킨다**. dogfood config 를 `sed` 로 고쳐 쓰면서 두 source 의 root 가 같아졌다. 그래서 walker 가 파일을 두 번 스캔하고, run 하나가 **자산 처리 1,584건**을 낸다. A/B 두 run 이 완전히 같은 설정을 쓰므로 비교 자체는 유효하지만, 수치를 읽을 때 알고 있어야 한다. +- 저장된 결과: 문서 792건 / chunk 16,379개 / 캐시 항목 14,599개. +- run 당 임베딩 캐시 조회 32,758회 (자산 처리 1,584건 × 평균 21청크). +- 임베더: ollama + snowflake-arctic-embed2 (1024-dim). `--force-reingest` 로 문서 skip 을 우회해 전 문서 재처리. +- 캐시 우회는 `derivation_cache` 테이블을 비워 전량 미스로 만들었다. + +| 조건 | 총 소요 | +|---|---| +| 캐시 히트 경로 | **139.1초** | +| 캐시 우회(전량 재임베딩) | **1179.6초** | **캐시 히트가 8.5배 빠르다.** 이슈의 가설은 이 환경에서 재현되지 않는다. -새로 넣은 `asset_timings` 계측으로 내역을 뜯어보면 더 분명하다 (문서 1,584건 / 히트 32,758 / 미스 0, run 141.3초): +배칭 수정 전후(A-before / A-after)는 139.1초 / 139.3초로 측정 오차 안이다. + +새로 넣은 `asset_timings` 계측으로 내역을 뜯어보면 더 분명하다. 아래는 계측 정밀도를 고친 뒤의 별도 run(141.3초, 위 A/B 와 같은 스냅샷에서 시작, 자산 처리 1,584건 / 히트 32,758 / 미스 0): | 구간 | 소요 | 비중 | |---|---|---| @@ -37,15 +46,15 @@ git history. | `store_ms` — SQLite 문서·청크 기록 | 57.0초 | 40% | | `chunk_ms` | 4.4초 | 3% | | `parse_ms` | 0.1초 | 0% | -| ↳ 그중 **캐시 경로**(키 계산+조회+디코드+삽입+touch) | **0.6~2.2초** | **0.4~1.6%** | +| ↳ 그중 **캐시 경로**(키 해싱+조회+디코드+삽입+touch) | **0.6~2.2초** | **0.4~1.6%** | -두 가지를 정확히 적어 둔다. 리뷰에서 지적받아 고친 것들이다. +두 가지를 정확히 적어 둔다. 둘 다 리뷰에서 지적받아 고친 것이다. `embed_ms` 는 "Lance upsert" 가 아니다. `t_embed` 스팬은 orphan purge(`purge_vector_orphans_for_workspace_path`) + 캐시 경로 + 임베더 호출 + 레코드 구성 + Lance upsert + touch 를 전부 감싼다 — 코드 주석 자신이 "purge + upsert" 라고 적고 있다. -캐시 경로는 **`embed_ms` 안에 포함된 부분집합**이지 별도 가산 항목이 아니다. 그리고 0.6초는 **하한**이다. `cache_ms` 는 문서당 한 번 ms 로 절삭되는데 문서 하나의 캐시 작업이 대개 1 ms 미만이라 **1,584건 중 1,422건(90%)이 0 으로 찍혔다**. 절삭 상한이 문서당 1 ms 이므로 참값은 0.6~2.2초 구간이다. 초안은 이걸 0.6초 점추정으로 적었고, 그 숫자를 근거로 제안 3·6 을 기각했다 — 구간으로 고쳐 적는다. 결론(캐시 경로가 run 의 몇 %)은 구간 어느 쪽에서도 같다. +캐시 경로는 **`embed_ms` 안에 포함된 부분집합**이지 별도 가산 항목이 아니다. 그리고 0.6초는 **하한**이었다. `cache_ms` 는 자산당 한 번 ms 로 절삭되는데 자산 하나의 캐시 작업이 대개 1 ms 미만이라 **1,584건 중 1,422건(90%)이 0 으로 찍혔다**. 절삭 상한이 자산당 1 ms 이므로 참값은 0.6~2.2초 구간이다. 초안은 이걸 0.6초 점추정으로 적었고 그 숫자를 근거로 제안 3·6 을 기각했다 — 구간으로 고쳐 적는다. 결론(캐시 경로가 run 의 몇 %)은 구간 어느 쪽에서도 같다. -내부 누적은 마이크로초로 바꿔 절삭 지점을 문서당 3곳에서 1곳(emit 시점)으로 줄였고, 히트 payload 를 `Vec` 로 되돌리는 디코드 비용도 캐시 경로에 계상했다 — SQL 경계에서 멈추는 지표는 캐시를 실제보다 싸 보이게 한다. +내부 누적을 마이크로초로 바꿔 절삭 지점을 자산당 3곳에서 1곳(emit)으로 줄였고, 그 1곳은 **올림**으로 바꿔 계통적 하한을 없앴다. 올림 후 같은 run 을 다시 재니 0 으로 찍히는 자산이 하나도 없고 합이 **2.1초** 였다 — 내림이 하한 0.6초, 올림이 상한 2.1초이므로 참값은 그 사이이고, 앞서 산술로 낸 0.6~2.2초 구간이 실측으로 확인된 셈이다. 어느 쪽이든 run 141초의 1.5% 이하다. 히트 payload 를 `Vec` 로 되돌리는 디코드 비용과 blake3 키 해싱도 캐시 경로에 계상했다 — SQL 경계에서 멈추는 지표는 캐시를 실제보다 싸 보이게 한다. ### 왜 원 보고가 틀렸다고 단정하지 않는가