Writing

The layout audit spent 86% of its time waiting

The layout audit took 184 seconds to do 26 seconds of work. Loading several pages at once cut that to 112 seconds, and fixing one pasted argument cut it to 14.

7 min read

  • Testing
  • Playwright
  • Performance

This site refuses to let me commit a layout change until three browser harnesses pass. Each harness is a script that drives browsers through the site and checks the result. The slowest was the layout audit. It loads all eleven routes the site had at the time, at six viewport widths in two browser engines. On every render it looks for:

  • text drawn on top of other text
  • tap targets under 24×24
  • contrast below AA
  • clipped or absurdly narrow text

That’s 132 page renders, and it took 184 seconds.

I complained about it out loud, which is how I ended up measuring it.

Timing it

/usr/bin/time reports three figures. real is the wall-clock time, and user plus sys is the time the processor spent working.

real 184.04
user  19.92
sys    6.44

That’s 26 seconds of processor time inside 184 seconds of wall clock. The check spent 86% of its life waiting.

Adding concurrency

The obvious fix was concurrency, which means loading several pages at once. I tried that first, and it was the smaller half of the fix. The audit was written as three nested loops: for each engine, for each viewport, for each route. The order didn’t matter. The probe that measures each page only reads it, and one central list removes duplicate findings. So route six can’t care whether route five has finished.

I gave it workers. Four pages per viewport now pull routes off a shared queue. Both engines run at once instead of one after the other. They’re separate browser processes, and they share only a read-only static server.

real 112.47   ← was 184.04
user  22.83
sys    7.24

That’s 1.6 times faster. I’d expected more from going four-wide in two engines at once. For a minute I assumed I’d wired the concurrency wrong.

I hadn’t. If eight workers each spend most of their time waiting, running them together only overlaps the waits. Concurrency multiplies work, and this check had little work to multiply.

What it was waiting for

The cause was one argument in the navigation call. I’d copied it from another harness without reading it closely:

await page.goto(url, { waitUntil: 'networkidle' });

networkidle means Playwright, the library that drives the browsers, has seen 500 milliseconds of network silence. That’s a useful signal for a page that starts requests after load, like an app that fetches its content or a widget that appears late. This is a static site. A page needs only the HTML, the stylesheet and one font file. All of them are already in flight before the document has finished parsing.

So every navigation arrived and went quiet. Then the harness sat there for half a second, confirming that no more requests were coming. Across 132 navigations, that’s over a minute of the run spent waiting to be sure it had already finished.

The right signal is load, which fires once stylesheets and images are in, and those decide layout. domcontentloaded doesn’t wait for stylesheets, and it’s already caught me once. An unstyled page reported a finding that existed only because the CSS hadn’t arrived, in WebKit and nowhere else.

load doesn’t cover the font, and this audit needs it:

await page.goto(url, { waitUntil: 'load' });
await page.evaluate(() => document.fonts.ready);

Overlap, clipping, and narrow-measure findings are all measured in glyphs. A fallback face measures differently from Inter, so checking before the font swaps means checking a layout that no reader will ever see.

real 13.87   ← was 184.04
user  16.86
sys    5.31

Before and after

Wall Processor Idle
Original 184.0s 26.4s 86%
Concurrent 112.5s 30.1s 73%
Concurrent, load 13.9s 22.2s n/a
Where the time went
Original184.0s86% idle
Concurrent112.5s73% idle
Concurrent, load13.9sno idle

Each bar is wall time, on one scale. The shaded part is time the check spent idle. The last run has no idle figure, because it spread its work across cores and its processor time (22.2s) is higher than its wall time.

The audit got 13 times faster, and its processor time went down. I didn’t speed up any work, though. It’s the same 132 renders, with the same probe, doing the same work. I stopped asking it to wait.

Concurrency was worth 1.6×. The one-line change to the wait condition was worth 8.1× on top of that. I’d have gotten most of the win by reading the argument I’d pasted.

Checking that it still finds problems

I nearly skipped this step. A check that got 13 times faster but stopped finding things would be worse than a slow one: it would pass fast and look clean. Zero findings before and after only proves the two versions agree about a clean page, not that the fast one still sees a dirty one.

