intertwingly

My last post argued that Campfire's shared benchmark, one viewer asking for the same pages as fast as it can, rewards a whole-page cache that a busy chat server may rarely hit, and proposed measuring many people instead. I've now built that benchmark and run it against Campfire on Rails. Most of what it found isn't specific to Campfire, so this post is about what a Rails developer can take from it. The short version:

1. A cache that hits on every request in a benchmark can hit on almost none in production.
2. Look at what's actually in your fragment cache keys.
3. Computing a cache key can cost more than the render it saves.
4. Action Cable can process one connection's commands out of order, and your users pay for it at the 99th percentile.

Three pull requests to Campfire came out of this. Together they take the room page from 46 ms to 11 ms at the median, at half the server CPU.

What the benchmark does

The load is people, not requests. Each simulated person has their own account and session, holds a WebSocket with the subscriptions a real page makes, and navigates about every ten seconds: opening a room (55%), scrolling back through history (20%), searching (10%) or returning to a room they had open (15%). Each person posts about every five minutes, into rooms weighted by where they're a member. There are 5,000 accounts and 30 rooms, with membership skewed so that a few rooms are busy and most are quiet, as in a real deployment.

Every response is checked, not just timed: the page is for the right user, every message on it belongs to that room, the sidebar lists only rooms the user belongs to, and the newest acknowledged post is there. Every post must reach every person viewing that room, and at the end every acknowledged write is checked against the database.

The run adds people in steps (250, 500, 1,000, 2,000, 3,000), one minute each after a warmup. A step counts as served if 99% of navigations complete within 100 ms, none fail, and 99% of messages reach their viewers within 500 ms. That's a strict target, chosen so that "served" means a page that feels instant, not merely one that eventually loads.

Setup, so the numbers can be read in context: an 8-core Ryzen 7 with Ruby head. The server gets four cores (eight threads), and the load generator gets the other four. The generator reports its own CPU at every step, and it never used more than about half of one core, with timer lag around one millisecond. Both still share one machine's cache and memory bandwidth, so moving the generator to a second machine is on the list. Each configuration ran three times, and every number below is the median of three, with the run order alternated so that no lane always goes first.

The generator is on a branch of my fork of Campfire's shared verification harness (loadgen users). I'd like it to land in the shared harness, so that every implementation can be measured this way.

Your cache may not be hitting

Campfire puts a whole-page cache in front of its room, messages, sidebar and search pages, keyed per viewer and cleared by any database commit. With one viewer it hits on every request after the first.

To see what it does under real load, I first had to be able to see it at all, so the first pull request, #411, reports cache use in the Server-Timing header:

Server-Timing: page;desc="miss", records;desc="hits=2 misses=0", fragments;desc="hits=38 misses=2"

Browsers show that header in their network panel, and a load generator can tell a hit from a render without guessing from timings.

With 250 people the page cache's hit rate was effectively zero. The reason is simple once you can see it: in Campfire, visiting a room is itself a write. The presence channel records that you're there, and refreshes it every 50 seconds. With hundreds of people moving around, something commits several times a second, every commit clears the cache, and the same viewer almost never asks for the same page between two commits.

I tried the obvious fix as an experiment first, making presence writes do nothing and running the comparison three times. The room page improved by 10% at the median and a third at p99. That's an upper bound, since posts still commit about once a second, and it isn't enough to justify moving presence out of the database, so that change is on hold.

What to check in your app: if your cache is invalidated by writes, measure its hit rate under traffic that writes the way your users do. Rails' own ActionDispatch::ServerTiming middleware reports time spent per notification, but not hits and misses. Counting those from the cache_read.active_support and cache_read_multi.active_support events takes a few dozen lines; #411 is one way to do it.

Look at what's in your cache keys

Below the page cache, each message on a room page is a cached fragment. These did hit, but each viewer had their own copy of every message: Campfire overrides combined_fragment_cache_key to add the user's id and a digest of their session token to every fragment key. That protects fragments containing something personal, such as a CSRF token, but a message fragment contains nothing of the kind. With hundreds of viewers, a message rendered once per viewer, not once.

#412 drops the viewer from the key for fragments whose key already fingerprints everything they render. The fragment hit rate went to 78–88%, and:

What to check in your app: find every override of combined_fragment_cache_key, every cache call that passes current_user, and everything else that ends up in a key, and ask whether the fragment really differs by it. A key that varies by viewer multiplies your cache's size and divides its hit rate by the number of viewers.

A cache key can cost more than the render

Campfire's message fragments are keyed by content: a SHA-256 of the message, its room, its creator, its rendered body and its boosts. That key can never go stale, even when something outside Rails edits the database without touching timestamps, which the shared verification harness tests. But to compute it, every render loads all of those associations for every message on the page and hashes them before it can look anything up. On a hit, almost all of that work is thrown away.

