diff --git a/docs/decisions/proposed/2026-10-29-recorded-graveyard-for-cleanup.md b/docs/decisions/proposed/2026-10-29-recorded-graveyard-for-cleanup.md new file mode 100644 index 00000000..56db084e --- /dev/null +++ b/docs/decisions/proposed/2026-10-29-recorded-graveyard-for-cleanup.md @@ -0,0 +1,158 @@ +# A recorded graveyard for cleanup the commit could not finish + +[简体中文](2026-10-29-recorded-graveyard-for-cleanup.zh-CN.md) · [Terms](2026-10-29-recorded-graveyard-for-cleanup.terms.yaml) + +**Status:** proposed + +## Problem + +Cleanup of superseded partition snapshots happens **after** the manifest compare-and-swap +succeeds, because a key may only be deleted once the manifest that stopped referencing it is +durable. That leaves three ways to leave an orphan with no name: + +- the function is killed after the commit and before the delete (the platform ceiling, a + restart); +- a delete fails and the caller's `.catch(() => {})` swallows it; +- the delete is now batched at the provider's 1000-key limit, so a later batch can fail after + earlier ones succeeded - a **partial** cleanup that reports nothing and names nothing. + +None of these is visible from the manifest, which is the only thing a later request reads. The +invariant that matters - every key under `parts/` is referenced by the manifest - holds only +during a quiet period with no crash and with every delete batch succeeding, which is exactly the +condition an incident violates. + +## Proposal + +Record the doomed keys in the manifest before deleting them, so a failed delete has a name that +survives the request. + +1. **Order: record, then delete.** The keys are appended to `manifest.graveyard` inside the same + CAS that stops referencing them. Deletion of the previous graveyard happens **before** that + CAS, on the keys that are in neither the new `parts` nor the new `graveyard` - and never on + keys written by this same commit, or the drain would eat what it just recorded. +2. **A failed delete stays named.** Whatever could not be deleted remains in the new + `graveyard` and is carried to the next commit at no extra round trip. Retries are idempotent, + and a rival cannot reference our graveyard keys, so re-deleting is safe. +3. **Never delete doomed keys before the CAS.** Tempting - they are not in the new manifest - but + a retry's content fingerprint can still point at one of them, and the committed manifest would + then reference an object that no longer exists. The drain before the CAS is a different shape + with the opposite conclusion, and the reason is worth keeping: graveyard keys come from + **earlier requests**, so they can never appear in this request's `reuse`, while staged keys + **belong to this request** - which is exactly why deleting a staged key also has to remove it + from `reuse`. Same appearance, opposite answer, different reason. +4. **Bounded, newest first.** The field has a cap; over the cap, drop the **oldest** entries and + keep the newest, because the newest are the ones a partitioned delete just failed to remove. + An unbounded field would grow the manifest without limit under contention. +5. **A corrupt graveyard never blocks service, and is not blindly overwritten.** On read, a value + that is not an array, or one longer than the read cap, is **skipped** (no drain this request) + and counted, never sliced - slicing would drop keys from the cleanup list and manufacture the + leak this record exists to prevent. Writing does not simply overwrite, because a partially + corrupt value can still contain valid keys: a value that is not an array contributes nothing, an + array contributes the entries that are non-empty strings, and everything else is dropped and + counted as `graveyard_dropped_unparseable`. The salvaged keys, this commit's doomed set and the + carried-forward remainder are then unioned, filtered against the new `parts` - a graveyard entry + that is also a live part is a contradiction, and the next drain would delete live data - + deduplicated, capped newest-first (drops counted as `graveyard_dropped_cap`), and only then + written. Overwriting outright would discard keys that were perfectly parseable, which is our own + leak rather than the corruption's. `/add`, `/search` and `/capacity` keep serving regardless of + what the field contains. +6. **The counters ride the channel an operator already reads.** `userCapacity` returns + `pending_entries` and `manifest_bytes` per user and already raises `warnings` at 80% of a + limit, so `graveyard_pending`, `graveyard_dropped_unparseable` and `graveyard_dropped_cap` + belong in the same object, and a non-zero drop counter raises a warning ("leaking") there + rather than in a field nobody has a reason to look at. `graveyard_pending` measures **only + what was recorded**; orphans created before this mechanism existed are invisible to it and + must be measured separately. + +7. **Reset keeps the names.** `resetManifestState` builds a fresh object literal, so any field it + does not name is dropped, and `clearResetPendingKeys` only knows `parts` keys plus + `reset.pending_keys`. A graveyard key would therefore survive a reset with nothing referring to + it - permanently, since reclamation only sweeps other epochs - and reset is supposed to be the + escape hatch. Reset merges the graveyard into `reset.pending_keys` (already de-duplicated there) + and drops the field; `clearResetPendingKeys` already deletes in the same 1000-key batches, so + this adds no new limit. + +## What this does and does not establish + +- It gives a **bounded and self-healing** residue, not an **immediate** one: the last batch of a + quiet period waits for the next commit, so the invariant holds "after the last commit", not "at + any instant". +- It does not repair orphans that already exist. A local memory-bucket soak or a one-off admin + LIST is the only way to see those, and the two numbers must not be compared as one series. +- It does not make a stalled bucket fast; it makes the residue named. + +## Rollback + +During a rollback, an older writer does not know about the field and drops it while rewriting the +manifest, so keys recorded by the newer writer lose their only name. Rolling forward again does +not restore them. Storage does not shrink; the leak becomes unnamed. This is recorded here so it +is not later investigated as a new defect. + +## Acceptance criteria + +- **Empty state is byte-identical**: with an empty graveyard the manifest contains no + `graveyard` key at all, so a user who never triggers the mechanism is indistinguishable from + one written by today's deployment. `JSON.stringify` must not contain the string. +- **Availability with a corrupt field**: seed a manifest with `graveyard: "not-an-array"` and one + with an array longer than the read cap; assert `/add`, `/search` and `/capacity` all answer + normally, that the value is preserved until the next successful write, and that the counter is + reported. Without this test nothing prevents a future edit from turning it back into a 503. +- **The write side is an assertion, not a description.** Feed several corrupt graveyards - a + non-array, an array holding non-string entries, one longer than the cap, and one containing a + key that is also a live `parts` entry - and after one successful write assert that the field is + either absent or (an array of non-empty strings **and** no longer than the cap **and** disjoint + from `parts`). Without this, an implementation that forgets the `parts` filter or the cap passes + every other criterion here, and the first entry under Risks - a wrong filter deleting live data - + stays a paragraph instead of a test. In the live-key case also assert the referenced **object + still exists**: an implementation that deletes first and tidies the field afterwards satisfies + disjointness while destroying live data. In the over-cap case assert **which** keys survive, not + just the length - the newest entries and the newly doomed ones must be kept and the oldest + dropped - because a reversed comparison passes a length-only test. +- **Record then delete**: a failed delete leaves the key in the next manifest's graveyard, and the + following successful commit removes it. + +## Risks + +- **The drain deletes a live key.** The filter is "in neither the new `parts` nor the new + `graveyard`". A mistake there destroys a referenced snapshot, which is data loss, not residue: + this is the reason the filter is spelled out and tested before the mechanism is enabled. +- **The cap drops a key that is still referenced.** Newest-first exists to avoid it, but a wrong + comparison could drop the newest instead of the oldest; the acceptance test has to pin the + direction, not just the length. +- **An older writer drops the field** (see Rollback): in-flight keys lose their only name and + never come back. +- **Manifest growth under contention.** Bounded by the cap, but the cap has to be small enough + that 128 partitions of doomed keys never approach `MAX_MANIFEST_BYTES`. + +## Companion pit: a manifest at the byte ceiling also has no way back + +`commitManifest` throws when the receipt count exceeds `MAX_RECEIPTS`, and it throws the same way +when the encoded manifest exceeds `MAX_MANIFEST_BYTES`. Both are the same class as an unparseable +graveyard - a user that cannot be written to at all, repairable only by `/reset` or an admin +action - and both deserve to be recorded together rather than one being fixed and the other +forgotten. This record does not fix them; it notes that the graveyard's cap must be small enough +that it can never be the reason a manifest crosses that ceiling. + +## Alternatives considered + +- **A timeout heuristic** ("delete anything under `parts/` older than N") without recording: needs + a background sweep for a scenario that has no background execution on this platform, and it + guesses at a threshold instead of knowing which keys were doomed. +- **Delete before the CAS** so the failure window disappears: breaks retries, see rule 3. +- **Unbounded graveyard**: grows the manifest without limit exactly when writes are contending. +- **Swift at delete time rather than recorded**: batching turned a whole-batch rejection into a + partial one; a retry-driven sweep inside the same request is what actually finishes the job. + +## Consequences + +- One new manifest field, written only when there is something to record, so a drained manifest + stays byte-identical to today's. +- Cleanup costs at most one extra commit to converge, and nothing extra on the wire. +- An operator gets a number (`graveyard_pending`) that says how much recorded backlog exists. + +## Scope + +This is **not** part of the append-log accept slice, and not part of its gate. It changes the +manifest format, so it gets its own decision entry (this one) and its own commit boundary; it must +not land quietly inside the add-log ticket, or a later reader cannot tell which intent added a +field to the manifest. diff --git a/docs/decisions/proposed/2026-10-29-recorded-graveyard-for-cleanup.terms.yaml b/docs/decisions/proposed/2026-10-29-recorded-graveyard-for-cleanup.terms.yaml new file mode 100644 index 00000000..c9c1a952 --- /dev/null +++ b/docs/decisions/proposed/2026-10-29-recorded-graveyard-for-cleanup.terms.yaml @@ -0,0 +1,3 @@ +version: 2 +terms: [] +references: [] diff --git a/docs/decisions/proposed/2026-10-29-recorded-graveyard-for-cleanup.zh-CN.md b/docs/decisions/proposed/2026-10-29-recorded-graveyard-for-cleanup.zh-CN.md new file mode 100644 index 00000000..0fe5d7c3 --- /dev/null +++ b/docs/decisions/proposed/2026-10-29-recorded-graveyard-for-cleanup.zh-CN.md @@ -0,0 +1,105 @@ +# 用可记录的 graveyard 收尾提交完成不了的清理 + +[English](2026-10-29-recorded-graveyard-for-cleanup.md) · [Terms](2026-10-29-recorded-graveyard-for-cleanup.terms.yaml) + +**Status:** proposed + +## 问题 + +被取代的分区快照的清理只能发生在 manifest 的比较交换**成功之后**——只有"不再引用它的 manifest 已经持久化" +这一条成立,键才可以删。于是有三种情况会留下**没有名字**的孤儿: + +- 提交之后、删除之前函数被杀(平台上限、重启); +- 删除失败,调用方的 `.catch(() => {})` 把它吞掉; +- 删除现在按 provider 的 1000 键上限分批,后一批失败时前一批已经成功——**部分清理**,既不报错也不留名。 + +这三种从 manifest 都看不出来,而 manifest 是后续请求唯一读取的东西。真正关心的不变量——`parts/` 下的每个键都被 +manifest 引用——只在"无崩溃、且每一批删除都成功"的静默期成立,而那正是事故破坏的条件。 + +## Proposal + +在删除之前把待删的键记进 manifest,让失败的删除有一个能活过本次请求的名字。 + +1. **顺序:先记后删。** 键在"不再引用它们"的那一次 CAS 里追加进 `manifest.graveyard`。旧 graveyard 的删除发生在 + 该 CAS **之前**,且只删"既不在新 `parts`、也不在新 `graveyard`"里的键——**绝不删本次提交刚写进去的键**, + 否则 drain 会吃掉自己刚记下的东西。 +2. **删失败的留在名字里。** 删不掉的键留在新 `graveyard` 里,被顺路带到下一次提交,没有任何额外往返。重试幂等, + 对手不可能引用我们的 graveyard 键,所以重删安全。 +3. **绝不在 CAS 之前删待删键。** 看着安全(它们不在新 manifest 里),但重试的内容指纹仍可能指向其中之一, + 提交后的 manifest 就会引用一个已不存在的对象。CAS 之前的 drain 是形状相同、结论相反的另一件事,理由值得留住: + graveyard 里的键来自**更早的请求**,因此永远不可能出现在本次请求的 `reuse` 里;而 staged 键**属于本次请求** + ——这正是"删掉 staged 键还必须同时从 `reuse` 移除"那条规则必要的原因。外观相同,结论相反,理由不同。 +4. **有界、新键优先。** 字段有上限;超限丢**最旧**的、保留最新的——最新的恰好是某批删除刚失败的那批。 + 无界会让 manifest 在争用时无限增长。 +5. **坏 graveyard 永不阻塞服务,也不直接覆盖。** 读侧遇到非数组、或长度超过读上限的值时**跳过**(本次不 drain) + 并计数,**绝不 slice**——截断等于把一部分键从清理清单里悄悄扔掉,正是本条记录要防的泄漏。写侧不是简单覆盖, + 因为**部分损坏的值里仍可能有合法键**:非数组贡献 0;是数组则贡献其中非空字符串的项,其余丢弃并计入 + `graveyard_dropped_unparseable`。随后把「抢救出的键 + 本次待删集合 + 从上次带过来的剩余」做并集, + 按新 `parts` 过滤(graveyard 里的键同时又是 live part 是自相矛盾,下一次 drain 会删到活数据),去重, + 按新键优先做 cap(丢弃计入 `graveyard_dropped_cap`),最后才写出。直接覆盖等于丢掉本来完全可解析的键, + 那是我们自己制造的泄漏,不是损坏造成的。无论字段内容如何,`/add`、`/search`、`/capacity` 都正常服务。 +6. **计数器走运维已经在看的那条通道。** `userCapacity` 按用户返回 `pending_entries`、`manifest_bytes`,并且已经有 + 80% 触发 `warnings` 的机制,所以 `graveyard_pending`、`graveyard_dropped_unparseable`、 + `graveyard_dropped_cap` 应放进同一个对象,且后两者非零时在那里产生一条 warning("leaking"), + 而不是放在没人有理由去查的新字段里。`graveyard_pending` 只度量**被记录过的**积压;机理上线前产生的孤儿 + 它看不见,必须单独测。 + +7. **reset 要保住这些名字。** `resetManifestState` 构造的是一个全新的对象字面量,它没点名的字段会被丢掉, + 而 `clearResetPendingKeys` 只认识 `parts` 的键和 `reset.pending_keys`。于是 graveyard 里的键会在 reset 之后 + 活下来、却没有任何东西再引用它——而且是**永久**的,因为回收只扫其它代;而 reset 本该是那条逃生通道。 + 所以 reset 要把 graveyard 并进 `reset.pending_keys`(那里已经去重)并丢掉字段;`clearResetPendingKeys` + 本来就是按 1000 键分批删,所以这不引入新的上限。 + +## 这确立了什么、没有确立什么 + +- 给出的是**有界且自愈**的残留,不是**立即**收敛:静默期的最后一批要等下一次提交,所以不变量在"最后一次提交之后" + 成立,不是"任意时刻"。 +- **不修复已存在的孤儿**。只有本地 memory bucket soak 或一次性 admin LIST 能看到它们,两个数字不能当同一序列比较。 +- **不让卡住的桶变快**,只是让残留有名字。 + +## 回滚 + +回滚期间,旧写入者不认识这个字段,重写 manifest 时会把它丢掉——新写入者记录的那批键就此失去唯一的名字; +再前滚也不会恢复。存储不会因此下降,泄漏从"有名字"变成"没名字"。记在这里,避免以后被当成新缺陷重新排查。 + +## Acceptance criteria + +- **空态逐字节相等**:graveyard 为空时 manifest 里**根本没有** `graveyard` 键,于是从未触发该机理的用户与今天部署写出的 + 完全不可区分;`JSON.stringify` 里不得出现这个字符串。 +- **坏字段下仍可用**:seed 一个 `graveyard: "not-an-array"` 与一个超长数组的 manifest,断言 `/add`、`/search`、 + `/capacity` 全部正常作答、值在下一次成功写入前被原样保留、且计数被报出。没有这条,将来把行为改回 503 没有任何东西拦得住。 +- **写侧是断言,不是描述。** 分别喂进几种坏 graveyard——非数组、含非字符串元素的数组、超过 cap 的数组、 + 以及含有同时是 live `parts` 键的数组——各做一次**成功写入**后断言:字段要么不存在,要么满足 + (非空字符串数组 **且** `length <= CAP` **且** 与 `parts` 无交集)。没有这一条,一个忘了按 `parts` 过滤、 + 或忘了封顶的实现能通过这里列出的全部验收,而 Risks 第一条——过滤器写错就是删掉活数据——就永远只是一段话, + 不是一个测试。**live 键那一档还要断言被引用的对象仍然存在**:一个"先删、后整理字段"的实现能满足"无交集", + 同时销毁活数据。**超 cap 那一档要断言活下来的是哪几个键**,而不是只看长度——最新的、以及本次新判死的必须保留, + 最旧的必须被丢;比较方向写反的实现能通过只测长度的断言。 +- **先记后删**:一次失败的删除会把键留在下一个 manifest 的 graveyard 里,随后一次成功提交把它清掉。 + +## Risks + +- **drain 删掉一个仍在使用的键。** 过滤条件是"既不在新 `parts`、也不在新 `graveyard`"。这里判断错就是删掉被引用的快照—— + 那是数据丢失,不是残留。这也是为什么必须先把过滤条件写清并测过,再启用机理。 +- **cap 丢掉仍被引用的键。** 新键优先就是为了避免它;但比较方向写错就会丢最新的。验收测试要钉住**方向**,不只是长度。 +- **旧写入者把字段丢掉**(见"回滚"):在飞的那批键失去唯一名字,且永不恢复。 +- **争用下 manifest 增长。** 由 cap 约束,但 cap 必须足够小,让 128 个分区的待删键永远不会逼近 `MAX_MANIFEST_BYTES`。 + +## 考虑过的替代方案 + +- **超时启发式**("删掉 `parts/` 下比 N 更老的"):需要一个后台清扫,而这个平台没有后台执行;而且是猜阈值,不是知道 + 哪些键已被判死。 +- **在 CAS 之前删**以消掉失败窗口:破坏重试,见规则 3。 +- **无界 graveyard**:恰在写入争用时让 manifest 无限增长。 +- **只在删除时重试而不记录**:分批把"整批被拒"变成了"部分失败",真正能收尾的是同一次请求内由重试驱动的清扫。 + +## 后果 + +- 新增一个 manifest 字段,只在有话要记时出现,所以排空后的 manifest 与今天的逐字节相同。 +- 清理最多多花一次提交来收敛,线上没有任何额外往来。 +- 运维得到 `graveyard_pending` 这个"已记录积压有多少"的数字。 + +## 边界 + +这**不属于**加法日志的 accept 切片,也不属于它的门槛判据。它改变 manifest 格式,因此有自己的决策条目(本条)与 +自己的提交边界;不能悄悄落在加法日志那张票里,否则以后没人说得清"manifest 为什么多了个字段"。 diff --git a/docs/postmortem/0006-concurrency-ceiling-on-the-live-endpoint.md b/docs/postmortem/0006-concurrency-ceiling-on-the-live-endpoint.md new file mode 100644 index 00000000..d86d0667 --- /dev/null +++ b/docs/postmortem/0006-concurrency-ceiling-on-the-live-endpoint.md @@ -0,0 +1,115 @@ +# 0006 - The submission fails before the first question: concurrency ceiling on the live endpoint + +[中文](0006-concurrency-ceiling-on-the-live-endpoint.zh-CN.md) · [Terms used](0006-concurrency-ceiling-on-the-live-endpoint.terms.yaml) + +**Status:** open + +## Executive summary + +Seven scored attempts in one day never produced a score, and none of them failed inside the +retrieval logic. Measured on the deployed endpoint from a clean network, the service answers +every request at concurrency **1** and **2**, and stops doing so at **4**: 7 of 24 Adds died at +the 120 s invocation ceiling and the median Add went from 2.6 s to 106 s. At **16**, five of +thirty-two connections never completed at all. + +The harness probes `/health` before it starts, so a single connection failure voids the attempt +before any question is asked - which is what the two `PARTICIPANT_ENDPOINT_UNAVAILABLE` results +were. Two further attempts earlier in the day were `SEARCH_TIMEOUT · HTTP 504`, produced by this +same mechanism one layer down: a request that runs to the platform ceiling. + +The operating decision is to **run with concurrency 1**. That is a choice to trade wall-clock +time for a run that finishes, because a voided attempt costs everything and a slow one costs +minutes. + +## Summary + +Three independent limits, each sufficient on its own: + +1. **The write path redoes multi-megabyte work per CAS attempt.** An Add reads the user + manifest, reads and rewrites a partition of up to 8 MiB, and retries up to twelve times when + a rival writer wins the compare-and-swap. Concurrency does not help this: the writers + serialize on one manifest, so concurrency multiplies the number of losing attempts rather + than the throughput. +2. **Connection establishment becomes unreliable at four concurrent requests.** `/health` + answered in 2.3-14.5 s across probes, with two samples landing at ~10 s, which is the + default connect timeout of the clients involved. Past that boundary the client reports no + status at all. +3. **Every deployment is a window of unavailability.** Requests issued while a deployment + switched over were refused, twice today, and both times the resulting error was + `PARTICIPANT_ENDPOINT_UNAVAILABLE`, indistinguishable from a network fault. + +## Impact + +| attempt | error | class | +| -------- | --------------------------------------- | --------------------------------- | +| 05:34:20 | `SEARCH_SERVICE_UNAVAILABLE · HTTP 503` | server 5xx, older build | +| 10:45:38 | `SEARCH_TIMEOUT · HTTP 504` | request reached the 120 s ceiling | +| 13:50:50 | `SEARCH_TIMEOUT · HTTP 504` | same | +| 16:01:11 | `SEARCH_TIMEOUT · HTTP 504` | same | +| 18:11:50 | `ADD_CONNECTION_FAILED` | connection never established | +| 18:55:57 | `PARTICIPANT_ENDPOINT_UNAVAILABLE` | preflight connection failed | +| 19:01:59 | `PARTICIPANT_ENDPOINT_UNAVAILABLE` | same | + +No score was recorded; the failures were not distributed over the workload, they happened before +it. + +## Timeline + +- 05:18-10:43 - 220 invocations killed at exactly 120000 ms. Diagnosed as a 90 s per-attempt + embedding timeout that the client retried, multiplied by up to forty sequential calls in one + search. Fixed by a 10 s per-attempt timeout, no retry of timeouts, one batch call per purpose, + a 25 s query budget and a 45 s write budget. +- 17:4x - the provider endpoint was removed from the embedding index identity after it made + every existing user's next write re-embed their whole store inside the retry loop; Adds went + from 53-76 s back to 0.6-3.8 s. +- 18:55 and 19:01 - two `PARTICIPANT_ENDPOINT_UNAVAILABLE` results with clean platform logs, + which is the signature of a request that never arrived. +- 19:1x - measured from a clean network at concurrency 1, 2, 4 and 16. + +## Root cause + +Measured, same user, fresh user per run, deploy `8d5d91d3`: + +| concurrency | Add | Search | failures | +| ----------- | --------------------------------------------------------------- | ------------------- | ---------------------- | +| 1 | 24/24 200, p50 **2.6 s**, max 21.9 s | 8/8, p50 7.2 s | none | +| 2 | 16/16 200, p50 **3.6 s**, max 41.2 s | 4/4, p50 5.7 s | none | +| 4 | 17/24 200 + **7 x 504**, p50 106 s (round 1) / 51.6 s (round 2) | 8/8, p50 8.4-11.1 s | 7 x 504 | +| 16 | 27/32 200, p50 **45.6 s** | 15/16 | 5 connect timeouts + 1 | + +The maxima at concurrency 1-2 (21.9 s, 41.2 s) are the fold: one partition rewrite per eight +accepted entries. At concurrency 4 the folds and the accepts contend for the same manifest, and +the losing attempts redo a multi-megabyte partition read, export and upload each time - which is +how a 5 s operation becomes three figures. + +The preflight then fails for the same reason: sixteen invocations each holding an instance for +tens of seconds leave nothing for the health probe, and the probe's connect timeout is shorter +than the wait. + +## Guardrails added + +- `onlion/scripts/soak-endpoint.mjs`: the harness's own order from any network - preflight twice, + a concurrent Add phase, a concurrent Search phase - reporting per-status counts, p50/max and + connection errors. Exit code 1 when anything other than 200 appears, so it can gate a run. +- `/admin/status` reports the live embedding endpoint, model, index identity and the four + timeouts that bound a request, so "which endpoint is this build talking to" stops being + inferred from latency. +- Search and Add now carry explicit budgets (25 s query, 45 s write) and every COS round trip has + a 20 s timeout, so a stalled dependency fails a request instead of consuming the ceiling. + +## Lessons + +- **A health preflight turns every availability problem into a zero.** The most valuable thing to + protect is the first request, not the average one. +- **Concurrency is not free when the write path serializes per user.** It multiplied attempts + instead of throughput, and the cost landed exactly on the requests that had nothing to do with + the contention. +- **Measure from the client's network.** Three rounds of diagnosis were spent on numbers taken + through a proxy, which produced failures and latencies that the real client never saw - and hid + the ones it did. +- **A deployment is an outage.** Both times an attempt died at the endpoint, a deployment had + happened within the hour. Freezing deployments for the duration of a run is not caution, it is + part of the measurement. +- **A silent partial failure in cleanup costs nothing to look at and everything to reason about.** + Batching deletions made the cleanup more robust and the residue less observable; the fix is to + record what could not be deleted, not to hope it was nothing. diff --git a/docs/postmortem/0006-concurrency-ceiling-on-the-live-endpoint.terms.yaml b/docs/postmortem/0006-concurrency-ceiling-on-the-live-endpoint.terms.yaml new file mode 100644 index 00000000..c9c1a952 --- /dev/null +++ b/docs/postmortem/0006-concurrency-ceiling-on-the-live-endpoint.terms.yaml @@ -0,0 +1,3 @@ +version: 2 +terms: [] +references: [] diff --git a/docs/postmortem/0006-concurrency-ceiling-on-the-live-endpoint.zh-CN.md b/docs/postmortem/0006-concurrency-ceiling-on-the-live-endpoint.zh-CN.md new file mode 100644 index 00000000..01da8c46 --- /dev/null +++ b/docs/postmortem/0006-concurrency-ceiling-on-the-live-endpoint.zh-CN.md @@ -0,0 +1,90 @@ +# 0006 - 提交在第一个问题之前就失败了:线上端点的并发上限 + +[English](0006-concurrency-ceiling-on-the-live-endpoint.md) · [Terms used](0006-concurrency-ceiling-on-the-live-endpoint.terms.yaml) + +**Status:** open + +## Executive summary + +一天里七次计分尝试都没有产出分数,而没有一次是失败在检索逻辑里。从干净网络对已部署端点实测: +并发 **1** 和 **2** 时所有请求都正常;到 **4** 就不行了——24 次 Add 里 7 次死在 120 秒的调用上限上, +Add 的中位数从 2.6 秒变成 106 秒;到 **16** 时,32 次连接里有 5 次根本没建立。 + +比赛方在开始前会探测 `/health`,所以**一次连接失败就足以让整次尝试作废**——那两次 +`PARTICIPANT_ENDPOINT_UNAVAILABLE` 就是这种情况。当天更早的两次 `SEARCH_TIMEOUT · HTTP 504` 是同一机制 +下沉一层的结果:请求一直跑到平台上限。 + +运维决定是**以并发 1 运行**:用墙钟时间换一次能跑完的评测。作废的尝试损失一切,慢一点的只损失几分钟。 + +## Summary + +三个互相独立的限制,任何一个单独成立就足够: + +1. **写路径在每次 CAS 重试里重做 MB 级的工作。** 一次 Add 要读用户 manifest、读写最多 8 MiB 的分区, + 并在对手赢下比较交换时最多重试十二次。并发对此没有帮助:写者在同一份 manifest 上串行,所以并发 + 放大的是失败重试的次数,不是吞吐。 +2. **并发到四个请求时,连接建立开始不可靠。** `/health` 的实测在 2.3–14.5 秒之间,其中两次落在 ~10 秒 + ——那正是相关客户端默认的建连超时。越过这条线,客户端根本拿不到状态码。 +3. **每次部署都是一段不可用窗口。** 切换期间发出的请求被拒绝,当天发生两次,两次的错误都是 + `PARTICIPANT_ENDPOINT_UNAVAILABLE`,与网络故障无法区分。 + +## Impact + +| 尝试 | 错误 | 分类 | +| -------- | --------------------------------------- | ------------------- | +| 05:34:20 | `SEARCH_SERVICE_UNAVAILABLE · HTTP 503` | 服务端 5xx,旧构建 | +| 10:45:38 | `SEARCH_TIMEOUT · HTTP 504` | 请求跑到 120 秒上限 | +| 13:50:50 | `SEARCH_TIMEOUT · HTTP 504` | 同上 | +| 16:01:11 | `SEARCH_TIMEOUT · HTTP 504` | 同上 | +| 18:11:50 | `ADD_CONNECTION_FAILED` | 连接未建立 | +| 18:55:57 | `PARTICIPANT_ENDPOINT_UNAVAILABLE` | 预检连接失败 | +| 19:01:59 | `PARTICIPANT_ENDPOINT_UNAVAILABLE` | 同上 | + +没有记录到任何分数;失败不是分散在工作负载上的,它们发生在工作负载之前。 + +## Timeline + +- 05:18–10:43 220 次调用全部精确死在 120000 ms。诊断为:单次嵌入超时被写成 90 秒,而客户端会重试超时, + 再乘以单次检索里最多四十次的串行调用。修复为 10 秒单次超时、不重试超时、每种用途一次批量调用、 + 25 秒检索预算、45 秒写入预算。 +- 17:4x 把「端点」从嵌入索引身份里移除。此前它让每个既有用户的下一次写入都在重试循环里重嵌整个库, + Add 从 53–76 秒回到 0.6–3.8 秒。 +- 18:55 与 19:01 两次 `PARTICIPANT_ENDPOINT_UNAVAILABLE`,平台日志干净——那是「请求根本没到」的特征。 +- 19:1x 从干净网络在并发 1、2、4、16 下实测。 + +## Root cause + +实测,同一用户、每次运行使用全新用户、部署 `8d5d91d3`: + +| 并发 | Add | Search | 失败 | +| ---- | --------------------------------------------------------------- | ------------------- | ---------------- | +| 1 | 24/24 200,p50 **2.6 s**,max 21.9 s | 8/8,p50 7.2 s | 无 | +| 2 | 16/16 200,p50 **3.6 s**,max 41.2 s | 4/4,p50 5.7 s | 无 | +| 4 | 17/24 200 + **7 个 504**,p50 106 s(第一轮)/ 51.6 s(第二轮) | 8/8,p50 8.4–11.1 s | 7 个 504 | +| 16 | 27/32 200,p50 **45.6 s** | 15/16 | 5 次建连超时 + 1 | + +并发 1–2 下的最大值(21.9 s、41.2 s)是折叠:每接受八条就重写一次分区。并发 4 时折叠与接受争抢同一份 +manifest,输掉的那次尝试每次都要重做 MB 级的分区读、导出与上传——于是一个 5 秒的操作变成三位数。 + +预检随后因为同样的原因失败:十六次调用各自占着一个实例数十秒,健康探测拿不到实例,而它的建连超时比 +等待时间更短。 + +## Guardrails added + +- `onlion/scripts/soak-endpoint.mjs`:从任意网络按比赛方的顺序压测——两次预检、并发 Add 阶段、并发 + Search 阶段——报告各状态码计数、p50/max 与连接错误。出现非 200 就以退出码 1 结束,可用于开跑前的门禁。 +- `/admin/status` 报出当前嵌入端点、模型、索引身份以及约束一次请求的四个超时,让「这版在打哪个端点」 + 不再靠延迟推断。 +- 检索与写入各有显式预算(25 秒 / 45 秒),每次 COS 往返都有 20 秒超时,于是卡住的上游会让一个请求失败, + 而不是吃掉整个上限。 + +## Lessons + +- **健康预检会把任何可用性问题变成零分。** 最该保护的请求是第一个,不是平均水平。 +- **当写路径按用户串行时,并发不是免费的。** 它放大的是尝试次数而不是吞吐,而代价恰好落在那批与竞争无关的 + 请求上。 +- **必须从客户端所在的网络测量。** 三轮诊断花在经代理取到的数字上,而那些数字既产生了真实客户端看不到的失败, + 也掩盖了它看到的失败。 +- **一次部署就是一次中断。** 两次端点失败都在部署之后一小时内发生。评测期间冻结部署不是谨慎,是测量的一部分。 +- **清理里的静默部分失败,看的时候不花钱,推理的时候要命。** 分批删除让清理更健壮、让残留更难观测;正确的做法是 + 记录删不掉的键,而不是指望它没有。 diff --git a/docs/postmortem/README.md b/docs/postmortem/README.md index 0c22eb97..fa34a986 100644 --- a/docs/postmortem/README.md +++ b/docs/postmortem/README.md @@ -135,14 +135,15 @@ one row once a class has a canonical case — the record a reader should read fi — and the rule the class produced. A class whose rule cell is empty is a class nothing catches yet, which is the point of writing it down. -| Class | Canonical case | Rule it produced | -| ----------------------- | -------------- | ---------------- | -| unchecked tooling | 0001 | | -| wrong-tree verification | 0002 | | -| mutant-in-tree reading | 0003 | the sweep's lock: `agent:verify` refuses to report, and a new sweep refuses to start, while one holds the tree (`tools/mutation-lock.ts`) | -| mislabelled flake | 0004 | an intermittent failure is recorded with its reproduction attempt and rate, or left open - never as "flaky" (`skills/repo-development/SKILL.md`) | -| undrainable backlog | 0005 | [store regression](../../tests/core/store/maintenance.test.ts), [service regression](../../tests/cli/service.test.ts) | -| ----- | -------------- | ---------------- | +| Class | Canonical case | Rule it produced | +| ------------------------------ | -------------- | ------------------------------------------------------------------------------------------------------------------------------------------------ | +| unchecked tooling | 0001 | | +| wrong-tree verification | 0002 | | +| mutant-in-tree reading | 0003 | the sweep's lock: `agent:verify` refuses to report, and a new sweep refuses to start, while one holds the tree (`tools/mutation-lock.ts`) | +| mislabelled flake | 0004 | an intermittent failure is recorded with its reproduction attempt and rate, or left open - never as "flaky" (`skills/repo-development/SKILL.md`) | +| undrainable backlog | 0005 | [store regression](../../tests/core/store/maintenance.test.ts), [service regression](../../tests/cli/service.test.ts) | +| submission concurrency ceiling | 0006 | run at concurrency 1 and gate on `onlion/scripts/soak-endpoint.mjs`; no deployment between the start and the end of a scored run | +| ----- | -------------- | ---------------- | A class name is a short noun phrase, not a sentence, and it is not invented before there is a case to point at: the first record names the class, the second one @@ -151,10 +152,11 @@ one place to read the whole taxonomy. ## Index -| # | Record | Failure class | -| ---- | --------------------------------------------------------------------------------------------- | ----------------------- | -| 0001 | [The tool that checks the others is not itself checked](0001-tools-outside-the-type-check.md) | unchecked tooling | -| 0002 | [The tree I verified was not the tree I pushed](0002-wrong-tree-verification.md) | wrong-tree verification | -| 0003 | [The checks I read were reading a mutant](0003-checks-read-a-live-mutant.md) | mutant-in-tree reading | -| 0004 | ["Flaky" was a clock boundary](0004-flaky-was-a-clock-boundary.md) | mislabelled flake | -| 0005 | [Maintenance pressure that could not drain](0005-maintenance-pressure-cannot-drain.md) | undrainable backlog | +| # | Record | Failure class | +| ---- | -------------------------------------------------------------------------------------------------- | ------------------------------ | +| 0001 | [The tool that checks the others is not itself checked](0001-tools-outside-the-type-check.md) | unchecked tooling | +| 0002 | [The tree I verified was not the tree I pushed](0002-wrong-tree-verification.md) | wrong-tree verification | +| 0003 | [The checks I read were reading a mutant](0003-checks-read-a-live-mutant.md) | mutant-in-tree reading | +| 0004 | ["Flaky" was a clock boundary](0004-flaky-was-a-clock-boundary.md) | mislabelled flake | +| 0005 | [Maintenance pressure that could not drain](0005-maintenance-pressure-cannot-drain.md) | undrainable backlog | +| 0006 | [The submission fails before the first question](0006-concurrency-ceiling-on-the-live-endpoint.md) | submission concurrency ceiling | diff --git a/docs/postmortem/README.zh-CN.md b/docs/postmortem/README.zh-CN.md index f070f6fa..8069ddc1 100644 --- a/docs/postmortem/README.zh-CN.md +++ b/docs/postmortem/README.zh-CN.md @@ -88,24 +88,26 @@ 索引把每篇记录的类别写成自由文本。本表是分类体系:一类失败有一个典型案例——读者应先读的那篇记录——和它产生的规则时,就占一行。规则列空着,就意味着这一类目前没有任何东西拦住它,而把它写下来正是意义所在。 -| 类别 | 典型案例 | 它产生的规则 | -| ----------------------- | -------- | ------------ | -| unchecked tooling | 0001 | | -| wrong-tree verification | 0002 | | -| mutant-in-tree reading | 0003 | the sweep's lock: `agent:verify` refuses, and a new sweep refuses to start, while a sweep holds the tree (`tools/mutation-lock.ts`) | -| mislabelled flake | 0004 | an intermittent failure is recorded with its reproduction attempt and rate, or left open - never as "flaky" (`skills/repo-development/SKILL.md`) | -| undrainable backlog | 0005 | [store 回归](../../tests/core/store/maintenance.test.ts)、[服务回归](../../tests/cli/service.test.ts) | -| ----- | -------- | ------------ | +| 类别 | 典型案例 | 它产生的规则 | +| ------------------------------ | -------- | ------------------------------------------------------------------------------------------------------------------------------------------------ | +| unchecked tooling | 0001 | | +| wrong-tree verification | 0002 | | +| mutant-in-tree reading | 0003 | the sweep's lock: `agent:verify` refuses, and a new sweep refuses to start, while a sweep holds the tree (`tools/mutation-lock.ts`) | +| mislabelled flake | 0004 | an intermittent failure is recorded with its reproduction attempt and rate, or left open - never as "flaky" (`skills/repo-development/SKILL.md`) | +| undrainable backlog | 0005 | [store 回归](../../tests/core/store/maintenance.test.ts)、[服务回归](../../tests/cli/service.test.ts) | +| submission concurrency ceiling | 0006 | run at concurrency 1 and gate on `onlion/scripts/soak-endpoint.mjs`; no deployment between the start and the end of a scored run | +| ----- | -------- | ------------ | 类别名是简短名词短语,不是句子;在没有案例可指之前不凭空发明:第一篇记录命名它,第二篇确认它。记录的类别只写在索引里,不写在记录里,所以整个分类体系只有一处可读。 ## 索引 -| # | 记录 | Failure class | -| ---- | -------------------------------------------------------------------------- | ----------------------- | -| 0001 | [检查别人的工具,自己没被检查](0001-tools-outside-the-type-check.zh-CN.md) | unchecked tooling | -| 0002 | [我验证的树,不是我推送的树](0002-wrong-tree-verification.zh-CN.md) | wrong-tree verification | -| 0003 | [我读到的检查,读的是 mutant](0003-checks-read-a-live-mutant.zh-CN.md) | mutant-in-tree reading | -| 0004 | ["flaky" 其实是一个时钟边界](0004-flaky-was-a-clock-boundary.zh-CN.md) | mislabelled flake | -| 0005 | [重平衡无法消耗的维护压力](0005-maintenance-pressure-cannot-drain.zh-CN.md) | undrainable backlog | -| --- | ---- | ------------- | +| # | 记录 | Failure class | +| ---- | -------------------------------------------------------------------------------------------------- | ------------------------------ | +| 0001 | [检查别人的工具,自己没被检查](0001-tools-outside-the-type-check.zh-CN.md) | unchecked tooling | +| 0002 | [我验证的树,不是我推送的树](0002-wrong-tree-verification.zh-CN.md) | wrong-tree verification | +| 0003 | [我读到的检查,读的是 mutant](0003-checks-read-a-live-mutant.zh-CN.md) | mutant-in-tree reading | +| 0004 | ["flaky" 其实是一个时钟边界](0004-flaky-was-a-clock-boundary.zh-CN.md) | mislabelled flake | +| 0005 | [重平衡无法消耗的维护压力](0005-maintenance-pressure-cannot-drain.zh-CN.md) | undrainable backlog | +| 0006 | [The submission fails before the first question](0006-concurrency-ceiling-on-the-live-endpoint.md) | submission concurrency ceiling | +| --- | ---- | ------------- | diff --git a/onlion/backend/memory-service.ts b/onlion/backend/memory-service.ts index ed36d4ef..655a1f7e 100644 --- a/onlion/backend/memory-service.ts +++ b/onlion/backend/memory-service.ts @@ -186,7 +186,11 @@ export class AmlMemoryService { // Same ordered, transactional primitive as daemon rememberBatch. The // outer manifest commit also makes multiple internal batches atomic. this.store.rememberMany(inputs); - if (this.client) await syncRecordEmbeddings(this.store, this.client, 32); + // Bounded like the search path: a fold must not embed a whole partition's backlog in one + // 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 }); // After embeddings: leaf-summary staleness must not trigger extra // embedding batches in records-granularity mode. runExtractiveLeafSummaries(this.store); diff --git a/onlion/backend/storage.mjs b/onlion/backend/storage.mjs index 5ac342de..91163350 100644 --- a/onlion/backend/storage.mjs +++ b/onlion/backend/storage.mjs @@ -126,10 +126,19 @@ export async function stagePart(bucket,userKey,part,snapshot,reuse){ delete base.delta; return {...base,key,bytes:snapshot.byteLength}; } -export async function stageSearchPart(bucket,userKey,part,result,userBudget,fullSnapshot=false){ +/** Turns one part's search result into the snapshot the manifest will reference. + * + * `reuse` has to be forwarded, and it does double duty: it is what lets a retry + * skip an upload it already made for byte-identical content, and it is also the + * only record of *every* key this request uploaded - a snapshot staged by an + * abandoned attempt stays in the map so the caller can collect it after a later + * attempt commits. Dropping the argument silently loses both, and the loss is + * invisible: the request still works, it just re-uploads whole snapshots that no + * cleanup can name afterwards. */ +export async function stageSearchPart(bucket,userKey,part,result,userBudget,fullSnapshot=false,reuse=null){ const patch=fullSnapshot?null:measureSync('delta_encode',()=>makePageDelta(part,result.previousImage,result.snapshot,userBudget)); if(patch)return {...patch,mode:patch.changed?'inline_page_delta':'unchanged',stagedKey:null}; - const saved=await stagePart(bucket,userKey,part,result.snapshot); + const saved=await stagePart(bucket,userKey,part,result.snapshot,reuse); return {part:saved,mode:'full_snapshot',stagedKey:saved.key,changed:true,changedPages:0,inlineBytes:0}; } export async function commitManifest(bucket,key,previous,manifest){ @@ -163,8 +172,14 @@ export async function clearLog(bucket,userKey){ } return removed; } +// A multi-object delete takes at most 1000 keys per request (R2 and S3 both stop +// there). The set can exceed that: one search attempt stages a snapshot per part, +// so `staged ∪ reuse` for a wide user passes 1000 easily. An oversized call fails +// as a whole, and behind the callers' `catch` that is indistinguishable from a +// cleanup that removed nothing - the same permanent orphan, one level up. +const DELETE_BATCH = 1000; export async function removeStaged(bucket,keys){ - if(keys.length)await bucket.delete(keys); + for(let i=0;ip.key)); diff --git a/onlion/backend/worker.mjs b/onlion/backend/worker.mjs index 185b6157..450fc58a 100644 --- a/onlion/backend/worker.mjs +++ b/onlion/backend/worker.mjs @@ -29,6 +29,7 @@ import compiledSqlite from "../sqlite-wasm/sqlite3.wasm"; import { configure, DatabaseSync, withDatabases, sqliteStats } from "./sqlite.mjs"; import { memRequestStarted, memLog, memFields } from "./mem-trace.mjs"; import { AmlMemoryService, AML_SEARCH_PROFILE, CORE_SOURCE } from "./memory-service.ts"; +import { memoryEmbeddingText } from "../../src/core/store/search-ranking.ts"; import { createEmbeddingClientFromEnv } from "../../src/core/embedding-provider.ts"; import { normalizeContent, @@ -272,9 +273,13 @@ async function commitAttempt(env, { sqlite, key, object, before, operation, reus ); if (!saved) return { retry: true }; const live = new Set(manifest.parts.map((p) => p.key)); + // `reuse` holds keys uploaded by an earlier attempt of this same request. A committed attempt + // has to retire those too: they belong to a manifest that lost its CAS, so filtering only + // `staged` left one orphan per reused snapshot under parts/. The end-state invariant is + // "every key under parts/ is referenced by the manifest", which is what this enforces. await removeStaged( env.MEMORY, - staged.filter((k) => !live.has(k)), + [...new Set([...staged, ...reuse.values()])].filter((k) => !live.has(k)), ).catch(() => {}); await measure("retired_cleanup", () => retireParts(env.MEMORY, before, manifest)); return { response: result.response, committed: true, retry: false }; @@ -354,6 +359,14 @@ const EMBED_DOCUMENT_TIMEOUT_MS = 25_000; * well inside it: past this point the Add fails with a clear code instead of running out the * clock with no answer. */ const EMBED_WRITE_BUDGET_MS = 45_000; +/** How long an accept may spend embedding its own messages inline. + * + * The document text is `[day ]statement` for this path - `previous_turn` is never supplied by the + * service - so it is fully determined by the message and can be computed before the fold runs. + * Doing it here, under a budget, keeps the provider call out of the fold, which is the only place + * that serialises per user: a fold that has the vectors is a pure storage operation. If the + * budget expires the entry is written without them and the fold embeds as it does today. */ +const ACCEPT_EMBED_MS = 8_000; /** Total embedding work one search may spend, across every call site. * * A single search embeds its clauses, their windows, every pending record and each @@ -361,7 +374,16 @@ const EMBED_WRITE_BUDGET_MS = 45_000; * call means a slow provider costs a degraded score instead of the whole request: * every caller already treats a missing vector as "score this one by term overlap". */ const EMBED_QUERY_BUDGET_MS = 25_000; -function embeddingClient(env) { +/** The text a record is embedded from. Kept in one place so the accept-time vector and the fold's + * own computation cannot drift: both call this. */ +function embeddingTextOf(message) { + const statement = + message.indexText ?? (typeof message.content === "string" ? message.content : ""); + return memoryEmbeddingText(statement, { eventTime: message.chat_time }); +} +/** Seeds the client with vectors the entry already carries, so a fold finds them instead of + * calling the provider. Keyed by text, which is what the store asks for. */ +function embeddingClient(env, seed) { const client = createEmbeddingClientFromEnv({ ...env, NMG_EMBED_TIMEOUT_MS: env.NMG_EMBED_TIMEOUT_MS ?? String(EMBED_TIMEOUT_MS), @@ -406,6 +428,13 @@ function embeddingClient(env) { return embeddingOperation(() => client.embed(inputs)); }), embedDocuments: deferredDocuments((inputs) => { + // A fold that already holds these vectors must not call the provider: this is what keeps the + // fold a storage-only operation. A partial match falls through to the provider for all of + // them, which is correct and only costs the call this avoids in the common case. + if (seed) { + const seeded = inputs.map((text) => seed.get(text) ?? null); + if (seeded.every(Boolean)) return Promise.resolve(seeded); + } // Bounded by a total, not by an attempt: without it one slow provider turned a single // Add into a 55-120 s request that the platform killed with no answer. if (Date.now() >= writeDeadline) @@ -414,6 +443,9 @@ function embeddingClient(env) { }); return embeddingOperation(() => documents().embedDocuments(inputs)); }), + // 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)), // 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 @@ -619,92 +651,85 @@ async function acceptAdd(env, input) { const { userId, requestId, sessionId, messages, requestHash, fingerprint } = readAddRequest(input); const contentView = createContentView(); - let accepted = 0; - let prepared = null; - let reservation = null; - const response = await mutateUser(env, userId, async (ctx) => { - const reused = await existingReceipt(env, ctx, requestHash, fingerprint); - if (reused) return reused; - // Scoped to this generation: an entry written before a reset has the same name, - // and replaying its stored response would swallow the new Add - the request would - // answer 200 while its data was never recorded (class A, data lost). - const pending = await findLogEntry(env.MEMORY, ctx.key, requestHash, { - generation: ctx.manifest.generation ?? null, - }); - if (pending) { - if (pending.entry.fingerprint !== fingerprint) - throw new HttpError( - 409, - "request_id_reused", - "request_id was already used for different content", - ); - return { readOnly: true, response: pending.entry.response }; - } - // Structured content is prepared once per request, not once per retry: a - // caption may come from a vision model and a CAS conflict must not pay for it - // twice. It is prepared before the entry is written, so a fold never has to call - // a vision model while holding a partition. - if (!prepared) { - prepared = []; - for (const message of messages) - prepared.push( - typeof message.content === "string" - ? message - : { ...message, indexText: await contentView(message.content) }, - ); - } - const response = addResponse( - ctx.key, - requestId, - userId, - sessionId, - requestHash, - prepared.length, - ); - // Reserve the counter *before* the entry is durable. The order is the safety - // argument: a failed commit leaves no entry behind, while a failed write leaves - // the counter one too high - and an over-count only costs a log listing. The - // other order strands an entry no counter accounts for, and `pendingCount === 0` - // then hides it from every search (I1). - accepted = setPending(ctx.manifest, pendingCount(ctx.manifest) + 1); - reservation = { - key: ctx.key, - entry: { - v: LOG_ENTRY_VERSION, - generation: ctx.manifest.generation ?? null, - user_id: userId, - session_id: sessionId, - request_id: requestId, - request_hash: requestHash, - fingerprint, - received_at: Date.now(), - messages: prepared, - response, - }, - }; - return { response }; - }); - // The reservation is committed; only now must the entry become durable. A failure - // answers 5xx with the counter one too high, which capacity or the next fold - // corrects by reading the log back. - if (reservation) { - try { - await putLogEntry(env.MEMORY, reservation.key, reservation.entry); - } catch (error) { - // A throwing write is not proof that nothing reached the bucket: the storage - // wrapper writes first and then verifies the generation, so the throw can - // happen after the object landed. Ask instead of assuming, and only give the - // slot back when the answer is a definite "no" - releasing for an entry that - // is on disk leaves a counter below the truth, which hides accepted data. - const landed = await logEntryLanded(env.MEMORY, reservation.key, reservation.entry).catch( - () => null, + const key = keyFor(userId); + // One read of the manifest, and only for what the log cannot answer: the generation this entry + // belongs to, and the receipt of a request that was already folded. Nothing here takes a + // compare-and-swap, which is the point - sixteen concurrent Adds on one user used to fight over + // this object and lose twelve times each, redoing a megabyte of partition work per retry. + const { manifest } = await loadManifest(env.MEMORY, key, userId); + const reused = await existingReceipt(env, { key, manifest }, requestHash, fingerprint); + if (reused) return reused; + // Scoped to this generation: an entry written before a reset has the same name, and replaying + // its stored response would swallow the new Add - the request would answer 200 while its data + // was never recorded (class A, data lost). + const generation = manifest.generation ?? null; + const pendingEntry = await findLogEntry(env.MEMORY, key, requestHash, { generation }); + if (pendingEntry) { + if (pendingEntry.entry.fingerprint !== fingerprint) + throw new HttpError( + 409, + "request_id_reused", + "request_id was already used for different content", ); - if (landed === true) return { response, pending: accepted }; - if (landed === false) await releasePending(env, userId).catch(() => {}); - throw error; - } + return { readOnly: true, response: pendingEntry.entry.response }; + } + const prepared = []; + for (const message of messages) + prepared.push( + typeof message.content === "string" + ? message + : { ...message, indexText: await contentView(message.content) }, + ); + const response = addResponse(key, requestId, userId, sessionId, requestHash, prepared.length); + // Best effort inside a budget: the vectors travel with the entry, so the fold that eventually + // applies it does not have to reach the provider. A timeout leaves them out and the fold embeds. + const vectors = await inlineEntryVectors(env, prepared); + const entry = { + v: LOG_ENTRY_VERSION, + generation, + user_id: userId, + session_id: sessionId, + request_id: requestId, + request_hash: requestHash, + fingerprint, + received_at: Date.now(), + messages: prepared, + response, + ...(vectors ? { vectors: vectors.vectors, vector_model: vectors.model } : {}), + }; + try { + await putLogEntry(env.MEMORY, key, entry); + } catch (error) { + // A throwing write is not proof that nothing reached the bucket: the storage wrapper writes + // first and then verifies the generation, so the throw can happen after the object landed. + // Ask instead of assuming - an entry on disk must not be reported as a failure. + const landed = await logEntryLanded(env.MEMORY, key, entry).catch(() => null); + if (landed === true) return { response, pending: null }; + throw error; } - return { response, pending: accepted }; + // No manifest write at all, not even for the count. The log listing answers "how many are + // waiting" whenever somebody actually asks (`/capacity`), and that is the only consumer. + return { response }; +} +/** Embeds this entry's messages inside `ACCEPT_EMBED_MS`, or reports that it did not finish. + * + * Losing the race is not an error: the entry is still written, the fold embeds instead, and the + * abandoned call is harmless. What it buys is that in the common case the fold never contacts the + * provider - and the fold is the only per-user serialisation point left. */ +async function inlineEntryVectors(env, messages) { + const client = embeddingClient(env); + if (!client || messages.length === 0) return null; + const budget = + Number(env.NMG_ACCEPT_EMBED_MS) >= 0 ? Number(env.NMG_ACCEPT_EMBED_MS) : ACCEPT_EMBED_MS; + if (budget === 0) return null; + const texts = messages.map((message) => embeddingTextOf(message)); + const embedded = client.embedDocumentsDirect(texts).catch(() => null); + const raced = await Promise.race([ + embedded, + new Promise((resolve) => setTimeout(() => resolve(null), budget)), + ]); + if (!raced || raced.length !== texts.length) return null; + return { vectors: raced, model: client.indexId }; } /** Folds waiting entries into the partition, one partition write for the batch. * @@ -748,9 +773,12 @@ async function foldPending(env, userId) { ...message, source_message_id: `aml:${entry.request_hash}:${index}`, })); + // The entry may carry the vectors its accept computed. Handing them to this entry's client + // means the fold applies storage and nothing else. + const seeded = seedFromEntry(env, entry); await addOneBatch( env, - { ...ctx, userId, sessionId: entry.session_id, client }, + { ...ctx, userId, sessionId: entry.session_id, client: seeded ?? client }, entry.request_id, batch, ctx.manifest, @@ -866,7 +894,9 @@ async function fusePendingRecords({ appendOnly, appendedById, }) { - if (pendingCount(ctx.manifest) === 0) return candidates; + // No gate on the count here either. This is the short-circuit that made accepted entries + // invisible once the accept stopped maintaining the count: the manifest said zero while the log + // held entries. The listing inside `pendingForSearch` is bounded, so asking is always cheap. const waiting = await pendingForSearch(env, ctx, Math.min(topK, MAX_PENDING_READ)); if (waiting.length === 0) return candidates; const attribute = (clauseIndex) => { @@ -946,7 +976,9 @@ async function fusePendingRecords({ * Scoring happens in `search`: one embedding call per entry, capped at * `MAX_PENDING_READ`, because a search must see an Add that was just accepted. */ async function pendingForSearch(env, ctx, limit) { - if (pendingCount(ctx.manifest) === 0) return []; + // No short-circuit on the count: it is a hint that can lag or be absent, and trusting a zero is + // how accepted data becomes invisible (I1). The listing below is bounded by MAX_PENDING_READ, so + // never trusting the hint costs one small request. const waiting = await listPending(env.MEMORY, ctx.key, { limit: Math.min(limit, MAX_PENDING_READ), generation: ctx.manifest.generation ?? null, @@ -1045,6 +1077,19 @@ const FOLD_BATCH = 8; * writes: a fold absorbs exactly one batch, so the cadence is one fold per batch of * accepts at any trigger value above it. */ const FOLD_TRIGGER = FOLD_BATCH; +/** How long an Add may spend folding before it leaves the backlog for the next request. + * + * A fold is one partition rewrite - read, export, write - and it runs *after* the entry is + * durable, so skipping it is honest: the accept already earned its 200. Running it unbounded + * is what turned a contended user into a request the platform killed at 120 s, and a killed + * request loses the whole evaluation attempt rather than one fold. */ +const FOLD_BUDGET_MS = 20_000; +/** How long a search may spend reading partitions before it answers with what it has. + * + * Every partition is read to be exhaustive, which is unbounded in the manifest. Past this the + * page is built from the partitions already read and marked `partial`: fewer candidates for one + * question, instead of a request killed at the ceiling and no answer at all. */ +const SEARCH_DEADLINE_MS = 60_000; /** Features to embed and search per clause, bounded by `MAX_QUERY_FEATURES`. * @@ -1169,6 +1214,19 @@ function watchSlowRequest(env, context, started) { timer?.unref?.(); return () => clearTimeout(timer); } +/** Vectors an entry already carries, keyed by the text the store will ask for. Null when the entry + * has none, when they belong to a different index, or when the counts do not line up. */ +function seedFromEntry(env, entry) { + if (!Array.isArray(entry.vectors) || entry.vectors.length !== entry.messages.length) return null; + const client = embeddingClient(env); + if (!client || entry.vector_model !== client.indexId) return null; + const seed = new Map(); + entry.messages.forEach((message, index) => { + const vector = entry.vectors[index]; + if (Array.isArray(vector) && vector.length) seed.set(embeddingTextOf(message), vector); + }); + return seed.size ? embeddingClient(env, seed) : null; +} /** Fold one partition's persistence mode into the request totals. */ function tallyPartPersistence(persistence, saved) { if (saved.mode === "inline_page_delta") persistence.inline_delta_saves++; @@ -1212,13 +1270,22 @@ async function search(env, input, options = {}) { const contributions = clauses.map((_clause, index) => ({ index, contributed: 0, exclusive: 0 })); const client = embeddingClient(env), started = Date.now(); - return mutateUser(env, userId, async ({ sqlite, key, manifest, staged }) => { + return mutateUser(env, userId, async ({ sqlite, key, manifest, staged, reuse }) => { let candidates = []; const modes = new Set(); let changed = false; await warmClauseVectors(client, features, manifest.parts); const persistence = { inline_delta_saves: 0, full_snapshot_saves: 0, changed_pages: 0 }; + const searchDeadline = + Number(env.NMG_SEARCH_DEADLINE_MS) >= 0 + ? Number(env.NMG_SEARCH_DEADLINE_MS) + : SEARCH_DEADLINE_MS; + let partial = false; for (let i = 0; i < manifest.parts.length; i++) { + if (Date.now() - started > searchDeadline) { + partial = true; + break; + } const result = await runPart( env.MEMORY, manifest.parts[i], @@ -1252,6 +1319,9 @@ async function search(env, input, options = {}) { result, USER_DELTA_LIMIT - otherBytes, options.fullSnapshot || env.NMG_SEARCH_DELTAS === "0", + // Without this a search retry re-uploaded a byte-identical snapshot: the signature + // accepted a reuse map, the call site never passed one. + reuse, ); copyLegacyReceipts(manifest, result.legacyReceipts); manifest.parts[i] = saved.part; @@ -1290,6 +1360,7 @@ async function search(env, input, options = {}) { response: { data: candidates, retrieval_mode: modes.has("records") ? "records" : "lexical", + partial, timings: { totalMs: Date.now() - started, partitions: manifest.parts.length, @@ -1734,6 +1805,18 @@ function embeddingDiagnostics(env) { last_observation: embeddingObservation(), }; } +/** `/capacity` with `pending_entries` derived from the log instead of a maintained counter. + * + * The counter is gone from the accept path, so the only honest number is a listing. It is bounded: + * `pending_capped` says the bound was reached, which is enough for an operator and avoids reading a + * log that a stalled fold let grow without limit. */ +async function capacityReport(env, userId) { + const capacity = await userCapacity(env.MEMORY, userId); + const cap = Number(env.NMG_CAPACITY_PENDING_CAP) > 0 ? Number(env.NMG_CAPACITY_PENDING_CAP) : 200; + const listed = await listPending(env.MEMORY, keyFor(userId), { limit: cap }).catch(() => null); + if (listed === null) return { ...capacity, pending_entries: null, pending_capped: null }; + return { ...capacity, pending_entries: listed.length, pending_capped: listed.length >= cap }; +} async function adminStatusResponse(env) { const [sqlite, r2, reclaim, history] = await Promise.all([ check(() => sqliteReady().then(() => true)), @@ -1812,9 +1895,7 @@ async function adminRouteDispatcher(request, env, url, path) { return json({ load: setStatistics(input.enabled) }); } if (path === "/admin/capacity" && request.method === "GET") - return json( - await userCapacity(env.MEMORY, textField(url.searchParams.get("user_id"), "user_id")), - ); + return json(await capacityReport(env, textField(url.searchParams.get("user_id"), "user_id"))); if (path === "/admin/reset" && request.method === "POST") return json(await reset(env, await readJson(request))); if (path === "/admin/key" && request.method === "GET") return json({ api_key: env.NMG_API_KEY }); @@ -1898,9 +1979,7 @@ async function resetRoute(request, env, path) { } async function capacityRoute(request, env, url, path) { if (path !== "/capacity" || request.method !== "GET") return undefined; - return json( - await userCapacity(env.MEMORY, textField(url.searchParams.get("user_id"), "user_id")), - ); + return json(await capacityReport(env, textField(url.searchParams.get("user_id"), "user_id"))); } /** Drains one user's log. Needed before rolling the code back - a v4 manifest is * unreadable to an older deployment - and by the log-mode test, which otherwise has @@ -1936,10 +2015,22 @@ async function addRoute(request, env, path) { if ((path !== "/add" && path !== "/remember") || request.method !== "POST") return undefined; const input = await readJson(request); if (addMode(env) !== "log") return json(await add(env, input)); + const startedAt = Date.now(); const accepted = await acceptAdd(env, input); // A burst leaves entries waiting; fold a bounded batch here rather than on the // read path, so accepted latency stays flat while the log cannot grow forever. - if (accepted.pending >= FOLD_TRIGGER) + // The budget is what keeps a contended user from folding its way into the platform + // ceiling; the entry is already durable, so the backlog simply waits. + const foldBudget = + Number(env.NMG_FOLD_BUDGET_MS) >= 0 ? Number(env.NMG_FOLD_BUDGET_MS) : FOLD_BUDGET_MS; + // The trigger cannot read a count that no longer exists, so it is scheduled: roughly one accept + // in FOLD_TRIGGER attempts a fold. The fold lists the log first and does nothing when fewer than + // a batch is waiting, so a wasted attempt costs one listing, while a missed backlog would hide + // accepted data - the schedule is a rate, not a correctness signal. + const foldEvery = Number(env.NMG_FOLD_EVERY) > 0 ? Number(env.NMG_FOLD_EVERY) : FOLD_TRIGGER; + const dueBySchedule = + Number.parseInt(hash(accepted.response.request_id).slice(0, 6), 16) % foldEvery === 0; + if (dueBySchedule && Date.now() - startedAt < foldBudget) await foldPending(env, accepted.response.user_id).catch(() => {}); return json(accepted.response); } diff --git a/onlion/scripts/soak-endpoint.mjs b/onlion/scripts/soak-endpoint.mjs new file mode 100644 index 00000000..22e73f67 --- /dev/null +++ b/onlion/scripts/soak-endpoint.mjs @@ -0,0 +1,121 @@ +/* eslint-disable no-console -- a CLI that reports through stdout */ +/* Endpoint soak: the same shape the evaluation uses, from your network. + * + * The failures worth reproducing are connection-level ones - `PARTICIPANT_ENDPOINT_UNAVAILABLE` + * and `ADD_CONNECTION_FAILED` - where the platform log looks normal because the request either + * never arrived or the client gave up before it answered. Those cannot be seen from a single + * request, and they cannot be seen from a machine behind a proxy, so this runs the harness's own + * order from wherever you point it: preflight, a concurrent Add phase, then a concurrent Search + * phase. + * + * node onlion/scripts/soak-endpoint.mjs --endpoint https://... --key [--concurrency 16] + * + * Nothing is written to a shared user: every run gets its own user id, so it cannot disturb a + * scored run's data. Exit code is 1 when anything failed, so it can gate a run. + */ +const args = Object.fromEntries( + process.argv + .slice(2) + .join(" ") + .split("--") + .filter(Boolean) + .map((pair) => { + const [name, ...rest] = pair.trim().split(/[= ]/); + return [name, rest.join(" ")]; + }), +); +const endpoint = (args.endpoint ?? process.env.NMG_ENDPOINT ?? "").replace(/\/+$/, ""); +const key = args.key ?? process.env.NMG_API_KEY ?? ""; +const concurrency = Number(args.concurrency ?? 16); +const adds = Number(args.adds ?? 32); +const queries = Number(args.queries ?? 16); +if (!endpoint || !key) { + console.error("usage: node soak-endpoint.mjs --endpoint --key [--concurrency 16]"); + process.exit(2); +} + +const user = `soak-${Date.now().toString(36)}`; +const post = async (path, body) => { + const started = Date.now(); + try { + const response = await fetch(endpoint + path, { + method: "POST", + headers: { authorization: `Bearer ${key}`, "content-type": "application/json" }, + body: JSON.stringify(body), + signal: AbortSignal.timeout(150_000), + }); + return { status: response.status, ms: Date.now() - started, body: await response.json().catch(() => null) }; + } catch (error) { + // No status at all is the interesting outcome: it is the connection-level failure. + return { status: 0, ms: Date.now() - started, error: error?.cause?.code ?? error?.name ?? "unknown" }; + } +}; +const summarise = (label, results) => { + const byStatus = {}; + for (const result of results) byStatus[result.status] = (byStatus[result.status] ?? 0) + 1; + const times = results.map((result) => result.ms).sort((a, b) => a - b); + const errors = [...new Set(results.filter((result) => result.error).map((result) => result.error))]; + console.log( + `${label}: n=${results.length} statuses=${JSON.stringify(byStatus)} ` + + `p50=${times[Math.floor(times.length / 2)]}ms max=${times.at(-1)}ms` + + (errors.length ? ` connection_errors=${errors.join(",")}` : ""), + ); + return results.every((result) => result.status === 200); +}; + +// 1. Preflight, twice: the evaluation's first call is a health probe, and a cold instance is +// where it is most likely to be slow. +for (const attempt of [1, 2]) { + const started = Date.now(); + try { + const response = await fetch(`${endpoint}/health`, { signal: AbortSignal.timeout(60_000) }); + console.log(`health ${attempt}: ${response.status} ${Date.now() - started}ms`); + } catch (error) { + console.log(`health ${attempt}: FAILED ${error?.cause?.code ?? error?.name}`); + } +} + +const burst = async (makeRequest, count) => { + const queue = [...Array(count).keys()]; + const results = []; + await Promise.all( + Array.from({ length: concurrency }, async () => { + while (queue.length) { + const index = queue.shift(); + results.push(await makeRequest(index)); + } + }), + ); + return results; +}; + +// 2. Add phase. +const addResults = await burst( + (index) => + post("/add", { + user_id: user, + session_id: "soak", + request_id: `add-${index}`, + messages: [{ role: "user", content: `soak note ${index} about tide ${7000 + index}` }], + }), + adds, +); +const addOk = summarise("add", addResults); + +// 3. Search phase, top_k 100 like the harness. +const searchResults = await burst( + (index) => + post("/search", { + user_id: user, + query: `what did we record about the tide and the pier in note ${index}`, + top_k: 100, + }), + queries, +); +const searchOk = summarise("search", searchResults); + +if (!addOk || !searchOk) { + console.error("FAILED: at least one request did not answer 200"); + process.exit(1); +} +console.log(`PASS: ${adds} adds and ${queries} searches at concurrency ${concurrency}`); diff --git a/onlion/scripts/test-add-log-mode.mjs b/onlion/scripts/test-add-log-mode.mjs index 5207899b..2456b01d 100644 --- a/onlion/scripts/test-add-log-mode.mjs +++ b/onlion/scripts/test-add-log-mode.mjs @@ -98,6 +98,79 @@ try { ); } assert.equal(health.body.limits.add_mode, "log", "the fixture must run the log path"); + { + // A missing seventh argument is invisible at runtime: the signature defaults to null, the + // snapshot is re-uploaded on every CAS retry, and only a bucket listing shows it. The same + // reason the add-mode default is pinned here applies to a call-site argument. + const source = fs.readFileSync( + path.join(path.dirname(fileURLToPath(import.meta.url)), "../backend/worker.mjs"), + "utf8", + ); + assert.match( + source, + /async \(\{ sqlite, key, manifest, staged, reuse \}\)/, + "the search operation must receive the attempt's reuse map", + ); + assert.match( + source, + /options\.fullSnapshot \|\| env\.NMG_SEARCH_DELTAS === "0",[\s\S]{0,400}?reuse,/, + "stageSearchPart must be given the reuse map, or a retry re-uploads an identical snapshot", + ); + // The two budgets are what keep a request from being killed at the platform ceiling. A + // killed request loses the whole evaluation attempt, so their removal has to fail a test: + // the entry is durable before the fold, and a partial page is worth more than no answer. + assert.match( + source, + /const dueBySchedule =[\s\S]{0,240}?if \(dueBySchedule && Date\.now\(\) - startedAt < foldBudget\)/, + "the fold must be scheduled and budgeted; unbounded, a contended user folds past 120 s", + ); + // The root fix: an accept takes no compare-and-swap at all. Sixteen concurrent Adds on one + // user used to serialise on the manifest and lose twelve times each, redoing a megabyte of + // partition work per retry; that is what took a write from 0.5 s to 51-106 s. If a future + // edit routes the accept through `mutateUser` again, this fails. + { + const start = source.indexOf("async function acceptAdd(env, input) {"); + const end = source.indexOf("/** Folds waiting entries into the partition"); + const body = source.slice(start, end); + assert.ok(start > 0 && end > start, "acceptAdd must still exist"); + for (const forbidden of ["mutateUser(", "commitManifest(", "setPending("]) + assert.ok( + !body.includes(forbidden), + `accept must write nothing but its log entry; found ${forbidden}`, + ); + } + // And the read path must not trust a zero hint, or accepted data becomes invisible. + assert.ok( + !/async function pendingForSearch\(env, ctx, limit\) \{\s*if \(pendingCount\(ctx\.manifest\) === 0\)/.test( + source, + ), + "the pending read must not short-circuit on the hint", + ); + assert.match( + source, + /if \(Date\.now\(\) - started > searchDeadline\) \{\s*partial = true;\s*break;/, + "the partition loop must stop at a deadline and mark the page partial", + ); + assert.match(source, /partial,/, "the response must say whether the page is partial"); + // Spend is bounded per request, not per record: the fold's backfill must cap its batches, or + // one fold embeds a whole partition's backlog and is charged for it. + { + const service = fs.readFileSync( + path.join(path.dirname(fileURLToPath(import.meta.url)), "../backend/memory-service.ts"), + "utf8", + ); + assert.match( + service, + /syncRecordEmbeddings\(this\.store, this\.client, 32, \{ maxBatches: 1 \}\)/, + "both backfill call sites must cap their batches", + ); + assert.equal( + (service.match(/syncRecordEmbeddings\(this\.store, this\.client, 32\)/g) ?? []).length, + 0, + "the unbounded backfill form must not come back", + ); + } + } // I1: accepted Add is searchable before any fold. const first = await call( @@ -283,13 +356,12 @@ try { } } - // One search embeds every pending record and every query feature in a single call. - // The sequential version spent a round trip per text - thirty or more inside one - // search - which is how a slow provider ran into the invocation ceiling instead of - // costing a score. + // One search embeds every pending record in a single call, and its features in another. + // The sequential version spent a round trip per text - thirty or more inside one search - + // which is how a slow provider ran into the invocation ceiling instead of costing a score. { const batchUser = "batch-" + process.pid; - for (let index = 0; index < 6; index += 1) { + for (let index = 0; index < 4; index += 1) { const content = `batch marker ${index} records the tidepier${index} gauge reading`; const added = await call("/add", addBody(batchUser, `batch-${index}`, content)); assert.equal(added.status, 200, JSON.stringify(added.body)); @@ -301,26 +373,36 @@ try { top_k: 20, }); assert.equal(found.status, 200, JSON.stringify(found.body)); - // The record text is rendered (a date and role prefix may be added), so the marker - // token is what identifies it rather than the raw message content. + // The rendered record text may carry a date and role prefix, so the marker token identifies + // it. How many of the four are still pending depends on the fold schedule, which is a rate + // rather than a counter, so the count is not pinned here - the shape is: pending records + // reach the provider inside one call, not one call per record. + assert.ok( + embedCalls.some((inputs) => inputs.some((text) => /tidepier\d/.test(text))), + `pending records must reach the provider; saw ${embedCalls + .map((inputs) => inputs.length) + .join("/")}`, + ); assert.ok( - embedCalls.some((inputs) => inputs.filter((text) => /tidepier\d/.test(text)).length >= 6), - `pending records must be embedded in one batch; saw ${ - embedCalls.length - } calls with ${embedCalls.map((inputs) => inputs.length).join("/")} inputs`, + embedCalls.length <= 2, + `one batch per purpose; saw ${embedCalls.length} calls with ${embedCalls + .map((inputs) => inputs.length) + .join("/")} inputs`, ); } - // A search must embed its features in one call, not one call per feature. The engine asks - // for a single feature at a time, so the batch only helps if the cache is keyed by text - - // and against a provider across a region boundary, twenty-four round trips per search is - // the difference between a search that finishes and one that hits the invocation ceiling. + // A search embeds its features in one call, not one per feature: the engine asks for a single + // feature at a time, so the cache is keyed by text and the warm pass fetches them together. { const featureUser = "features-" + process.pid; for (let index = 0; index < 3; index += 1) { const added = await call( "/add", - addBody(featureUser, `feat-${index}`, `feature marker ${index} about harbour tide ${index}`), + addBody( + featureUser, + `feat-${index}`, + `feature marker ${index} about harbour tide ${index}`, + ), ); assert.equal(added.status, 200, JSON.stringify(added.body)); } @@ -331,8 +413,6 @@ try { top_k: 20, }); assert.equal(found.status, 200, JSON.stringify(found.body)); - // Two calls at most: the feature batch and the pending-record batch. Before the cache was - // keyed by text this was one call per feature plus one per pending record. assert.ok( embedCalls.length <= 2, `one batch per purpose; saw ${embedCalls.length} calls with ${embedCalls @@ -341,6 +421,40 @@ try { ); } + // The vectors travel with the entry, so the fold must not buy them again. The observable is the + // provider call count: an Add makes at most one call - its own inline embed - even when it is + // the Add that triggers a fold. Without the seed the fold would add a second call for the same + // text, which is the serialisation the whole change exists to remove. + { + const inlineUser = "inline-" + process.pid; + let worst = 0; + for (let index = 0; index < 24; index += 1) { + const before = embedCalls.length; + const added = await call( + "/add", + addBody(inlineUser, `inline-${index}`, `inline marker ${index} about the tide gauge`), + ); + assert.equal(added.status, 200, JSON.stringify(added.body)); + worst = Math.max(worst, embedCalls.length - before); + } + assert.equal( + worst, + 1, + `an Add must embed its own messages once and the fold must reuse them; saw ${worst} calls`, + ); + // The assertion above is only meaningful if a fold actually ran, so prove it did: some of the + // 24 entries are on disk and the backlog is smaller than the log. + const afterFolds = await call(`/capacity?user_id=${inlineUser}`); + assert.ok( + (afterFolds.body.sqlite_bytes?.used ?? 0) > 0, + "a fold must have written a partition during the loop", + ); + assert.ok( + (afterFolds.body.pending_entries ?? 99) < 24, + "a fold must have drained part of the log during the loop", + ); + } + // With a provider configured, the private status answers which endpoint and which vector // space are live - the question that had to be guessed three times during the 2026-10-29 // incidents. diff --git a/onlion/scripts/test-manifest-pending.mjs b/onlion/scripts/test-manifest-pending.mjs index 526cad16..e503d034 100644 --- a/onlion/scripts/test-manifest-pending.mjs +++ b/onlion/scripts/test-manifest-pending.mjs @@ -25,9 +25,12 @@ import { keyFor, loadManifest, manifestFormat, + newPart, pendingCount, + removeStaged, resetUser, setPending, + stageSearchPart, withPending, } from "../backend/storage.mjs"; @@ -36,7 +39,7 @@ import { * is first-create-only, and `list` pages with a stable key cursor so deleting * while paging behaves like COS/R2 (an index cursor would silently skip keys). */ -function createMemoryBucket() { +function createMemoryBucket({ maxDeleteKeys = Infinity } = {}) { const objects = new Map(); // key -> { body, etag } const stats = { puts: 0, deletes: 0, lists: 0 }; const etagOf = (body) => createHash("md5").update(body).digest("hex"); @@ -73,7 +76,12 @@ function createMemoryBucket() { return { key, etag, size: Buffer.byteLength(text) }; }, async delete(keys) { - for (const key of Array.isArray(keys) ? keys : [keys]) if (objects.delete(key)) stats.deletes++; + const list = Array.isArray(keys) ? keys : [keys]; + // R2 and S3 both cap a multi-object delete at 1000 keys; an oversized request + // fails as a whole rather than deleting what it can. + if (list.length > maxDeleteKeys) + throw new Error(`delete accepts at most ${maxDeleteKeys} keys, got ${list.length}`); + for (const key of list) if (objects.delete(key)) stats.deletes++; }, async list({ prefix = "", limit = 1000, cursor } = {}) { stats.lists++; @@ -363,7 +371,64 @@ assert.equal(logPrefix("abc123"), "users/abc123/log/"); console.log("PASS: a failed log cleanup reports incomplete and the same reset_id finishes it."); } +{ + // The provider caps a multi-object delete at 1000 keys. `staged ∪ reuse` can pass + // that for a wide user (one snapshot per part per attempt), and an oversized request + // fails as a whole - which the callers' catch turns into "cleanup succeeded, nothing + // removed". So the batch size is part of the contract, not an implementation detail. + const bucket = createMemoryBucket({ maxDeleteKeys: 1000 }); + const keys = Array.from({ length: 1500 }, (_unused, index) => `users/batch/parts/${index}.sqlite`); + for (const key of keys) await bucket.put(key, "snapshot"); + + await removeStaged(bucket, keys); + assert.equal(bucket.objects.size, 0, "a cleanup above the batch limit must still delete everything"); + assert.equal(bucket.stats.deletes, 1500); + + console.log( + "PASS: removeStaged batches at the provider limit — an oversized cleanup deletes instead of failing whole.", + ); +} + console.log( "PASS: manifest pending/lazy-v4/clearLog verified without a build — " + "empty log keeps today's bytes, pending log is v4, reset drains the log.", ); + +{ + // A search retry re-stages the partition it just uploaded. Passing `reuse` makes + // that free for identical content, and - the part that is easy to lose - it is how + // the abandoned attempt's snapshot stays reachable for cleanup after a later + // attempt commits. Without the argument the request still succeeds while uploading + // a whole snapshot per retry that no cleanup can name, so the assertion is on both + // effects of the same call. + const bucket = createMemoryBucket(); + const userKey = keyFor("search-reuse"); + const part = newPart("search-reuse"); + const snapshot = Buffer.from("nmg-part-v2 snapshot bytes"); + const resultOf = { snapshot, previousImage: null }; + const reuse = new Map(); + + const first = await stageSearchPart(bucket, userKey, part, resultOf, 0, true, reuse); + assert.equal(first.mode, "full_snapshot"); + assert.equal(bucket.stats.puts, 1, "the first staging uploads once"); + assert.ok( + [...reuse.values()].includes(first.stagedKey), + "a staged search snapshot must be registered so an abandoned attempt can be collected", + ); + + const second = await stageSearchPart(bucket, userKey, part, resultOf, 0, true, reuse); + assert.equal(second.stagedKey, first.stagedKey, "identical content reuses the upload"); + assert.equal(bucket.stats.puts, 1, "a retry with the same content must not upload again"); + + // The behaviour a caller gets by forgetting the argument: correct on the wire, + // duplicated on the bucket. Spelled out so the difference is visible in a diff. + const forgetful = createMemoryBucket(); + const forgotten = newPart("search-reuse"); + await stageSearchPart(forgetful, userKey, forgotten, resultOf, 0, true); + await stageSearchPart(forgetful, userKey, forgotten, resultOf, 0, true); + assert.equal(forgetful.stats.puts, 2, "without reuse every attempt uploads another snapshot"); + + console.log( + "PASS: a search staging call forwards reuse — identical content uploads once and the key stays registered for cleanup.", + ); +}