From cd132cd8ba1a0dc50d5bc2db1b194dae74acb7e0 Mon Sep 17 00:00:00 2001 From: wefio <48851810+wefio@users.noreply.github.com> Date: Fri, 30 Oct 2026 17:57:59 +0800 Subject: [PATCH] fix(onlion): an embedding outage costs latency, not the write Tencent's analysis of 16:52-17:52 split 74 timeouts into three classes; class B (39 rows, 52.7%) is ours and it is a mechanism: 1. the accept's inline embed loses its 8 s race, so the entry is stored vectorless; 2. the fold backfills, syncRecordEmbeddings throws on the provider timeout; 3. the throw leaves rememberBatch -> addOneBatch -> mutateUser, which treats it as a lost compare-and-swap and re-runs the whole attempt - up to twelve times, each paying the same 12 s timeout. 12 x 12 s = 144 s, which is the 120 s ceiling with only the fold on the stack. The records were already durable; every retry re-embedded them for nothing. Fixes: - the backfill never fails its caller, except EmbeddingPreparation, which is control flow (runPart unwinds the SQLite session, embeds outside it, re-enters). Swallowing that one silently dropped records - the fold-must-stay-searchable test caught it. - monitoring gains a provider circuit breaker (NMG_EMBED_BREAKER_MS, default 30 s) on dependency_timeout / embedding_timeout / embedding_network_error / 429 / 5xx. While open an embedding call fails in microseconds as embedding_suppressed; records are stored vectorless and score lexically until a later fold backfills them. A 400 does not trip it: that is our bug. Class A (31 rows, 53 ms, 54.48 MB) and C (4 rows) never reached the handler, so the worker cannot fix them; reducing the 600-800 MB per-instance baseline is the separate next task, and the record says so. Recorded in docs/decisions/implemented/2026-10-30-embedding-breaker.* --- .../2026-10-30-embedding-breaker.md | 84 +++++++++++++++++++ .../2026-10-30-embedding-breaker.terms.yaml | 4 + .../2026-10-30-embedding-breaker.zh-CN.md | 58 +++++++++++++ onlion/backend/memory-service.ts | 34 +++++++- onlion/backend/monitoring.mjs | 54 +++++++++++- onlion/backend/worker.mjs | 9 +- 6 files changed, 236 insertions(+), 7 deletions(-) create mode 100644 docs/decisions/implemented/2026-10-30-embedding-breaker.md create mode 100644 docs/decisions/implemented/2026-10-30-embedding-breaker.terms.yaml create mode 100644 docs/decisions/implemented/2026-10-30-embedding-breaker.zh-CN.md diff --git a/docs/decisions/implemented/2026-10-30-embedding-breaker.md b/docs/decisions/implemented/2026-10-30-embedding-breaker.md new file mode 100644 index 00000000..211836ea --- /dev/null +++ b/docs/decisions/implemented/2026-10-30-embedding-breaker.md @@ -0,0 +1,84 @@ +# An embedding outage must cost latency, not the write + +[简体中文](2026-10-30-embedding-breaker.zh-CN.md) · [Terms](2026-10-30-embedding-breaker.terms.yaml) + +**Status:** implemented +**Approved:** explicit + +## Problem + +Tencent's log analysis of 16:52-17:52 (74 rows, all `调用超时`) split the outage into three +classes: + +| class | signature | rows | +| ----------------------------- | ---------------------------------------------------------------------------------------------------------------- | ---------- | +| A — fast fail | 53 ms, 54.48 MB, no business code ran | 31 (41.9%) | +| B — blocked on the dependency | 120000 ms, 588-770 MB, `kind=embedding_failure code=dependency_timeout` at `text-embedding-v4` in ap-southeast-1 | 39 (52.7%) | +| C — idle to the ceiling | 120000 ms, 54.48 MB | 4 (5.4%) | + +Class B is ours and is a mechanism, not a slow dependency: + +1. The accept embeds inline (8 s race) and **loses** the race — the entry is stored vectorless. +2. The fold then backfills vectors: `syncRecordEmbeddings` inside `rememberBatch`. When the + provider times out, that **throws**. +3. The throw leaves `rememberBatch` → `addOneBatch` → `mutateUser`, which treats it as a lost + compare-and-swap and **re-runs the whole attempt** - up to twelve times, each paying the same + provider timeout. Twelve attempts x 12 s is 144 s, which is how a request reaches the 120 s + ceiling while "the fold" is the only thing on the stack. + +The write had already succeeded by then. Every one of those retries was spent re-embedding records +that were already durable. + +## Decision + +**A vector backfill is an optimisation, so it may not fail the write; and a provider that is down +must not be called at all.** + +- `memory-service`'s backfill never throws except for `EmbeddingPreparation`, which is **control + flow**: `runPart` relies on it to unwind the SQLite session, embed outside it, and re-enter. + Swallowing that one silently dropped records (caught by the fold it must keep searchable test); + every other error is recorded in `backfillStatus` and the write continues. +- `monitoring.embeddingOperation` gains a **circuit breaker**: provider-side failures + (`dependency_timeout`, `embedding_timeout`, `embedding_network_error`, 429, 5xx) open it for + `NMG_EMBED_BREAKER_MS` (default 30 s). While open, an embedding call fails in microseconds with + `embedding_suppressed` instead of waiting out the timeout. Records accepted during the window + are stored vectorless and score lexically until a later fold backfills them. +- A 400 from a malformed input does **not** trip the breaker: that is our bug and must stay visible. + +## Evidence + +| before | after | +| ----------------------------------------------------------------------------------------------------- | --------------------------------------------------------------------------------------------------- | +| 39 rows at the 120 s ceiling in 18 minutes, all `dependency_timeout`, Adds 22-63 s when they survived | one timeout opens the breaker; the next Adds inside the window do no embedding work at all | +| a fold whose provider timed out re-ran the manifest CAS up to 12 times | the fold's storage work completes regardless of the provider; only the vectors are missing | +| `Add` p50 in the window: 22-36 s | unmeasurable until deployed; the accept no longer waits on a provider call that is known to be down | + +## What this does and does not establish + +- It does not make the provider fast, and it does not add capacity. During an outage, retrieval + quality drops (lexical instead of vector) for records accepted in the window - that is the + deliberate trade, and it is bounded by the breaker window. +- Class A (53 ms, 54.48 MB, 31 rows) and class C are **not** addressed. Those invocations never + reached the handler (no `nmg_request` line), so nothing in the worker can fix them; the honest + next step is to reduce the per-instance baseline (600-800 MB rss measured) so the platform has + less reason to fail fast, which is a separate task. +- The OPFS init noise (`Ignoring inability to install 'opfs' sqlite3_vfs`) comes from the vendored + SQLite WASM loader, not our code. + +## Alternatives considered + +- **Raise the document timeout back to 25 s.** That is the 15:2x configuration: each attempt waits + longer and the retry multiplier still applies. +- **Lower `mutateUser`'s attempt count.** It would cap the damage but keep the embedded call on the + request path; a breaker removes the call, which is strictly better under an outage. +- **Batch API for the backfill.** Needs a polling driver this runtime does not have (documented in + `2026-10-29-embedding-invocation-budget`). + +## Consequences + +- `/health limits` and `/admin/status` can report `embeddingBreakerStatus()`; `resetEmbeddingBreaker()` + is the operator action after a provider recovers. +- A record accepted during an outage is retrievable lexically and gains a vector at a later fold. + Nothing is lost; quality recovers on its own. +- The fold's outcome no longer depends on the provider at all, which is what + `2026-10-30-search-is-a-read` promised for the read path. diff --git a/docs/decisions/implemented/2026-10-30-embedding-breaker.terms.yaml b/docs/decisions/implemented/2026-10-30-embedding-breaker.terms.yaml new file mode 100644 index 00000000..6d27e285 --- /dev/null +++ b/docs/decisions/implemented/2026-10-30-embedding-breaker.terms.yaml @@ -0,0 +1,4 @@ +version: 2 +terms: [] +references: + - docs/decisions/implemented/2026-10-30-embedding-breaker.md diff --git a/docs/decisions/implemented/2026-10-30-embedding-breaker.zh-CN.md b/docs/decisions/implemented/2026-10-30-embedding-breaker.zh-CN.md new file mode 100644 index 00000000..cd5c52c3 --- /dev/null +++ b/docs/decisions/implemented/2026-10-30-embedding-breaker.zh-CN.md @@ -0,0 +1,58 @@ +# 嵌入故障应该只花延迟，不该花掉写入 + +[English](2026-10-30-embedding-breaker.md) · [Terms](2026-10-30-embedding-breaker.terms.yaml) + +**Status:** implemented +**Approved:** explicit + +## 问题 + +腾讯云对 16:52-17:52 的日志分析（74 条，全部 `调用超时`）把这次故障分成三类： + +| 类别 | 特征 | 条数 | +| ------------ | ------------------------------------------------------------------------------------------------------------- | ----------- | +| A 快速失败 | 53 ms、54.48 MB，业务代码没跑 | 31（41.9%） | +| B 依赖阻塞 | 120000 ms、588-770 MB，`kind=embedding_failure code=dependency_timeout`，`text-embedding-v4` @ ap-southeast-1 | 39（52.7%） | +| C 空转满时长 | 120000 ms、54.48 MB | 4（5.4%） | + +B 类是我们的问题，而且是机制问题，不是"依赖慢"： + +1. accept 内联嵌入（8 s 竞速）**输掉**——条目以无向量方式写入。 +2. 折叠随后回填向量：`rememberBatch` 里的 `syncRecordEmbeddings`。提供商超时时它**抛出**。 +3. 异常穿出 `rememberBatch` → `addOneBatch` → `mutateUser`，被当作 CAS 冲突，**整轮重试**——最多 12 次，每次都再付一次同样的超时。12 × 12 s = 144 s，这正是"请求达到 120 s 上限，而栈上只有折叠"的成因。 + +而此时写入其实早已成功。每一条重试都在为已经落库的记录重新嵌入。 + +## 决策 + +**向量回填是优化项，不得让写入失败；提供商已经倒下时，根本不该再调用它。** + +- `memory-service` 的回填不再抛出——**除了 `EmbeddingPreparation`，那是控制流**：`runPart` 依赖它解开 SQLite 会话、在会话外嵌入、再重进。把它一起吞掉会静默丢记录（被"折叠后的条目仍可检索"测试抓住）；其余错误记入 `backfillStatus`，写入继续。 +- `monitoring.embeddingOperation` 加**熔断器**：提供商侧失败（`dependency_timeout`、`embedding_timeout`、`embedding_network_error`、429、5xx）打开 `NMG_EMBED_BREAKER_MS`（默认 30 s）。窗口内嵌入调用以微秒级失败（`embedding_suppressed`），不再等满超时。窗口内接收的记录以无向量方式存储并按词面打分，等后续折叠回填。 +- 输入导致的 400 **不触发**熔断：那是我们的 bug，不能被藏起来。 + +## 证据 + +| 改前 | 改后 | +| ----------------------------------------------------------------------------- | ----------------------------------------------------- | +| 18 分钟内 39 条撞 120 s 上限，全是 `dependency_timeout`；活下来的 Add 22-63 s | 一次超时即打开熔断；窗口内的后续 Add 完全不做嵌入工作 | +| 提供商超时的折叠会把 CAS 重跑至多 12 次 | 折叠的存储工作不再依赖提供商，只缺向量 | +| 窗口内 Add p50 22-36 s | 部署前无法测量；accept 不再等一个已知不可用的调用 | + +## 这确立了什么、没有确立什么 + +- 它没有让提供商变快，也没有增加配额。故障期间，窗口内接收的记录检索质量下降（词面而非向量）——这是有意的取舍，且被熔断窗口约束。 +- A 类（53 ms、54.48 MB、31 条）与 C 类**未处理**：这些调用从未进入 handler（没有 `nmg_request` 行），worker 里没有任何东西能修；诚实的下一步是降低每实例基线（实测 600-800 MB rss）以降低平台快速失败的概率，那是另一个任务。 +- OPFS 初始化噪音（`Ignoring inability to install 'opfs' sqlite3_vfs`）来自 vendored 的 SQLite WASM loader，不是我们的代码。 + +## 考虑过的替代方案 + +- **把文档超时调回 25 s**：那是 15:2x 的配置，每次等待更久，而重试乘数照旧。 +- **降低 `mutateUser` 的重试次数**：能限制损失，但嵌入调用仍在请求路径上；熔断直接去掉调用，故障下严格更优。 +- **回填改用 Batch API**：需要本运行时不存在的轮询驱动（见 `2026-10-29-embedding-invocation-budget`）。 + +## 后果 + +- `/health limits` 与 `/admin/status` 可报告 `embeddingBreakerStatus()`；提供商恢复后由 `resetEmbeddingBreaker()` 复位。 +- 故障期间接收的记录可按词面检索，并在后来的折叠中获得向量。不丢数据，质量自行恢复。 +- 折叠的结果不再依赖提供商——这正是 `2026-10-30-search-is-a-read` 对读路径承诺过的事情。 diff --git a/onlion/backend/memory-service.ts b/onlion/backend/memory-service.ts index 958129d4..fa4a04b4 100644 --- a/onlion/backend/memory-service.ts +++ b/onlion/backend/memory-service.ts @@ -1,6 +1,7 @@ import { createHash } from "node:crypto"; import { NmgStore } from "../../src/core/store.ts"; import { syncRecordEmbeddings } from "../../src/core/embedding-sync.ts"; +import { EmbeddingPreparation } from "./embedding-session.mjs"; import { searchMemoryContext } from "../../src/integration/search.ts"; import { projectAmlMemory, @@ -116,6 +117,29 @@ export class AmlMemoryService { this.allowBackfill = options.allowBackfill; } private allowBackfill?: boolean; + /** The last backfill failure, for /admin/status. Deliberately not thrown: see backfillVectors. */ + private lastBackfillError: string | null = null; + + /** Bounded vector backfill that never fails its caller: the worst case is a record that keeps + * scoring lexically until a later fold tries again. */ + private async backfillVectors(): Promise { + if (!this.client) return; + try { + await syncRecordEmbeddings(this.store, this.client, 32, { maxBatches: 1 }); + this.lastBackfillError = null; + } catch (error) { + // EmbeddingPreparation is control flow, not a failure: `runPart` expects it to unwind the + // SQLite session so the documents can be embedded outside it, then re-enters. Swallowing it + // here looked like success and silently dropped the records - the write completed with a + // snapshot that never contained them, and only the fold/searchability test noticed. + if (error instanceof EmbeddingPreparation) throw error; + this.lastBackfillError = String((error as { code?: string })?.code ?? error); + } + } + + get backfillStatus(): string | null { + return this.lastBackfillError; + } async rememberBatch(userId: string, sessionId: string, requestId: string, messages: Message[]) { // Node-summary compensation without an LLM writer. The identity name below @@ -194,7 +218,13 @@ export class AmlMemoryService { // request. Without the cap the cost and the duration of one fold are unbounded in the number // of vectorless records, so a single call can both burn the provider budget and run into the // invocation ceiling. Later folds continue where this one stopped. - if (this.client) await syncRecordEmbeddings(this.store, this.client, 32, { maxBatches: 1 }); + // A vector backfill is an optimisation, not part of the write's contract. Before this + // guard a provider timeout threw out of here, out of the fold, and into `mutateUser`, which + // re-ran the whole attempt (up to twelve times, each paying the timeout again): that is how + // 2026-10-30 produced Adds at 15-55 s and seventeen kills at the 120 s ceiling. The records + // are already stored; leaving them vectorless costs lexical scoring until a later fold + // backfills them, which is strictly better than failing the write. + if (this.client) await this.backfillVectors(); // After embeddings: leaf-summary staleness must not trigger extra // embedding batches in records-granularity mode. runExtractiveLeafSummaries(this.store); @@ -232,7 +262,7 @@ export class AmlMemoryService { if (this.allowBackfill === false) { /* fall through: vectorless records score lexically until a fold backfills */ } else { - await syncRecordEmbeddings(this.store, this.client, 32, { maxBatches: 1 }); + await this.backfillVectors(); } } } diff --git a/onlion/backend/monitoring.mjs b/onlion/backend/monitoring.mjs index af17d705..2128d596 100644 --- a/onlion/backend/monitoring.mjs +++ b/onlion/backend/monitoring.mjs @@ -189,7 +189,52 @@ export function reportFailure(error, status, kind = "request_failure") { ); } } -export async function embeddingOperation(operation) { +/** Provider circuit breaker. + * + * 2026-10-30 17:35-17:49: one saturated embedding account answered nothing but timeouts, and + * every Add paid for it twice - once in the accept's inline embed, again in the fold's backfill - + * then retried the whole manifest compare-and-swap because the backfill threw. Seventeen requests + * died at the 120 s ceiling and one ran 196 s. A provider that is down must cost a request + * nothing: while the breaker is open, an embedding call fails in microseconds instead of twelve + * seconds, records are stored without vectors, and they score lexically until a later fold + * backfills them. Quality degrades for the duration of the outage; latency does not. + * + * Only provider-side failures trip it. A 400 from a malformed input is our bug and must stay + * visible rather than be hidden behind a breaker that also silences the next good request. */ +const breaker = { openUntil: 0, openedAt: null, trips: 0, reason: null }; +const tripsBreaker = (code) => + code === "dependency_timeout" || + code === "embedding_timeout" || + code === "embedding_network_error" || + code === "embedding_http_429" || + /^embedding_http_5\d\d$/.test(String(code)); +/** Milliseconds a trip keeps the provider out of the request path. */ +function breakerWindowMs(env) { + const configured = Number(env?.NMG_EMBED_BREAKER_MS); + return Number.isFinite(configured) && configured >= 0 ? configured : 30_000; +} +export function embeddingBreakerStatus() { + const open = Date.now() < breaker.openUntil; + return { + state: open ? "open" : "closed", + open_until: open ? new Date(breaker.openUntil).toISOString() : null, + opened_at: breaker.openedAt, + trips: breaker.trips, + reason: breaker.reason, + }; +} +/** Ends the current trip early. The operator path after a provider recovers. */ +export function resetEmbeddingBreaker() { + breaker.openUntil = 0; + breaker.reason = null; + return embeddingBreakerStatus(); +} +export async function embeddingOperation(operation, env) { + if (Date.now() < breaker.openUntil) { + const error = new Error("embedding provider is in a breaker window after a failure"); + error.code = "embedding_suppressed"; + throw error; + } // The call crosses a region boundary (function in ap-hongkong, provider elsewhere), so its // duration is the number that decides whether a per-attempt timeout is sane. Recording only // the status left that unknown through two incidents. @@ -220,6 +265,13 @@ export async function embeddingOperation(operation) { ...classifyError(error), }; reportFailure(error, null, "embedding_failure"); + const code = lastEmbedding.code; + if (tripsBreaker(code)) { + breaker.openUntil = Date.now() + breakerWindowMs(env); + breaker.openedAt = new Date().toISOString(); + breaker.trips += 1; + breaker.reason = code; + } throw error; } } diff --git a/onlion/backend/worker.mjs b/onlion/backend/worker.mjs index 81678ed4..c9a6854d 100644 --- a/onlion/backend/worker.mjs +++ b/onlion/backend/worker.mjs @@ -432,7 +432,7 @@ function embeddingClient(env, seed) { embed: (inputs) => Promise.resolve().then(() => { spend(); - return embeddingOperation(() => client.embed(inputs)); + return embeddingOperation(() => client.embed(inputs), env); }), embedDocuments: deferredDocuments((inputs) => { // A fold that already holds these vectors must not call the provider: this is what keeps the @@ -448,11 +448,12 @@ function embeddingClient(env, seed) { throw Object.assign(new Error("embedding budget exhausted for this request"), { code: "embedding_budget_exhausted", }); - return embeddingOperation(() => documents().embedDocuments(inputs)); + return embeddingOperation(() => documents().embedDocuments(inputs), env); }), // The raw provider call, for a caller outside any SQLite session - the accept path. The // deferred form above is for the fold, where it signals a preparation and throws by design. - embedDocumentsDirect: (inputs) => embeddingOperation(() => documents().embedDocuments(inputs)), + embedDocumentsDirect: (inputs) => + embeddingOperation(() => documents().embedDocuments(inputs), env), // Cached per TEXT, not per input array. The retrieval engine embeds one feature at a // time (`embedQueries([text])`), so a cache keyed by the array only ever hits when the // caller happens to ask for the same list: pre-warming a batch would populate nothing the @@ -470,7 +471,7 @@ function embeddingClient(env, seed) { // separate features: pooling them here would average the query's // aspects into one compromise vector, which measured worse than either // the whole text or the per-feature maximum. - const vectors = await embeddingOperation(() => client.embedQueries(missing)); + const vectors = await embeddingOperation(() => client.embedQueries(missing), env); if (vectors.length !== missing.length) throw new Error("embedding provider returned an invalid query batch"); return vectors;