diff --git a/CHANGELOG.md b/CHANGELOG.md index 9e8a94d..1fb0df2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,54 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.1.0/). ## [Unreleased] +### Fixed — the write batch was tied to the embed batch, and they want opposite things + +Moving the vector store to Postgres made `code_symbol_embed` go **38 min → 65 min** on +a full rebuild. One number governed both the embedding and the write, which cost +nothing while ChromaDB's write was a local file and cost a great deal once it was a +statement over a network. + +The two constraints are opposed. Embedding is memory-bound: the ONNX model pads every +document to 256 tokens, so activations are sized by the batch — 967 MiB at 200 against +415 MiB at 8, and an unbounded batch is what SIGKILLed the worker. Writing is +round-trip-bound. Measured against the production database with the embedder stubbed +out, 800 rows: + + batch= 8 16.67 s (100 round-trips, ~167 ms each) + batch=100 2.31 s ( 8 round-trips) + batch=400 1.92 s ( 2 round-trips) + +A fixed ~167 ms per statement, paid **3 196 times** over a full rebuild. `PGVECTOR_WRITE_BATCH_SIZE` +now defaults to 100 and the embed batch stays at 8; measured end to end on the same +800 rows, 13.89 s → 2.96 s, with ranking unchanged to four decimal places +(0.2234 / 0.7867 / 1.0161). + +**HNSW maintenance was the first suspect and is not the cause** — worth recording, +because it is the plausible answer. Measured server-side, 8 000 rows of 384 dimensions +cost 1 376 ms with no index against 12 348 ms with one: 9× per row, but only ~44 s +across the whole corpus, nowhere near the tens of minutes observed. Batching the write +would have been the wrong fix if the index had been the cause, and the right one only +because it was not. + +`repo_index_job_timeout_seconds` follows the measurement to **21600**: the pgvector +rebuild measured 15 051 s end to end (15:52 → 20:02 on 2026-08-28, chained code↔DB +sync included), against 12 039 s on ChromaDB. The write fix should bring that down and +has not yet been re-measured end to end, so the ceiling is sized from the number that +was measured rather than the one expected. + +### Verified — the store survives the event that used to empty it + + before restart 34 038 vectors, visible to a fresh one-off dyno + restart both dynos + after restart 34 038 vectors — handle.count() = 34 038, force_full would not fire + +Both halves matter. Surviving the restart is the fix; being visible to a *different* +dyno is the half ChromaDB could never do, because `web` and `worker` hold separate +filesystems. The full rebuild reached `pipeline_end`, the checkpoint was deleted (which +only happens on success), and the chained sync ran on its own — `code_db_sync` +20:01:51 → 20:02:51. Map after: 136 matched / 97 db_only / 23 code_only / **0 mismatch**. + + ### Fixed — the vector store lived on a disk that is wiped on every restart `CHROMA_PERSIST_DIR` is `/app/data/chroma`: the Heroku container filesystem. It does diff --git a/backend/.env.example b/backend/.env.example index 31560a8..f8d698e 100644 --- a/backend/.env.example +++ b/backend/.env.example @@ -180,6 +180,13 @@ CORS_ORIGINS=["http://localhost:3000","http://localhost:3100","https://checkmyda # deliberate no-op, and asking for pgvector there fails at start-up saying so. # Embeddings are unchanged either way (ONNX all-MiniLM-L6-v2, 384-d). # VECTOR_STORE_BACKEND=chroma +# How many embedded rows go to Postgres in one statement (pgvector backend only). +# Deliberately SEPARATE from EMBEDDING_UPSERT_BATCH_SIZE: embedding is memory-bound +# and must stay small (967 MiB at 200 vs 415 MiB at 8), writing is round-trip-bound. +# Measured against production with the embedder stubbed, 800 rows: 16.67 s at 8, +# 2.31 s at 100, 1.92 s at 400 — a fixed ~167 ms per statement. 100 takes most of the +# win; past it the curve is flat and only the buffer grows. +# PGVECTOR_WRITE_BATCH_SIZE=100 # CHROMA_PERSIST_DIR=./data/chroma # Remote ChromaDB. Set this to move the vector index OUT of the app process: with it # unset, an embedded PersistentClient keeps the HNSW graph in memory and the files on diff --git a/backend/app/config.py b/backend/app/config.py index dbd307f..448d033 100644 --- a/backend/app/config.py +++ b/backend/app/config.py @@ -111,6 +111,15 @@ def _fix_database_url(self) -> "Settings": # Default is still "chroma" so the switch is a deliberate flip on a verified # deployment rather than a side effect of deploying this change. vector_store_backend: str = "chroma" + # How many embedded rows go to Postgres in one statement. Separate from + # `embedding_upsert_batch_size` because the two pull in opposite directions and + # only shared a number while ChromaDB's write was local and free: embedding is + # memory-bound (967 MiB at 200 against 415 MiB at 8), writing is round-trip-bound. + # Measured against production with the embedder stubbed, 800 rows: 16.67 s at 8, + # 2.31 s at 100, 1.92 s at 400 — a fixed ~167 ms per statement, paid 3 196 times + # over a full rebuild when the two were tied. 100 takes most of the win; beyond it + # the curve is flat and the buffer only grows. + pgvector_write_batch_size: int = 100 chroma_persist_dir: str = "./data/chroma" chroma_server_url: str = "" chroma_embedding_model: str = Field( @@ -558,7 +567,13 @@ def _fix_database_url(self) -> "Settings": # 69 s embed_and_store + bm25 + the chained sync # 12039 s = 3.34 h # - # 16200 s leaves 35 % over that. Both dominant steps scale with repository size + # 2026-08-28: the store moved to pgvector and that number moved with it. The same + # rebuild measured 15 051 s end to end (15:52 -> 20:02, chained sync included), + # because `code_symbol_embed` went 38 min -> 65 min — the write batch was tied to + # the embed batch, paying a fixed ~167 ms per statement 3 196 times. Fixed via + # `pgvector_write_batch_size` (4.7x on the database path, measured), but not yet + # re-measured end to end, so this is sized from the number that WAS measured: + # 21600 s leaves 43 % over 15 051. Both dominant steps scale with repository size # rather than with a clock, so the headroom is not decoration. # # It cut off three runs before it was sized: 1800.02 s inside `code_symbol_embed`, @@ -578,7 +593,7 @@ def _fix_database_url(self) -> "Settings": # Invariant, asserted in `tests/unit/services/test_repo_index_ceiling.py`: this # stays below `daily_knowledge_sync_job_timeout_seconds`, which contains it plus # a DB index plus a code↔DB sync. - repo_index_job_timeout_seconds: int = 16200 + repo_index_job_timeout_seconds: int = 21600 # F-SCHED-07: how long a `running` batch may sit before another attempt may take # its claim. `run_batch` inherits ARQ's class-level `job_timeout` (1800 s), so past diff --git a/backend/app/knowledge/pgvector_store.py b/backend/app/knowledge/pgvector_store.py index 19988e3..c0c2634 100644 --- a/backend/app/knowledge/pgvector_store.py +++ b/backend/app/knowledge/pgvector_store.py @@ -142,46 +142,80 @@ def add_documents( ) -> None: if not doc_ids: return - # AUD-0819-01 carried over: the batch handed to one embed call decides peak - # memory, because the ONNX model pads every document to 256 tokens and its - # activations are sized by the batch and nothing else. Measured at 967 MiB - # for 200 and 415 MiB for 8; an unbounded batch is what SIGKILLed the worker. - step = max(1, settings.embedding_upsert_batch_size) + # TWO batch sizes, because embedding and writing pull in opposite directions + # and used to share one number only because ChromaDB's write was local and free. + # + # Embedding is memory-bound: the ONNX model pads every document to 256 tokens, + # so the transformer's activations are sized by the batch and nothing else — + # 967 MiB at 200 against 415 MiB at 8, and an unbounded batch is what SIGKILLed + # the worker (AUD-0819-01). That number must stay small. + # + # Writing is round-trip-bound. Measured against the production database with + # the embedder stubbed out, 800 rows: + # + # batch= 8 16.67 s (100 round-trips, ~167 ms each) + # batch=100 2.31 s ( 8 round-trips) + # batch=400 1.92 s ( 2 round-trips) + # + # A fixed ~167 ms per statement dominates completely, and tying the write to + # the embed batch paid it 3 196 times over a full rebuild. HNSW maintenance was + # the first suspect and is not the cause: measured server-side, 8 000 rows cost + # 1 376 ms with no index and 12 348 ms with one — 9x, but only ~44 s across the + # whole corpus, not the tens of minutes observed. + embed_step = max(1, settings.embedding_upsert_batch_size) + write_step = max(embed_step, settings.pgvector_write_batch_size) + + buf_ids: list[str] = [] + buf_docs: list[str] = [] + buf_meta: list[str] = [] + buf_vecs: list[str] = [] + + def _flush(conn: Any) -> None: + if not buf_ids: + return + conn.execute( + """ + INSERT INTO doc_embeddings + (project_id, id, document, metadata, embedding, updated_at) + SELECT %s, u.id, u.document, u.metadata::jsonb, u.embedding, now() + FROM unnest(%s::text[], %s::text[], %s::text[], %s::vector[]) + AS u(id, document, metadata, embedding) + ON CONFLICT (project_id, id) DO UPDATE + SET document = EXCLUDED.document, + metadata = EXCLUDED.metadata, + embedding = EXCLUDED.embedding, + updated_at = now() + """, + (project_id, buf_ids, buf_docs, buf_meta, buf_vecs), + ) + buf_ids.clear() + buf_docs.clear() + buf_meta.clear() + buf_vecs.clear() + with self._pool.connection() as conn: - for start in range(0, len(doc_ids), step): - end = start + step + for start in range(0, len(doc_ids), embed_step): + end = start + embed_step chunk_docs = documents[start:end] chunk_ids = doc_ids[start:end] chunk_meta = ( metadatas[start:end] if metadatas is not None else [{}] * len(chunk_ids) ) vectors = self._embed(chunk_docs) - conn.execute( - """ - INSERT INTO doc_embeddings - (project_id, id, document, metadata, embedding, updated_at) - SELECT %s, u.id, u.document, u.metadata::jsonb, u.embedding, now() - FROM unnest(%s::text[], %s::text[], %s::text[], %s::vector[]) - AS u(id, document, metadata, embedding) - ON CONFLICT (project_id, id) DO UPDATE - SET document = EXCLUDED.document, - metadata = EXCLUDED.metadata, - embedding = EXCLUDED.embedding, - updated_at = now() - """, - ( - project_id, - chunk_ids, - chunk_docs, - [json.dumps(m or {}) for m in chunk_meta], - [str(v) for v in vectors], - ), - ) + buf_ids.extend(chunk_ids) + buf_docs.extend(chunk_docs) + buf_meta.extend(json.dumps(m or {}) for m in chunk_meta) + buf_vecs.extend(str(v) for v in vectors) + if len(buf_ids) >= write_step: + _flush(conn) + _flush(conn) + logger.debug( - "PgVectorStore: upserted %d documents for project %s in batches of %d", + "PgVectorStore: upserted %d documents for project %s (embed %d, write %d)", len(doc_ids), project_id, - step, + embed_step, + write_step, ) def query( diff --git a/backend/tests/unit/docs/test_suppression_debt_ratchet.py b/backend/tests/unit/docs/test_suppression_debt_ratchet.py index 4cc5b8b..753feef 100644 --- a/backend/tests/unit/docs/test_suppression_debt_ratchet.py +++ b/backend/tests/unit/docs/test_suppression_debt_ratchet.py @@ -52,11 +52,17 @@ # this red. That friction is the point — every one of those raises is a sentence # somebody had to write — but a burst of five parallel PRs makes it feel like noise # rather than a decision, and it should be read as the latter. - # 2026-08-28, both raised by one: `PgVectorStore.close()` swallows a pool-close - # failure (the store is being torn down; raising there would mask whatever was - # actually being shut down), and `app/models/__init__.py` gained - # a `DocEmbedding` re-export carrying the same unused-import suppression every one - # of the other forty imports in that file already carries — convention, not debt. + # 2026-08-28: `except Exception` raised by one for `PgVectorStore.close()`, which + # swallows a pool-close failure — the store is being torn down, and raising there + # would mask whatever was actually being shut down. + # + # `# noqa` 128 -> 129: `app/models/__init__.py` gained a `DocEmbedding` re-export + # carrying the same unused-import suppression the other forty-two imports in that + # file already carry. Convention, not debt. + # + # A SECOND one was added and then deleted — a suppression on an inner function's + # untyped argument, where annotating it cost one word. That is the answer this + # ratchet exists to provoke, and it is why the raise here is one rather than two. "except Exception": 614, "except ...: pass": 53, "# type: ignore": 49, diff --git a/backend/tests/unit/knowledge/test_pgvector_store.py b/backend/tests/unit/knowledge/test_pgvector_store.py index 9aa7259..c5bad7c 100644 --- a/backend/tests/unit/knowledge/test_pgvector_store.py +++ b/backend/tests/unit/knowledge/test_pgvector_store.py @@ -156,6 +156,43 @@ def test_an_unknown_backend_is_refused(self, monkeypatch) -> None: make_vector_store() +class TestTheTwoBatchSizesAreSeparate: + """They pull in opposite directions and shared one number only because ChromaDB's + write was local and free. + + Embedding is memory-bound — the ONNX model pads every document to 256 tokens, so + activations are sized by the batch: 967 MiB at 200 against 415 MiB at 8, and an + unbounded batch is what SIGKILLed the worker. Writing is round-trip-bound: measured + against production with the embedder stubbed, 800 rows took 16.67 s at batch 8 and + 2.31 s at 100 — a fixed ~167 ms per statement, paid 3 196 times over a full rebuild + while the two were tied. That is why `code_symbol_embed` went 38 min to 65 min when + the store moved to Postgres. + + HNSW maintenance was the first suspect and is not the cause: server-side, 8 000 rows + cost 1 376 ms with no index against 12 348 ms with one — 9x, but only ~44 s across + the whole corpus. Worth recording, because it is the plausible answer and it is the + wrong one. + """ + + def test_the_write_batch_has_its_own_setting(self) -> None: + from app.config import Settings + + assert "pgvector_write_batch_size" in Settings.model_fields + assert Settings.model_fields["pgvector_write_batch_size"].default == 100 + + def test_the_write_batch_is_never_smaller_than_the_embed_batch(self) -> None: + """A write smaller than an embed would flush mid-chunk for no gain — and the + floor is what makes an operator lowering the write batch harmless rather than + a silent slowdown.""" + source = inspect.getsource(pgv.PgVectorStore.add_documents) + assert "max(embed_step, settings.pgvector_write_batch_size)" in source + + def test_both_caps_are_read_at_the_call(self) -> None: + source = inspect.getsource(pgv.PgVectorStore.add_documents) + assert "embedding_upsert_batch_size" in source + assert "pgvector_write_batch_size" in source + + def test_the_batch_cap_still_governs_the_embed_call() -> None: """`EMBEDDING_UPSERT_BATCH_SIZE` was cut 200 -> 8 because the ONNX model pads every document to 256 tokens and its activations are sized by the batch: 967 MiB for 200 diff --git a/backend/tests/unit/services/test_repo_index_ceiling.py b/backend/tests/unit/services/test_repo_index_ceiling.py index a86dc24..100fb9b 100644 --- a/backend/tests/unit/services/test_repo_index_ceiling.py +++ b/backend/tests/unit/services/test_repo_index_ceiling.py @@ -76,7 +76,15 @@ #: #: NOT the cron's 42.4-minute run, which is an incremental index with the chain off #: and was the mis-reading this file exists to correct. -MEASURED_FULL_REBUILD_SECONDS = 12039 +MEASURED_FULL_REBUILD_SECONDS = 15051 +# +# 2026-08-28: 12 039 s was the ChromaDB path, which is no longer the path production +# runs. On pgvector the same rebuild measured **15 051 s** end to end (15:52 -> 20:02, +# chained code↔DB sync included), because `code_symbol_embed` went 38 min -> 65 min: +# the write batch was tied to the embed batch, so a fixed ~167 ms per statement was +# paid 3 196 times. That is fixed (`pgvector_write_batch_size`, measured 4.7x on the +# database path), but the fixed number has not yet been re-measured end to end — so +# the ceiling is set from what IS measured, not from what the fix should achieve. _DEFAULTS = Settings.model_fields