From bee1ace06ba7831d4f21e7c7bea7b07ab330ad19 Mon Sep 17 00:00:00 2001 From: altair823 Date: Mon, 17 Aug 2026 00:28:06 +0900 Subject: [PATCH] =?UTF-8?q?chore:=20PR=20#237=20=ED=9A=8C=EC=B0=A8=202=20?= =?UTF-8?q?=EB=A6=AC=EB=B7=B0=20=EB=B0=98=EC=98=81=20=E2=80=94=20=EB=AA=A8?= =?UTF-8?q?=EC=88=98=20=EC=A0=95=ED=95=A9=20+=20=EC=98=AC=EB=A6=BC=20+=20?= =?UTF-8?q?=EB=9D=BC=EB=B2=A8=20=EC=A0=95=EC=A0=95?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 2회차 리뷰가 1회차 지적 6건 모두 실질 해결을 확인하고(마이크로초 전환에 누락된 누적 지점 없음, 단위 1000배 오차 없음) 머지 가능으로 결론냈다. 남은 셋을 반영한다. 1) HOTFIXES 두 표의 모수가 정확히 2배 어긋났다 (MEDIUM) A/B 표는 "문서 792건 / 16,379 청크", 내역 표는 "1,584건 / 32,758" 이었다. 원인을 추적해 보니 **측정 설정의 artifact** 였다. 시험용 config 를 dogfood config 에서 sed 로 만들면서 `[[workspace.sources]]` 두 개(wiki / jira)의 root 가 같은 디렉토리를 가리키게 됐고, walker 가 파일 1,157개를 두 번 스캔해 run 하나가 자산 처리 1,584건을 낸다. A/B 두 run 이 완전히 같은 설정을 쓰므로 비교 자체는 유효하지만, 이 PR 의 산출물이 "실측 근거" 이므로 무엇을 몇 건 쟀는지 정확히 적어야 한다. 코퍼스 / 저장 결과 / run 당 조회 수를 나눠 적고 artifact 를 명시했다. 상한 2.2초의 유도(0.6 + 1,584 × 1 ms)도 이제 모수와 맞는다. 2) emit 시점 ms 절삭이 계통적 하한으로 남아 있었다 (MEDIUM) 내부 누적만 마이크로초가 됐고 wire 필드는 여전히 내림이라, 저자 자신의 데이터대로면 90% 자산이 계속 0 으로 찍힌다. 소비자가 합산하면 자산 수 × 최대 1 ms 만큼 계통적으로 과소 계상된다. `div_ceil` 로 올림했다. 같은 run 을 다시 재니 0 으로 찍히는 자산이 하나도 없고 합이 2.1초다 — 내림 0.6초가 하한, 올림 2.1초가 상한이므로 앞서 산술로 낸 0.6~2.2초 구간이 실측으로 확인됐다. 3) cache_ms 라벨이 blake3 키 해싱을 빠뜨렸다 (MEDIUM) `t_cache` 타이머는 `derivation_cache_key` 계산부터 시작한다. 청크 본문 전체를 해싱하는 순수 CPU 비용이라, "lookup" 만 적힌 라벨은 미스 위주 run 에서 실제로 오해를 만든다. 구조체 주석·필드 주석·스키마 셋 다 고쳤다. 4) 잔가지 (LOW) - `t_decode` 주석이 "디코드" 라고만 해서 실제로는 히트/미스 분류 루프 전체를 감싼다는 점이 안 드러났다. - `CacheStats` 의 hit / miss 필드에만 주석이 없었다. - DOGFOOD 의 "warm 재색인이면 cache_miss == 0" 은 `--force-reingest` 일 때만 성립한다. 그냥 재색인하면 변경 없는 문서가 통째로 skip 되어 `asset_timings` 자체가 안 나온다. 미반영: `get_many` 의 `prepare_cached` 가 배치 크기마다 SQL 문자열이 달라져 사실상 캐시 미스라는 지적 — 정확하지만 누수도 정확성 문제도 없고, 버킷 패딩은 1% 짜리에 낼 복잡도가 아니다. tracing 로그가 us 라 자릿수가 길다는 점도 단위 표기와 값이 맞으므로 그대로 둔다. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_017c9JwQq8ZkGvYjpKXMiDhF --- crates/kebab-app/src/ingest.rs | 20 ++++++++----- crates/kebab-app/src/ingest_progress.rs | 12 ++++++-- docs/DOGFOOD.md | 2 +- .../v1/ingest_progress.schema.json | 2 +- tasks/HOTFIXES.md | 29 ++++++++++++------- 5 files changed, 43 insertions(+), 22 deletions(-) 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 경계에서 멈추는 지표는 캐시를 실제보다 싸 보이게 한다. ### 왜 원 보고가 틀렸다고 단정하지 않는가