DEV Community

Daniel Pertu
Daniel Pertu

Posted on

1,250,964 audit rows recording that nothing happened

Munchable's ingredient curation job walks a backlog of words it has read off food labels and cannot yet place: a spelling it has not seen, a regional name, a translated fragment. For each one it either reaches a decision, alias this to an existing id, create a new id, mark it noise, reject it, or it reaches no decision and moves on.

Every one of those outcomes was written to a ledger table, because an audit trail for automated curation is obviously correct. Including the last one. Especially the last one, I remember thinking: I want to know what it looked at and could not resolve.

Here is what that produced, on a database with a 0.5 GB quota:

rows
decisions (alias, new, noise, rejected) 51,884 the audit trail
skips 1,250,964 302 MB of tuples, 418 MB with indexes

Twenty-four skip rows for every real decision. The table recording what our curation did was 96% a record of it doing nothing.

How you write 1.2 million rows about nothing

The job ran every 15 minutes for four days. Before it had a marker recording which version of the deterministic pass had already examined a word, each run re-examined the same roughly 7,000 unreadable slugs, could not place any of them again, and wrote 7,000 fresh skip rows.

That is 96 runs times 7,000 words, and the arithmetic lands almost exactly where the row count did.

No single part of this is a bug. The job is correct. The ledger write is correct. The scheduling is correct. The failure is in the composition: a non-idempotent write inside a loop over an unchanging input set, which is a shape that shows up in almost every recurring job that has not been explicitly designed against it. It stayed invisible because every individual run looked completely normal in the logs, and got noticed because the database ran out of room.

A skip is a state, not an event

The real mistake is upstream of the disk. I had conflated two things that look similar in an audit trail and are not the same:

  • A decision is an event. Something changed, at a time, for a reason. It happened once and the record of it is the only evidence it happened.
  • A skip is a state. This word is still unplaced. It was unplaced before the run and it is unplaced after. Nothing happened.

Writing a row per observation of an unchanged state is not an audit log, it is a poll log, and a poll log's size is a function of your cron interval rather than of anything about your data. Mine was set to fifteen minutes by a judgement about curation throughput, and it turned out to be, accidentally, the parameter controlling how fast the database filled up.

The state was also already stored. The backlog row for each word carries a proposed count, the number it was last skipped at, which is the thing the curation job actually reads when deciding what to look at next. The ledger rows were a second, far more expensive copy of information the system already had in the right place.

So the fix in the job is one deletion: it no longer ledgers skips at all. Nothing in the request path ever read the ledger, and nothing else needed those rows.

Deleting them on a disk that is already nearly full

The cleanup is a small operator-run script, and both of its interesting decisions come from the disk being close to the limit at the moment you want to reclaim space, which is the only moment anybody ever runs this.

Batched deletes, each its own commit:

const BATCH = 100_000;
for (;;) {
  const r = await sql.unsafe(
    `delete from catalog.taxonomy_ledger where id in (
       select id from catalog.taxonomy_ledger where decision = 'skip' limit $1)`,
    [BATCH],
  );
  deleted += r.count;
  if (r.count < BATCH) break;
}
Enter fullscreen mode Exit fullscreen mode

One DELETE of 1.25 million rows is one transaction, holding one enormous chunk of WAL, on a disk that has no room for it. Batching does not make the delete faster. It makes it fit.

VACUUM FULL, and the counter-intuitive reason it is safe here:

A DELETE only marks tuples dead. Space is not returned to the operating system, and on a managed plan the quota keeps counting them. VACUUM FULL rewrites the table with only its live rows, and this is the bit worth internalising: it needs free disk for the compacted size, not for the current size. About 20 MB here, not 418 MB.

That inverts the intuition that you cannot vacuum your way out of a full disk. You often can, precisely when the table is mostly dead rows, which is precisely when you want to. It takes an exclusive lock for a few seconds, and in this case the only writer is an operator-run job, so there was nothing to coordinate with.

The script defaults to a dry run that prints the counts and sizes and touches nothing. --apply is the flag that deletes. For anything that removes a million rows, the dangerous path gets the flag, never the safe one.

What I would check in your codebase

Two questions, both cheap:

  1. Does any recurring job write a row when it decides not to act? If yes, the table's growth rate is set by your scheduler rather than by your users, and it will outrun everything else you store.
  2. Can the job tell it has already examined this input? A version marker on the input row is enough. Ours now has one, and it is what stops the re-examination loop that made the volume possible in the first place. The ledger change removed the symptom; the marker removed the cause.

The wider rule I now apply to this database: an audit-style table must have something bounding it, either a retention policy or a shape that only grows with real events. Unbounded growth is a property to design against explicitly, not something to notice later from a quota alert.

This was the second of two size problems I worked through in the same week. The other one is a better story about data modelling than about operations: 45% of our stored ingredient tags were derivable, so we deleted them. And the curation pipeline that produces these ledger rows in the first place is built so that a model can propose but never decide, which I wrote up in AI proposes, the engine disposes.

The 51,884 rows that were worth keeping

The decisions that survived the cleanup are what turns a word printed on a pack into an id the rules engine can score, which is the difference between the app answering your question and shrugging at it. You can see the far end of that pipeline here:

The app itself is at munchable.app, now with 418 MB more room to grow into.

Top comments (0)