Thirty Times an Hour, Around the Clock

Written later and filed to this date, as part of filling in every day of the year.

Two of the largest memory peaks in the journal had no pipeline behind them. Every crash that week had landed in the same stage of the news aggregator’s pipeline, the one that scores signals, so I had my culprit, and then the service manager’s record showed 3.1 gigabytes and 2.9 gigabytes at hours when the pipeline was idle.

The suspect

The aggregator runs a pipeline over its article store on a schedule, and a conductor I had just added to the box measured what that cost: a rest of 360 MB, a burst to between 4.1 and 4.7 GB in stage 8, and five out-of-memory kills in five days. The kills fed themselves. Only a successful run anchors the schedule, so every restart after a kill read as “overdue”, logged that it was catching up, and relaunched the run four seconds after boot, straight into the stage that had just killed it. Kill at 08:45, catch-up at 08:45:33, kill at 09:02, catch-up at 09:02:39, kill at 09:08. The scheduler’s own docstring counted “runs kept dying” as a reason to catch up.

That stage had real waste in it. It held every article in a two-week window as a full database row, bodies and joined sources included, for the whole build: 6,786 rows, about 300 MB of text. Three of its signals each kept a private copy of the same 328 MB cross-encoder, a gigabyte of identical weights. The stage explained the kills. It did not explain two peaks on a quiet afternoon.

What was reading

The only traffic in those windows was one article page, then that article’s related list, every one to three minutes, from one address range, through the public viewer. A crawler, walking the site the way crawlers do: every page, then every link on every page.

The related endpoint, and the search endpoint beside it, answered a request by loading every article in the thirty-day retention window as a full row, source and cluster joined, to compute a cosine over each row’s 1.5 KB embedding. That is 10,533 rows and 548 MB of text, read in full, to compare vectors that together would fit in sixteen megabytes. About a gigabyte allocated per call. The crawler called it about thirty times an hour, around the clock, and any one of those calls landing while signal scoring was already at three gigabytes was the difference between a busy afternoon and a kill.

I had written that endpoint for a person. A person opens an article, maybe clicks “related” once, reads, closes the tab. A gigabyte for one click is wasteful, but it is one click, and on a quiet afternoon the box has a gigabyte to spare. Nothing on the open web clicks once. The crawler was not misbehaving. It was asking the question the page invites, as often as the page would answer it, and the page had been built as if that question would only ever be asked by someone with a reason to stop.

The fix is the obvious one

The candidate read is now the id and the embedding and nothing else. One matrix-vector product ranks the window, and full rows are loaded for the winners alone: 38 MB peak on the live window. A covering index over the fetch date, the id and the embedding lets the database serve that read without walking past the bodies, which took the candidate scan from 2.6 seconds to 55 milliseconds on a copy. The ORM’s create-everything call never adds an index to a table that already exists, so startup now creates the declared indexes itself, three seconds once and a no-op after. Two tests count the article objects the ORM materializes per request, and both fail on the old code with a number in the thousands.

The stage got its own repairs in the same quarter hour: it streams the window in batches of 256 rows and keeps only the tables it builds, and the three signals share one copy of the model. A run the process died in now makes the next startup wait an hour before catching up; a clean restart still catches up at once.

Measuring without causing the outage

The old code could not be measured at full scale where it ran. The box had 2.3 GB available and its swap was 98 percent full, so running the old stage 8 against the live store would have been the outage I was trying to understand. Each probe ran on a backup copy of the database under a 2.5 GB address-space limit, old code against new, and the live service was measured only after the deploy, through its own memory accounting: 599 MB before nine related-list calls, 628 MB after.

Nothing about the crawler changed. It is still asking for the related list thirty times an hour, and by that count each answer now costs it about three megabytes, which is roughly what a reasonable question should cost. It had been asking a reasonable question the whole time.


← all writing