So I broke the site one defect at a time and made sure each one still got caught. The contrast, clipping and tap-target checks all fired. The overlap check didn’t, and overlap is the reason this audit exists. A page here once shipped with text stamped over text.

That took a minute to understand. My test was broken, and the check was fine. I’d made an element position: absolute to shove it onto its neighbor. That takes it out of the page’s flow and puts it somewhere else, not on top of anything. position: relative with a negative offset keeps the box in place and moves only the paint. That’s a real overlap, and the check reported it:

[chrome 834] /  overlap: h1 "We build and backsoftware companies."
                       ⨯ p.dek "Actium builds products in-house, co-foun" (15234px²)

That missing space is in the tool’s output, not a typo of mine. The headline has a <br /> in it, and textContent doesn’t invent whitespace where a line break was.

The overlap check fired in both engines. It named the element pair and the overlap area in square pixels.

If I’d trusted “0 findings, and much faster,” I’d have shipped a harness that was mostly a stopwatch. I wouldn’t have found out until something ugly reached production. The gates on this site open with unit tests of the gates themselves, for the same reason.

The other two harnesses

Both of the other harnesses had the same argument, because I’d pasted it into both. The screenshot matrix waits on 420 navigations. The behavioral suite reloads the page to prove the light edition survives a refresh.

So I changed the same word twice more:

Before After
Layout audit 184.0s 12.5s
Screenshot matrix 122s 82.7s
Behavioral suite 29.0s 13.6s

The After column is one run of all three harnesses, so the audit’s 12.5s differs from the 13.9s I got timing it alone.

The behavioral suite is the one that surprised me. It only visits a dozen pages, so I’d assumed its time was the interactions themselves. The interactions include pressing the Konami code, dropping the 404’s digits, and hovering a card and waiting out the transition. They took less than half of the suite’s time. The rest was the same half-second, over and over.

The matrix improved least, because it writes 420 full-page PNGs and encoding them takes processor time. Its processor time is now higher than its wall clock, which is what a busy check looks like.

Five and a half minutes of gate became one and three quarters on the site as it stood that week. The total creeps back up as pages get added, because the matrix covers every page. The waiting hasn’t come back.

I only found any of this because I got annoyed enough to time it, instead of assuming I already knew where the time went.

A day later, on four cores

All of those runs happened on my laptop. The same checks also run on GitHub. A nightly workflow rebuilds the site there and screenshots whatever published that day. It does that because a scheduled post goes live with nobody at a keyboard.

This post was a day old, and that workflow was two days old. An unrelated failure email had me reading GitHub’s logs at one in the morning, and I finally looked at the workflow’s timings.

The screenshot matrix that runs in 83 seconds here took 324 seconds there. It was the same commit, the same script and the same four workers per engine.

The difference was where it ran. A GitHub runner is a rented computer with four processor cores. I was putting eight pages on it at once, four per engine with both engines together. That’s the arrangement I’d just finished bragging about. My laptop has cores to spare for that. On four, eight busy pages mostly wait for a turn: Chrome needed 323 seconds and WebKit 285, side by side on the one runner.

So the workflow now rents two runners, one engine each. The script didn’t change:

check:visual one runner one per engine
chrome 323s 86s
webkit 285s 131s

Concurrency only multiplies work while there are idle cores to put it on.

Two more changes made the run cheaper rather than faster. The matrix writes a screenshot for every page at every width in both engines. That was 448 screenshots at the time, and the count grows with the site. I’d defended that cost as what a busy check looks like. On a runner, it’s busywork. Every passing screenshot is deleted unseen when the runner is returned.

So on GitHub, a page now gets photographed only at the moment it fails, and a clean run keeps none. Nothing changed here at my desk: the commit gate still demands the full set, because I’m the one who looks at them.

And most pushes stopped starting browsers at all. GitHub charges for these runners by the minute. My plan includes 3,000 minutes a month, and the account’s other repositories were already using half of them. The two-day-old workflow had burned 261 more, on pace for the cap by mid-August. At the cap, GitHub stops running workflows by default, including deploys and the nightly publisher.

The expensive part was commits that changed documentation. A markdown edit can’t break a browser, so a push that touches no page now skips both runners.

The commit that recorded these numbers in the repo’s work log changed one markdown file. For the first time since the workflow existed, no browser started.

All writing