intertwingly

It’s just data

Campfire, Buffered


Two days ago I published a fragment cache and a sentence I was pleased with: one of our processes beats their eight. It beat them by 1.55x.

The same page today:

deployed Rails the binary two days ago
/rooms/1 334 req/s 1,351 538
/rooms/1/messages 677 req/s 2,991 897
p99, room page 150 ms 24 ms 68 ms
memory (PSS) 1,840 MB 297 MB 268 MB
cold start to a page 4,546 ms 380 ms 363 ms
1,000 idle WebSockets, CPU 0.015 cores 0.008 0.009
delivering to 1,000 sockets 0.163 cores 0.039 0.038

Four times, on the page that matters, against Campfire as its own Dockerfile runs it — Thruster, eight Puma workers of five threads, jemalloc, resque-pool, Redis. The socket rows did not move. Two things did, one of them ours.

A view stops returning a string

The lowering emits each view as io = String.new; io << …; io. A room page is views nested inside views, so rendering it materialises a String at every level and appends it to the level above, which materialises a String. A profile of a single request put 83% of the 11.5 MB it allocates in that materialisation — not in the accumulation, in the handing back.

So a view gets a second entry point. show_into(io, …) is the body without its buffer init and without its trailing read, appending into a buffer it was handed; show(…) keeps the original name and arity, allocates a buffer, calls the variant, returns the string. Inside the view layer, acc << Views::X.y(a) becomes Views::X.y_into(acc, a, …) wherever the appended value is a view call — including inside blocks, which is where the message loop lives. Every caller outside the view layer is untouched: controllers, models broadcasting a fragment, the blocks inside the fragment cache. 140 of the application's 144 views take the buffer form; the four that don't never touch their buffer.

Two emits from the same tree, one line of configuration apart, same compiler, each page asserted byte-identical:

c=16 c=64
returning a string 490 req/s 419
appending into the caller's 1,173 (2.39x) 940 (2.24x)
RSS 241 → 217 MB 602 → 592 MB

Allocation per request went 11,530 KB → 4,547 KB, and the collector's share of wall went 46.0% → 41.7%.

What Rails does here

Rails has this plumbing and does not use it, which surprised me enough that I went and read it rather than assuming.

ActionView::Template#render takes a buffer as its third argument. Hand it one and it runs the template into that buffer and returns nil; leave it off and it allocates a fresh OutputBuffer, renders, and returns a String. That is the same pair of entry points, already written, and it has been there since at least 7.1.

The only caller in all of ActionView that passes a buffer is the streaming renderer — render stream: true. On the ordinary path, PartialRenderer and CollectionRenderer both call render without one, so every partial materialises its own String. Collections cost a little more than that: collection_with_template maps each item to a String, and the collection's body is @rendered_templates.map(&:body).join(@spacer.body) — so Campfire's forty-message list makes forty Strings and then a joined copy of all of them. <%= render … %> compiles to @output_buffer.append=(…), appending a string that already exists.

(Read at rails/rails as the benchmark runs it, 8.2.0.alpha at dd1c8848; 8.1 and 7.1 are the same.)

So Rails materialises a String per nesting level exactly as we did, and it is not because nobody thought of the alternative — the alternative is in the tree, one argument away. My guess at why it stays unused is that render's String is a public return value. It goes to helpers, to capture, to content_for, to the block whose result a cache entry gets written from. ActionView cannot switch partials to nil-returning appends without knowing every caller, and it does not know every caller.

A lowering does. That is the whole of the difference here: we can rewrite the append sites because we can see all of them, and we keep the string-returning wrapper for exactly the callers that still need a string. It is the least glamorous form of the argument I keep making for compiling Rails — not a faster instruction anywhere, just a global rewrite that a library is not allowed to make.

What it took to land

It went in on Monday and came out the same evening, because the nightly benchmark segfaulted in the fiber root walk. That turned out to be two collector faults on the by-reference ABI this shape relies on, both now fixed upstream — a proc capturing a lent String parameter marked the caller's stack slot, and a lent slot needed to record its owner across the call. #4391 has the whole thread, including the core the benchmark archived alongside its own emitted tree, which is what let Matz work from the failure rather than from my description of it.

Worth one sentence because it decides whether any of the numbers above mean anything: an earlier version of this lowering benchmarked at 2.4x with 35% fewer bytes on the wire, and it was serving 27,815 bytes of a 423,364-byte page. If a speedup arrives with a byte count that improved, the byte count is the result. Every A/B cell above asserts the page.

Where the other half came from

The lowering is worth 2.39x. The page moved 2.5x on the room page and 3.3x on messages, and the difference is upstream, in a control loop that our shape happened to sit on the wrong side of.

The published page had been showing the one-worker binary at 2,425 MB against the same binary at thirteen workers at 128 MB — an 11x gap for one executable, with the object heap identical in both, so it was never application data.

The collector's string budget is 2 × live / nw per worker, but a collection is global, firing as soon as any one worker exceeds its share. The aggregate is therefore worker-count neutral, but the time to trigger is a minimum over nw draws: at thirteen workers you wait for the first of thirteen to cross 0.15 of live; at two, for the first of two to cross 1.0 of live. At two the coefficient is exactly one — unity loop gain — and live is an output of the pacing, so it ran away. It ran away on our workload and not on Matz's because his has a fixed 100 MB live string set anchoring the formula, while ours is about 6 MB of true working set and the rest was whatever the control law allowed itself to keep.

