#231 은 "캐시가 히트하는데도 우회하고 전량 재임베딩하는 편이 더 빠르다" 고 보고하면서 본문에 "⚠️ 정량 실측 보완 필요 … 수치 미기록" 이라고 표를 비워 뒀다. 그 표를 채우는 것이 이 커밋의 핵심이다. 측정 (나무위키 792문서 / 16,379 chunk, ollama arctic-embed2 1024-dim, --force-reingest 로 전 문서 full re-process): 캐시 히트 경로 139.1초 236 chunk/초 캐시 우회(전량 재임베딩) 1179.6초 28 chunk/초 캐시 히트가 8.5배 빠르다. 가설은 이 환경에서 재현되지 않는다. 새로 넣은 계측으로 139초의 내역을 보면 더 분명하다 (히트 32,758 / 미스 0): Lance upsert + 레코드 구성 74.6초 53% SQLite 문서·청크 기록 56.7초 41% chunk 4.4초 3% 캐시 경로 전체(조회+삽입+touch) 0.6초 0.4% 이슈가 지목한 여섯 원인이 전부 합쳐 run 의 0.4% 다. 다만 "보고가 틀렸다" 로 읽으면 안 된다. 보고 이후 #229 와 #230 이 머지됐고, #231 본문 스스로 #229 를 "같은 Mutex<Connection> 을 공유하므로 상호 증폭" 이라고 적었다. 원 보고 환경에서는 캐시 조회 52,000회가 그 뮤텍스를 잡았다 놓는데 같은 뮤텍스 위에서 chunk 삭제가 FTS5 전체 스캔을 돌리고 있었다. "#229 를 먼저 고치면 체감이 줄어든다" 도 이슈의 예측이다. 이 머신이 61 GB RAM 이라 DB 가 통째로 페이지 캐시에 올라간다는 점도 함께 적어 둔다. 반영한 것: 제안 1·2·4 는 실측과 무관하게 왕복이 줄 뿐 잃는 게 없어 넣었다. 다만 A/B 벽시계는 139.1초 → 139.3초로 측정 오차 안이다. 이 코퍼스에서는 체감이 없다. - derivation_cache_get_many — `WHERE cache_key IN (…)` 배치 조회. 문서 하나가 평균 21 chunk 이라 왕복이 21회에서 1회가 된다. - derivation_cache_put_many — 미스 벡터를 한 트랜잭션에. 기존 단건 put 은 명시 트랜잭션 밖이라 행마다 암묵 커밋이었다. - prepare_cached — get/put/touch 셋 다. query_row 는 호출마다 SQL 을 다시 파싱한다. 제안 5(계측 노출)가 실질 산출물이다. `asset_timings` 에 cache_hit / cache_miss / cache_ms 를 additive 로 실었다. 이전에는 hit/miss 가 tracing::info! 로 stderr 에만 나가 run 이 끝나면 사라졌고, "내 코퍼스에서 캐시가 이득인가" 를 확인할 방법이 없었다. cache_ms 에는 touch 도 포함한다 — 이슈의 가장 날카로운 지적이 "읽기 전용이어야 할 히트 경로가 쓰기를 만든다" 인데, touch 를 빼고 재는 지표로는 그 주장을 검증할 수 없다. 네 out-param 은 CacheStats 구조체로 묶었다. 함께 읽히고 함께 보고되는 값들이고, 셋만 갱신하고 하나를 빠뜨리면 캐시가 공짜인 것처럼 보고된다. 반영하지 않은 것: - 제안 3(touch 를 히트 경로에서 분리). 캐시 경로 전체가 0.6초라 touch 만 떼어낼 이유가 없고, 권한 (c)안은 LRU 를 age 기반 축출로 바꾸는 의미 변경이다. 근거 없이 할 변경이 아니다. - 제안 6(캐시 우회 스위치). 이슈 스스로 "1~4 로 해결되면 불필요 — 플래그부터 만들지 말 것" 이라고 적었다. - 원인 6(4 KB BLOB overflow). page_size 변경은 기존 DB 에서 VACUUM 을 요구하는데 kebab 은 VACUUM 을 실행하지 않는다. 0.4% 에 낼 비용이 아니다. 곁다리로 #228 에서 내가 넣은 flaky test 를 고쳤다. `ingest_log_records_the_deleted_file_sweep` 이 두 run 의 로그 중 뒤엣것을 파일명 정렬로 골랐는데, run id 가 `<초 단위 타임스탬프>-<난수 hex>` 라 같은 초에 끝난 두 run 은 난수 쪽으로 정렬된다. 이번 전체 테스트에서 우연히 터져 잡았다. 첫 run 의 로그 집합을 기록해 두고 차집합으로 고르도록 바꿨다. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_017c9JwQq8ZkGvYjpKXMiDhF
269 lines
9.2 KiB
Rust
269 lines
9.2 KiB
Rust
// crates/kebab-app/tests/ingest_log_smoke.rs
|
|
//
|
|
// Integration tests for ingest_log feature (v0.20.x). Spec §5 AC-9 + AC-6.
|
|
|
|
use std::path::PathBuf;
|
|
|
|
use kebab_app::{IngestOpts, ingest_with_config};
|
|
use kebab_config::{Config, LoggingCfg};
|
|
use kebab_core::SourceScope;
|
|
use serde_json::Value;
|
|
use tempfile::TempDir;
|
|
|
|
fn minimal_config(workspace: &std::path::Path, log_dir: &std::path::Path) -> Config {
|
|
let data_dir = workspace.parent().unwrap().join("data");
|
|
std::fs::create_dir_all(&data_dir).unwrap();
|
|
let model_dir = workspace.parent().unwrap().join("models");
|
|
std::fs::create_dir_all(&model_dir).unwrap();
|
|
|
|
let mut cfg = Config::defaults();
|
|
cfg.workspace.root = Some(workspace.to_string_lossy().into_owned());
|
|
cfg.workspace.exclude.clear();
|
|
cfg.storage.data_dir = data_dir.to_string_lossy().into_owned();
|
|
cfg.storage.model_dir = model_dir.to_string_lossy().into_owned();
|
|
cfg.models.embedding.provider = "none".to_string();
|
|
cfg.models.embedding.dimensions = 0;
|
|
cfg.ingest.chunking.target_tokens = 80;
|
|
cfg.ingest.chunking.overlap_tokens = 20;
|
|
cfg.logging = LoggingCfg {
|
|
ingest_log_enabled: true,
|
|
ingest_log_dir: log_dir.to_path_buf(),
|
|
..Default::default()
|
|
};
|
|
cfg
|
|
}
|
|
|
|
/// AC-9: ingest → log file exists + each line valid JSON + last line kind=summary + scanned>0.
|
|
#[test]
|
|
fn ingest_log_smoke() {
|
|
let tmp = TempDir::new().unwrap();
|
|
let workspace = tmp.path().join("kb");
|
|
std::fs::create_dir_all(&workspace).unwrap();
|
|
let log_dir = tmp.path().join("logs");
|
|
|
|
// 1. Minimal corpus: 1 markdown + 1 scanned PDF (OCR disabled — no Ollama needed).
|
|
std::fs::write(
|
|
workspace.join("hello.md"),
|
|
"# Hello\n\nThis is a smoke test.\n",
|
|
)
|
|
.unwrap();
|
|
let pdf_src = PathBuf::from("../kebab-parse-pdf/tests/fixtures/scanned_page1.pdf");
|
|
if pdf_src.exists() {
|
|
std::fs::copy(&pdf_src, workspace.join("scanned.pdf")).unwrap();
|
|
}
|
|
|
|
// 2. Config with logging enabled.
|
|
let cfg = minimal_config(&workspace, &log_dir);
|
|
let scope = SourceScope {
|
|
root: workspace.clone(),
|
|
exclude: vec![],
|
|
..Default::default()
|
|
};
|
|
|
|
// 3. Run ingest.
|
|
ingest_with_config(cfg, scope, IngestOpts::default())
|
|
.expect("ingest should succeed");
|
|
|
|
// 4. Assert log file exists in log_dir.
|
|
let log_files: Vec<_> = std::fs::read_dir(&log_dir)
|
|
.unwrap()
|
|
.filter_map(Result::ok)
|
|
.filter(|e| {
|
|
e.file_name().to_string_lossy().starts_with("ingest-")
|
|
&& e.file_name().to_string_lossy().ends_with(".ndjson")
|
|
})
|
|
.collect();
|
|
assert_eq!(
|
|
log_files.len(),
|
|
1,
|
|
"expected exactly 1 ingest-*.ndjson file, found: {log_files:?}"
|
|
);
|
|
|
|
// 5. Parse each line as JSON — assert kind field present and valid.
|
|
let body = std::fs::read_to_string(log_files[0].path()).unwrap();
|
|
let lines: Vec<&str> = body.lines().collect();
|
|
assert!(!lines.is_empty(), "log file should not be empty");
|
|
|
|
let valid_kinds = [
|
|
"ocr",
|
|
"parse_error",
|
|
"skip",
|
|
"error",
|
|
"purge",
|
|
"purge_failed",
|
|
"sweep_summary",
|
|
"summary",
|
|
];
|
|
for line in &lines {
|
|
let v: Value = serde_json::from_str(line)
|
|
.unwrap_or_else(|e| panic!("line is not valid JSON: {e}\nline: {line}"));
|
|
let kind = v
|
|
.get("kind")
|
|
.and_then(|k| k.as_str())
|
|
.unwrap_or_else(|| panic!("line missing 'kind' field: {line}"));
|
|
assert!(
|
|
valid_kinds.contains(&kind),
|
|
"unexpected kind '{kind}' in line: {line}"
|
|
);
|
|
}
|
|
|
|
// 6. Last line must be kind=summary with scanned > 0.
|
|
let last = lines.last().unwrap();
|
|
let last_v: Value = serde_json::from_str(last).unwrap();
|
|
assert_eq!(
|
|
last_v.get("kind").and_then(|k| k.as_str()),
|
|
Some("summary"),
|
|
"last line must be kind=summary, got: {last}"
|
|
);
|
|
let scanned = last_v.get("scanned").and_then(Value::as_u64).unwrap_or(0);
|
|
assert!(scanned > 0, "summary.scanned should be > 0, got: {last}");
|
|
}
|
|
|
|
/// AC-6: ingest_log_enabled=false → no log file created.
|
|
#[test]
|
|
fn ingest_log_disabled_emits_no_file() {
|
|
let tmp = TempDir::new().unwrap();
|
|
let workspace = tmp.path().join("kb");
|
|
std::fs::create_dir_all(&workspace).unwrap();
|
|
let log_dir = tmp.path().join("logs");
|
|
|
|
std::fs::write(
|
|
workspace.join("hello.md"),
|
|
"# Hello\n\nDisabled log test.\n",
|
|
)
|
|
.unwrap();
|
|
|
|
let data_dir = tmp.path().join("data");
|
|
std::fs::create_dir_all(&data_dir).unwrap();
|
|
let model_dir = tmp.path().join("models");
|
|
std::fs::create_dir_all(&model_dir).unwrap();
|
|
|
|
let mut cfg = Config::defaults();
|
|
cfg.workspace.root = Some(workspace.to_string_lossy().into_owned());
|
|
cfg.workspace.exclude.clear();
|
|
cfg.storage.data_dir = data_dir.to_string_lossy().into_owned();
|
|
cfg.storage.model_dir = model_dir.to_string_lossy().into_owned();
|
|
cfg.models.embedding.provider = "none".to_string();
|
|
cfg.models.embedding.dimensions = 0;
|
|
cfg.logging = LoggingCfg {
|
|
ingest_log_enabled: false,
|
|
ingest_log_dir: log_dir.clone(),
|
|
..Default::default()
|
|
};
|
|
|
|
let scope = SourceScope {
|
|
root: workspace.clone(),
|
|
exclude: vec![],
|
|
..Default::default()
|
|
};
|
|
|
|
ingest_with_config(cfg, scope, IngestOpts::default())
|
|
.expect("ingest should succeed");
|
|
|
|
// log_dir should either not exist or contain 0 ingest-*.ndjson files.
|
|
let log_file_count = if log_dir.exists() {
|
|
std::fs::read_dir(&log_dir)
|
|
.unwrap()
|
|
.filter_map(Result::ok)
|
|
.filter(|e| {
|
|
e.file_name().to_string_lossy().starts_with("ingest-")
|
|
&& e.file_name().to_string_lossy().ends_with(".ndjson")
|
|
})
|
|
.count()
|
|
} else {
|
|
0
|
|
};
|
|
assert_eq!(
|
|
log_file_count, 0,
|
|
"no ingest-*.ndjson file should be created when disabled"
|
|
);
|
|
}
|
|
|
|
|
|
/// Issue #228: the deleted-file sweep wrote nothing to the ndjson log, so
|
|
/// a run whose whole wall-clock went into purging left a zero-byte file
|
|
/// and no way to reconstruct afterwards what had been deleted. The log is
|
|
/// the only post-hoc record — tracing goes to stderr and is gone.
|
|
#[test]
|
|
fn ingest_log_records_the_deleted_file_sweep() {
|
|
let tmp = TempDir::new().unwrap();
|
|
let workspace = tmp.path().join("kb");
|
|
std::fs::create_dir_all(&workspace).unwrap();
|
|
let log_dir = tmp.path().join("logs");
|
|
|
|
let doomed = workspace.join("doomed.md");
|
|
std::fs::write(&doomed, "# doomed\n\nthis file is about to vanish\n").unwrap();
|
|
std::fs::write(workspace.join("kept.md"), "# kept\n\nthis one stays\n").unwrap();
|
|
|
|
let scope = SourceScope {
|
|
root: workspace.clone(),
|
|
include: vec!["**/*.md".to_string()],
|
|
exclude: Vec::new(),
|
|
};
|
|
ingest_with_config(
|
|
minimal_config(&workspace, &log_dir),
|
|
scope.clone(),
|
|
IngestOpts::default(),
|
|
)
|
|
.expect("first ingest should succeed");
|
|
|
|
// Remember the first run's log so the second can be identified by
|
|
// elimination. Sorting by filename does not work: the run id is
|
|
// `<second-resolution timestamp>-<random hex>`, so two runs inside the
|
|
// same second sort by the random half.
|
|
let logs_of = |dir: &std::path::Path| -> std::collections::BTreeSet<PathBuf> {
|
|
std::fs::read_dir(dir)
|
|
.unwrap()
|
|
.filter_map(Result::ok)
|
|
.map(|e| e.path())
|
|
.filter(|p| p.extension().is_some_and(|x| x == "ndjson"))
|
|
.collect()
|
|
};
|
|
let before = logs_of(&log_dir);
|
|
|
|
std::fs::remove_file(&doomed).unwrap();
|
|
let report = ingest_with_config(
|
|
minimal_config(&workspace, &log_dir),
|
|
scope,
|
|
IngestOpts::default(),
|
|
)
|
|
.expect("second ingest should succeed");
|
|
assert_eq!(report.purged_deleted_files, 1);
|
|
|
|
let after = logs_of(&log_dir);
|
|
let mut fresh = after.difference(&before);
|
|
let log = fresh.next().expect("the second run wrote a log");
|
|
assert!(fresh.next().is_none(), "and exactly one");
|
|
let body = std::fs::read_to_string(log).unwrap();
|
|
|
|
let events: Vec<Value> = body
|
|
.lines()
|
|
.map(|l| serde_json::from_str(l).expect("each line is JSON"))
|
|
.collect();
|
|
let kind = |v: &Value| v.get("kind").and_then(Value::as_str).unwrap_or("").to_string();
|
|
|
|
let purges: Vec<&Value> = events.iter().filter(|v| kind(v) == "purge").collect();
|
|
assert_eq!(purges.len(), 1, "one purge line for the deleted file: {body}");
|
|
assert_eq!(
|
|
purges[0].get("doc_path").and_then(Value::as_str),
|
|
Some("doomed.md"),
|
|
"and it names which document went: {body}"
|
|
);
|
|
|
|
let sweep = events
|
|
.iter()
|
|
.find(|v| kind(v) == "sweep_summary")
|
|
.unwrap_or_else(|| panic!("the phase totals must be recorded: {body}"));
|
|
assert_eq!(sweep.get("purged").and_then(Value::as_u64), Some(1));
|
|
assert_eq!(
|
|
sweep.get("checked").and_then(Value::as_u64),
|
|
Some(1),
|
|
"one candidate examined: {body}"
|
|
);
|
|
assert!(
|
|
sweep.get("ms").is_some(),
|
|
"with a duration, which is what tells a user whether the phase was \
|
|
the run's bottleneck: {body}"
|
|
);
|
|
}
|