#413 moves the version into the database: a presentation_version column on messages, kept moving by SQLite triggers whenever anything the fragment shows changes (the message, its body, its boosts, the creator's or a booster's name or avatar, or the room's name). Because triggers fire for every writer, the guarantee that foreign SQL edits can't serve stale HTML still holds. The view then uses plain cached: true, which reads every key from columns the message rows already have and loads associations only for the fragments that missed.

The difference is larger under more load. At 1,000 people the original build fell over: navigations took 17 seconds at the median, in two of the three runs hundreds of subscriptions were never confirmed, and 104 deliveries never arrived. With both changes it's still overloaded at 1,000 (a median of about 800 ms), but every page is correct and every message arrives.

Triggers are easy to get subtly wrong, and the review of #413 found six ways these could have been: writes from outside Rails that would have reused a version for different content, or not moved it at all. The fix is a single counter that only ever goes up, and one helper that every trigger goes through. One of the six is worth knowing about if you write SQLite triggers: in an INSERT OR REPLACE, SQLite applies the outer statement's conflict policy to every statement inside the triggers it fires, so the trigger's own INSERT OR IGNORE quietly became a REPLACE and reset the counter to zero.

What to check in your app: if a fragment's key needs associations, computing the key costs those queries on every hit. touch: true keeps a parent's updated_at moving for writes that go through Active Record; a column maintained by triggers does the same for every writer. Either way, the key comes from the row you already loaded.

Action Cable can reorder your commands

With those changes the median is good, but Rails still misses the target at 250 people: 99% of navigations finish within 144 ms, not 100. At 500 people the 99th percentile of opening a room is 582 ms, and nearly all of that is one thing.

Action Cable hands each command a connection sends (subscribe, unsubscribe, a channel action) to a thread pool, four threads by default, and nothing keeps one connection's commands in order. When a page navigation unsubscribes from a channel and subscribes to the same channel again, the two can run in either order. If the subscribe runs first, the server rejects it as a duplicate, sends no confirmation, and then processes the unsubscribe, leaving that page with no subscription at all. The browser recovers only because @rails/actioncable re-sends any subscribe that isn't confirmed within 500 ms. So about one room visit in a hundred takes half a second longer.

This has been reported before. rails#48292 was closed as stale, and rails#57504, which made a duplicate subscribe succeed instead of failing, was closed unmerged. That change would have turned the reorder from a delay into a silent loss, because the unsubscribe that follows would still remove the subscription. The fix that addresses the cause is to process each connection's commands in the order they arrive, and rails#59371 proposes exactly that, with a regression test. In a reproduction where the two commands arrive together, 998 of 1,000 navigations waited for the re-send before the change and none did after it.

What to check in your app: if your pages unsubscribe and resubscribe to the same channel as people navigate, count how many subscribe commands your clients send compared with how many pages they open. The difference is the re-sends.

A load-testing lesson: keep-alive

The first runs reported a handful of errors for Rails even at 250 people. When I made the generator record why, every one was a request sent on a keep-alive connection that Puma had already closed for being idle. A browser opens a new connection when that happens and you never see it. A naive load generator counts each one as a server error. The generator now does what a browser does, and Rails has zero errors at every load it was tested at. Its latencies didn't change: the runs before and after the fix agree within their ranges.

If you load-test with your own tools, check what an "error" actually was before you believe it.

How far there is to go

The same app also runs on two very different Ruby stacks, which gives a sense of how much headroom there is. Roundhouse transpiles Campfire's Rails source into a standalone Ruby app on Falcon, and Tobi's port is Campfire rewritten by hand in plain Ruby with Ractors. Rails and the Roundhouse build both ran Campfire with the three pull requests (my fork's preview branch), and Tobi's port is its own code. Each had six workers: Campfire's own Puma configuration (six workers of five threads, behind Thruster), six forked Falcon workers, and six Ractors in one process.

None of the three produced an error, a wrong page or a lost message at any load it served. Past that point, Falcon's requests start timing out at 3,000 people, while Tobi's port is past its target there but still answers everything.

That isn't a contest. They're three ways to run the same app, checked the same way. For Rails developers the useful part is the first row and how much it moved. The three pull requests above are plain Rails changes to a plain Rails app, and the Action Cable fix would be a change to Rails itself.

Next

For Rails: the Action Cable reproduction and a proposal to keep each connection's commands in order. On the Campfire side, a page could also avoid unsubscribing and resubscribing the same channel on every navigation, which would sidestep the problem for Campfire whatever happens upstream.

For the implementations: Roundhouse's Falcon build re-sends far more subscriptions than either of the others, renders a page at about two and a half times the cost of Tobi's port, and collapses rather than degrades when overloaded. Those are the next things to profile. The benchmark itself moves to two machines, and then replaces Roundhouse's nightly Campfire benchmark.

The pull requests are #411, #412 and #413. The generator is loadgen/src/users.rs on the users-profile branch, and the runs are driven by scripts/campfire-users-campaign in the roundhouse repository.