A third of my request was the garbage collector

The rostering app I maintain has a grid that shows a whole organisation’s shifts for a quarter. On live it took 1.1 to 1.5 seconds to load, and the app logs anything over 500 ms as a slow grid, so I spent a morning on it. The obvious suspects were the obvious ones: queries, and the Python that turns rows into cells. Both were guilty. But after a first round of fixes to those, the biggest remaining cost was somewhere I’d never have looked.

I measured it on a local copy of live: one running worker, warmed up with a single untimed load, then nine timed loads of that quarter grid, taking the median. Before each timed load I cleared the app’s roster cache, so the grid was rebuilt from the database every time. That’s what “cold” means in this post: the cache was empty, not the process. Python can tell you when its collector runs: gc.callbacks calls a function at the start and end of every collection, so one line records them all:

gstat = []
gc.callbacks.append(lambda ph, info: gstat.append((ph, info["generation"], time.perf_counter())))

Pairing each start with its stop gives the time spent collecting. Python’s cyclic garbage collector took 143 ms of a 463 ms request. A third of the work was the collector, and it found almost nothing to collect.

Re-checking objects that never die

In CPython 3.12, which this app runs, most objects are freed by reference counting, the moment nothing points at them. The cyclic garbage collector exists for the rest: objects that point at each other in a loop, which reference counting can never free. To find those it walks the objects it tracks, and it’s generational, so anything that survives a few collections moves into an older generation that’s scanned less often, but still scanned.

A Flask app with SQLAlchemy builds a lot at startup: the app itself, every model class, every mapper. In this app the collector was tracking 134,195 objects, nearly all of which live as long as the worker does. The collector doesn’t know that. Every full collection walked them all again, looking for garbage among objects that would never be garbage.

The younger passes added up too. The default threshold triggers a young collection every 700 net allocations of tracked objects, and building a quarter’s worth of grid cells allocates a great deal: 291 young collections, 27 middle and 3 full in a single load.

The fix is three lines, run once the app has finished importing:

gc.collect()
gc.freeze()
gc.set_threshold(20000, 10, 10)

gc.collect() goes first so that startup’s own garbage is freed rather than kept. gc.freeze(), in the standard library since Python 3.7, moves every object currently tracked by the collector into a permanent generation that future collections ignore. The larger first threshold makes young collections far rarer.

The same measurement, one step at a time:

Freezing did most of the work on its own, with the same number of young collections, because the expensive part was re-walking the frozen objects. The next setting I tried, 50000 with the older generations raised from 10 to 20, got the collector down to 12 ms and the request to 342: four milliseconds more. I took 20000 because it had already cut young collections from 291 to 6 and left the older generations at their defaults. I didn’t measure memory for any of these.

The collector is tuned, not switched off, and freezing has a cost worth knowing. A frozen object is never examined by cyclic collection again, so if a frozen cycle later becomes unreachable, it won’t be reclaimed while it stays frozen. That’s why this runs once, as each worker finishes importing the app, on a graph that’s meant to live for the worker’s lifetime. It isn’t something I’d run after arbitrary requests.

The second surprise was reading a field

The other big win, from the first round, was smaller per call and paid on a lot more calls. The grid’s read paths fetched SQLAlchemy Row objects, and reading an attribute off a Row goes through __getattr__: about 0.3 microseconds on the live server’s class of CPU. Reading a field off a namedtuple is a C slot, about 0.04. The grid reads around 40 fields per row, across about 12,000 rows in a quarter.

So the shared fetch now hands back plain named tuples:

_LightRow = namedtuple("_LightRow", [c.key for c in _ASSIGN_COLS])


def assignment_rows(session, staff_ids, lo, hi):
    return [_LightRow._make(r) for r in
            session.query(*_ASSIGN_COLS)
            .filter(Assignment.staff_id.in_(staff_ids),
                    Assignment.date >= lo, Assignment.date <= hi)]

One function that works out each person’s effective shift went from 50 ms to 7 ms over a quarter, on that change alone. The tuples are read-only, which suits the read paths, and the write paths still load full entities, because they edit rows and need the ORM to notice.

The rest was ordinary: one query where there had been 96, rows fetched once per request and reused instead of eight times, and shift times worked out only for the days that could matter.

Checking the roster stayed the same

A faster grid that shows a different roster is worse than a slow one, so every round had to pass one check: the grid’s JSON for six real views (two different users’ screens, across whole quarters and single months) had to be byte-for-byte identical to the old build’s, compared by hash on a snapshot of live. They were, after every round, and the existing suite still passed. Six matching outputs aren’t proof that nothing changed anywhere, but across real data they’re strong evidence that the roster didn’t. It’s the same check I leaned on when moving this app’s scripts out of its templates.

The garbage-collector settings got their own test, because they’re exactly the kind of three lines a later tidy-up removes without anyone noticing:

check("1a the boot objects are frozen out of the collector's scan (tens of thousands)",
      gc.get_freeze_count() > 50_000, str(gc.get_freeze_count()))
check("1b the young-generation threshold is 20000, older generations unchanged",
      gc.get_threshold() == (20000, 10, 10), str(gc.get_threshold()))
check("1c the collector is still ON - tuned, never disabled", gc.isenabled())

That’s a configuration check, not a performance one. It fails if the settings disappear or change; it says nothing about whether the collector stays cheap or memory stays where it should. Those still need measuring when the app grows.

What it added up to

Across all three rounds, on the same local copy of live and the same cold-load method, the widest view, a whole quarter, went from 684 ms to 278 ms, and every view I timed was about two and a half times faster. The table above sits partway along that line. Its 463 ms baseline was taken after the first round, and the 346 ms was an experiment before the second. The second round shipped these settings together with the rows reused per request and a single load of the shift codes, and the third trimmed the shift-time work to the days that mattered. Those took the same view the rest of the way to 278.

Live told the same story with less precision, from the slow-grid log. On the morning before the change, 18 grid loads crossed the 500 ms line, the slowest at 1,153 ms. In the 19 hours after, three did, the slowest at 649 ms. Those windows aren’t like for like, since the second covered an evening and a weekend, but the slow loads didn’t just get fewer, they got shorter.

If your Python web app builds a big object graph at startup and then serves requests, it’s worth finding out how much time the collector spends re-walking it. Measure first, with gc.callbacks, because this only pays when the graph is large. But when it is, three lines after startup stop the collector re-checking objects that were never going to die.