From ed04c250acb3362d4ace707948adf95859b50388 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E5=8D=83=E5=A4=8F?= Date: Tue, 1 Sep 2026 22:39:07 +0800 Subject: [PATCH] fix(recall): bound the embedding call so one slow upstream cannot hold recall open MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit generateEmbedding had no timeout. Hybrid recall awaits it, so a single slow upstream call held the whole request open for as long as the network took. Measured over a 14-day recall log (2404 calls): query_path=sync n=844 slow(>=3s)=0 avg 9ms query_path=strict n=144 slow(>=3s)=0 avg 60ms query_path=hybrid n=1416 slow(>=3s)=282 avg 2527ms Every slow call was on hybrid — the only path that embeds. Overall p50 is 327ms and p90 is 10635ms, which is not a tail, it is a second mode. The hybrid distribution has a cliff with an empty middle: p50 501ms · p70 919ms · p80 2290ms | p85 10695ms · p90 10734ms · p95 10880ms Nothing lives between ~3s and ~10s. That is the shape of an upstream stall, not of our work getting slower under load. ## Not the diagnosis we had This was on the books as "the resident server has a ~10s cold start, go find out where the server spends it". Two things kill that reading: - idle does not predict it. Median gap before a slow call is 3 minutes, before a fast one 1 minute; 16% of slow calls follow a >=10min gap vs 11% of fast ones. - the resident server is not where the time goes. It is an outbound HTTP call with no deadline, on the hot path, inside a Promise.all. The waiting also bought nothing. FTS runs in that same Promise.all and is synchronous, so its rows were already in hand — the request just sat on the socket holding them. ## Fix AbortSignal.timeout, default 2500ms, EMBEDDING_TIMEOUT_MS to override. 2.5s cuts the entire stall cluster (282 of the 286 calls it touches) at the cost of one legitimately slow embed; tightening to 1s would eat 84 more real ones and gain nothing, since the cluster is already gone by then. Resolved per call rather than at module load. Capturing env at import time makes the knob untunable by anything that configures itself after the import — which is every embedder of this library, and every test. Same trap as the DB path. ## Degradation stays visible A timeout returns null, the vector leg is skipped, and RRF proceeds on FTS rows. That is a quality degradation, so it is labelled rather than swallowed: the result carries _degradedTo / _degradeReason = 'embedding-timeout', matching what the early-bail branch already sets, and the timeout logs as its own line instead of reading like a broken upstream. Fast-and-quietly-worse is the failure mode this is guarding against. generateEmbedding is now exported. The timeout is only testable through it — going via recallMemoriesHybrid cannot discriminate on a machine without the sqlite-vec extension (CI), because that path early-bails to FTS before it ever embeds and would pass either way. ## Verification Red-then-green with the timeout removed: the stalled call runs 30024ms against a 30s stall — it waits the whole thing out — and returns an object instead of null with no degradation reason. Exactly those three assertions fail; both healthy-path assertions stay green, so they are not coupled to the fix. Full suite green: embedding-timeout 7 · cold-pool 6 · recall-contract 14 · ranking-importance 5 · recall-endpoint 17 · query-rewrite 6 · memory-health 68 · locations 51 · provenance 25 · encoding-damage 18 · injection-hygiene 14 · level-migration 10 · supersede-shrink 24 · anchor-pinned 4. [prediction] 修复: hybrid 的第二个模态(~10.6s 那簇, 占 20%)消失, p90 从 10635ms 掉到 2500ms 量级; 发起方多数在 1500ms 就放弃了, 那部分白烧的服务端时间一起省掉 [prediction] 风险: 那 20% 的调用改为只有 FTS 结果, 排序质量下降。如果开始出现 "召回变笨了", 先看 _degradeReason='embedding-timeout' 的比例——比例高说明该治 上游连通性(代理/DNS), 不是把超时调回去 [prediction] 验证: 观察期后 hybrid 的 p85/p90 应落在 2500ms 附近而不是 10.6s; 且带 embedding-timeout 标记的调用数应约等于原先 >=3s 的调用数 Co-Authored-By: 千夏 --- .github/workflows/ci.yml | 5 ++ embedding-timeout.integration.test.mjs | 111 +++++++++++++++++++++++++ index.mjs | 64 ++++++++++++-- 3 files changed, 173 insertions(+), 7 deletions(-) create mode 100644 embedding-timeout.integration.test.mjs diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 13743a1..6a7df6b 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -118,5 +118,10 @@ jobs: TOKENMEM_DB_PATH: ${{ runner.temp }}/mneme-ci-cold-pool.db run: node cold-pool-gate.test.mjs + - name: Integration test (embedding timeout — hot path degrades instead of hanging) + env: + TOKENMEM_DB_PATH: ${{ runner.temp }}/mneme-ci-embedding-timeout.db + run: node embedding-timeout.integration.test.mjs + - name: Adapter test (codex-recovery-proxy fault injection) run: node adapters/codex-recovery-proxy/proxy.test.mjs diff --git a/embedding-timeout.integration.test.mjs b/embedding-timeout.integration.test.mjs new file mode 100644 index 0000000..aa70c74 --- /dev/null +++ b/embedding-timeout.integration.test.mjs @@ -0,0 +1,111 @@ +// End-to-end: a slow embedding endpoint must not hold the recall hot path open +// Run: node embedding-timeout.integration.test.mjs +// +// generateEmbedding had no timeout. Because hybrid recall awaits it, one slow +// upstream call held the whole request open for as long as the network took. +// +// Measured on a 14-day recall_log (2404 calls, 2026-09-01): +// +// query_path=sync n=844 slow(>=3s)=0 avg 9ms +// query_path=strict n=144 slow(>=3s)=0 avg 60ms +// query_path=hybrid n=1416 slow(>=3s)=282 avg 2527ms +// +// Every slow call was on hybrid — the only path that embeds. The hybrid +// distribution has a cliff with nothing in it: p80 = 2290ms, p85 = 10695ms. +// That plateau is an upstream stall, not our work getting slower. +// +// The waiting bought nothing. FTS runs in the same Promise.all and is +// synchronous, so its rows are already in hand; the request just sits on the +// network. Worse, the hook that issued most of these aborts at 1500ms, so the +// server was spending 11 seconds producing a result nobody was still waiting for. +// +// The timeout is tested against generateEmbedding directly. Going through +// recallMemoriesHybrid would not discriminate on a machine without the +// sqlite-vec extension (CI): that path early-bails to FTS before it ever +// embeds, so it would pass whether or not the timeout exists. + +import { initMemory, generateEmbedding, recallMemoriesHybrid, storeMemory, closeMemory } from './index.mjs' +import http from 'node:http' + +let pass = 0, fail = 0 +const ok = (name, cond, extra = '') => { + if (cond) { pass++; console.log(`✓ ${name}`) } + else { fail++; console.log(`✗ ${name}${extra ? ' — ' + extra : ''}`) } +} + +const DIM = 1024 +const STALL_MS = 30_000 +const TIMEOUT_MS = 600 + +let mode = 'stall' +let calls = 0 +const server = http.createServer((req, res) => { + calls++ + const answer = () => { + if (res.writableEnded || res.destroyed) return + res.writeHead(200, { 'Content-Type': 'application/json' }) + res.end(JSON.stringify({ data: [{ embedding: new Array(DIM).fill(0.001) }] })) + } + if (mode === 'fast') answer() + else setTimeout(answer, STALL_MS).unref() +}) +await new Promise(r => server.listen(0, '127.0.0.1', r)) + +process.env.EMBEDDING_API_BASE_URL = `http://127.0.0.1:${server.address().port}` +process.env.EMBEDDING_API_KEY = 'test-key' +process.env.EMBEDDING_DIMENSION = String(DIM) +process.env.EMBEDDING_TIMEOUT_MS = String(TIMEOUT_MS) + +initMemory() + +// ── the fix itself ──────────────────────────────────────────────────────── +mode = 'stall' +let t0 = Date.now() +const stalledResult = await generateEmbedding('a query whose embedding never arrives') +let elapsed = Date.now() - t0 + +ok('the stalling endpoint was actually reached (fixture is wired up)', calls > 0, `calls=${calls}`) +ok('a stalled embedding gives up on schedule instead of waiting out the network', + elapsed < TIMEOUT_MS + 1500, `took ${elapsed}ms, budget ${TIMEOUT_MS}ms, stall ${STALL_MS}ms`) +ok('a timed-out embedding returns null rather than throwing', + stalledResult === null, `got ${stalledResult === null ? 'null' : typeof stalledResult}`) + +// ── the timeout must not eat healthy calls ──────────────────────────────── +mode = 'fast' +t0 = Date.now() +const goodResult = await generateEmbedding('a query whose embedding arrives promptly') +elapsed = Date.now() - t0 + +ok('a healthy embedding still comes back', + Array.isArray(goodResult) && goodResult.length === DIM, + `got ${Array.isArray(goodResult) ? goodResult.length + ' dims' : goodResult}`) +ok('a healthy embedding is not delayed by the timeout machinery', + elapsed < TIMEOUT_MS, `took ${elapsed}ms`) + +// ── degradation stays visible ───────────────────────────────────────────── +// Silent degradation is the failure mode this whole change is about: fast and +// wrong-looking-like-right is worse than slow. Only assertable where the vec +// extension is present, since otherwise hybrid never reaches the embed. +storeMemory({ + content: 'The recall hot path degrades to full-text search when the embedding API stalls.', + summary: 'embedding timeout degradation fixture', + importance: 6, +}) +mode = 'stall' +const rows = await recallMemoriesHybrid({ query: 'embedding stalls degrade full-text', limit: 5 }) +ok('recall still returns rows — it degrades, it does not fail', + Array.isArray(rows) && rows.length > 0, `got ${rows?.length} rows`) + +if (rows?._degradeReason === 'vec-extension-not-loaded') { + console.log('~ skipped: degradation-reason assertion needs the sqlite-vec extension (absent here)') +} else { + ok('a timeout is recorded as its own degradation reason, not as a normal hybrid call', + rows?._degradeReason === 'embedding-timeout', + `_degradeReason=${rows?._degradeReason}`) +} + +server.close() +closeMemory() + +console.log(`\n${fail ? 'FAIL' : 'PASS'}: ${pass} passed / ${fail} failed`) +process.exit(fail ? 1 : 0) diff --git a/index.mjs b/index.mjs index c2773e5..afac335 100644 --- a/index.mjs +++ b/index.mjs @@ -622,10 +622,41 @@ export function initMemory() { // ── Embedding (Optional) ──────────────────────────────────── +// How long a single embedding call may hold a caller before we give up on it. +// +// Chosen from the hybrid latency distribution over a 14-day recall log +// (1416 calls, 2026-09-01), which is bimodal with an empty middle: +// +// p50 501ms p70 919ms p80 2290ms | p85 10695ms p90 10734ms +// +// Nothing lives between ~3s and ~10s. A 2.5s bound therefore cuts the entire +// upstream-stall cluster (282 of the 286 calls it touches) while costing one +// legitimately slow embed. Tightening to 1s would start eating real ones (84 +// more) and buys nothing — the stall cluster is already gone by then. +// +// Giving up is cheap here. FTS runs in the same Promise.all and is synchronous, +// so hybrid already holds its rows; losing the vector leg costs ranking quality +// on that one call, not the answer itself. +// Read per call, not at module load. Capturing env at import time makes the +// knob untunable by anything that configures itself after the import — which is +// every embedder of this library, and every test. Same trap as the DB path. +const embeddingTimeoutMs = () => { + const n = parseInt(process.env.EMBEDDING_TIMEOUT_MS || '', 10) + return Number.isFinite(n) && n > 0 ? n : 2500 +} + +/** Lets the hot path tell "upstream was slow" apart from "upstream was broken". */ +const EMBED_TIMEOUT = Symbol('embedding-timeout') + /** - * Generate embedding vector (OpenAI-compatible API) + * Generate embedding vector (OpenAI-compatible API). + * + * Returns null on any failure — every caller guards on falsy and degrades to + * full-text search. Pass `{ signalTimeout: true }` to get EMBED_TIMEOUT back + * instead of null specifically when the deadline was hit, so a caller that + * cares can record *why* it degraded rather than reporting a normal result. */ -async function generateEmbedding(text) { +export async function generateEmbedding(text, { signalTimeout = false } = {}) { if (!_embeddingConfig) return null try { const res = await fetch(`${_embeddingConfig.baseUrl}/embeddings`, { @@ -640,12 +671,17 @@ async function generateEmbedding(text) { dimensions: _embeddingConfig.dimension, encoding_format: 'float', }), + signal: AbortSignal.timeout(embeddingTimeoutMs()), }) const data = await res.json() return data?.data?.[0]?.embedding || null } catch (e) { - log(`Embedding failed: ${e.message}`) - return null + // A stalling upstream is the common case and should not read as a broken one. + const timedOut = e?.name === 'TimeoutError' || e?.name === 'AbortError' + log(timedOut + ? `Embedding timed out after ${embeddingTimeoutMs()}ms — degrading to FTS for this call` + : `Embedding failed: ${e.message}`) + return timedOut && signalTimeout ? EMBED_TIMEOUT : null } } @@ -2119,8 +2155,8 @@ export async function recallMemoriesHybrid(opts = {}) { // Parallel: vector query (get embedding) + FTS query // _internal=true so the FTS path doesn't also surface random records (hybrid surfaces once at the end) - const [queryEmbedding, ftsRows] = await Promise.all([ - generateEmbedding(queryText), + const [rawEmbedding, ftsRows] = await Promise.all([ + generateEmbedding(queryText, { signalTimeout: true }), Promise.resolve(recallMemories({ ...opts, limit: candidateLimit, @@ -2130,6 +2166,13 @@ export async function recallMemoriesHybrid(opts = {}) { })), ]) + // A timed-out embedding is a degradation, not a normal hybrid call. It gets + // the same _degradeReason the early-bail branch sets, so a caller inspecting + // the result sees one consistent story instead of a silently vector-less + // "hybrid" answer. Silent degradation is the failure this guards against. + const embedTimedOut = rawEmbedding === EMBED_TIMEOUT + const queryEmbedding = embedTimedOut ? null : rawEmbedding + // Vector path: KNN top N let vecRows = [] if (queryEmbedding) { @@ -2300,7 +2343,14 @@ export async function recallMemoriesHybrid(opts = {}) { effectiveLimit: limit, }) if (ownsTrace) persistRecallTrace(trace, result.map(row => row.rowid)) - return attachRecallTrace(result, trace) + const out = attachRecallTrace(result, trace) + if (embedTimedOut && Array.isArray(out)) { + // Non-enumerable, matching the early-bail branch: invisible to + // JSON.stringify / spread, readable by callers that ask. + Object.defineProperty(out, '_degradedTo', { value: 'fts-only', enumerable: false }) + Object.defineProperty(out, '_degradeReason', { value: 'embedding-timeout', enumerable: false }) + } + return out } // ── Conversation History Retrieval ──────────────────────────