b64b1204 damps it by widening the object budget by the share of the collection the mark is:

before after
one worker, live string 2,713 MB 13.9 MB
one worker, PSS (/rooms/1/messages) 2,425 MB 162 MB
deployed, /rooms/1 1,197 req/s 1,351
deployed, /rooms/1/messages 2,568 req/s 2,991
collector share of wall 46.7% 38.7%

What the second column is, now

The last post put a caveat on its per-core number, and this is the caveat coming due:

It does not say Spinel's code generation is at parity with YJIT. The input to Spinel's compiler is roundhouse's output; if we emit polymorphic slots or untyped dispatch or needless string churn, that measurement bills our lowering to their backend.

It was the string churn. Same three-lane split as before — one Rails process, the lowered application on CRuby at one worker, the binary at one OS worker, all on one CPU:

per core /rooms/1 /rooms/1/messages
Rails 41 req/s 84 req/s
+ the lowering 191 (4.7x) 490 (5.8x)
+ the compiler 376 (1.97x) 805 (1.64x)
against one Rails process 9.3x 9.6x

Two days ago that middle multiplier was 1.24x on the room page and 0.98x on the messages page, and I wrote a paragraph about why nobody should read it as a statement about code generation. It is 1.97x and 1.64x now, and the honest reading is the same one in the other direction: what moved was our output, not their backend. A compiler handed less garbage does better. That is not news about compilers, but it is the first time this page could say it with the framework held fixed.

The deployed column stays separate: 1,351 against 334 is four times, and most of that four is that CRuby needs a process per core while the binary uses thirteen OS workers inside one. The GVL is still the whole column, and one process is still why the fragment cache, the Action Cable registry and the job queue can be in-process at all.

One loose end, named rather than buried. The emitted application on CRuby got the same change and moved a few percent — 1,551 → 1,635 req/s deployed, 187 → 191 at one worker. Those straddle two days of other commits, so they are an observation and not a measurement; the controlled A/B is on the binary only. But the direction is worth the run: a 61% cut in allocation is worth 2.4x to one runtime and single digits to the other, which is the entire argument for publishing both lanes.

The ceiling, which is now a mark phase nobody can explain

Throughput plateaus at eight workers and the process holds about six of twelve cores. That ceiling is the mark phase: per collection it roughly doubles from one worker to twelve while the sweep beside it halves, with the live heap flat throughout.

Two days ago I published a mechanism for that — every parked green thread's saved stack is a root set, so mark tracks suspended fibers. That is retracted, by its author, as of this afternoon. With the mark split into root scanning and tracing, on a program extracted from this application into Spinel's own benchmark suite:

workers objects marked mark root walk ns / object
1 182,158 2.81 ms 0.000 ms 15.4
4 182,923 3.51 ms 0.000 ms 19.2
12 177,930 3.58 ms 0.000 ms 20.1

Objects marked are flat, so neither phase is handed more work. The root walk is zero at every worker count, on two different machines. The entire rise is in the trace: the same graph costs 30% more per object to walk when more workers allocated it. Which also kills the fix the old mechanism implied — handing the fiber list to the parked workers would parallelize a column that reads 0.000.

The live candidate is locality: objects interleaved across per-worker free lists rather than laid down in one worker's order. It predicts something a much smaller program can test — build the graph on one worker and mark it from N, against building it on N — and that program is #4384's next move.

The budget has a second anomaly I can't explain yet either: a 16 MB floor costs more memory and less throughput than a 64 MB one, which a ceiling should not do. Matz has reproduced the shape and named premature promotion as the mechanism — a small budget promotes anything that outlives one budget's worth of allocation, and the major collection's gate re-aims to twice what survived, so an old generation inflated once stays inflated. Confirming it on our workload is my next measurement.

What did not move

The ruby lane still cannot honestly deploy at eight workers — its Action Cable registry is per-process, so a broadcast reaches only the subscribers sharing a process with the poster. That was the top of the last post's what's-next list and it is still there, still behind the Broadcasts.set_transport seam that exists for it.

The one-worker binary has an ugly tail: p99 of 998 ms on the room page and 328 ms on messages, against a p50 of 40 ms. The deployed lane, which is the shipped shape, is at 24 ms. I do not have the mechanism and I am not going to guess at one in public again this week — I did that with the collector default, filed it, and withdrew it five hours later after running the shape that argued the other way instead of the one that argued mine.

What's next

The locality program for the mark, which is the smallest experiment on this list and the only one that would name a mechanism rather than confirm one.

The controlled A/B of this same change on CRuby, because "worth 2.4x to one runtime and single digits to the other" deserves to be a measurement rather than a direction.

The cross-process pubsub, so the ruby column is a deployment claim.

And the one-worker tail, which is the lane that looks wrong on the page today — and therefore, on the evidence of this week, the one worth reading first.


Roundhouse is open source: dual-licensed MIT / Apache-2.0. Issues and discussion welcome.