Measure the Loop, Not the Program: Ninety Minutes to Eleven on mere-ruby's Spec Sweep

mere-ruby is a Ruby-subset interpreter written in Mere, a small ML-family language I am building. Its conformance record is a checked-in table: every group of ruby/spec, swept against the real ruby, byte for byte. Producing it took an hour and a half. Six sweeps in a day is normal when several things land, so most of a working day was the sweep.

I had assumed the interpreter was what was slow. That assumption had never been measured, and it was wrong in a way that is worth writing down.

The first honest measurement

One spec file, through the harness, with a clock on it:

real 2.71   user 0.15   sys 1.89

User 0.15 seconds. Both interpreters together — mere-ruby and the reference ruby — are about a tenth of a second on a small file. Everything else was the filesystem, and the filesystem was the harness’s own doing: it cloned the spec tree (core, language, library, shared, fixtures) into a private temporary directory for every spec file, so that require_relative and the sibling directories resolve.

That is 4,333 files copied per spec file. Across the record’s 2,498 files, about ten million clones per sweep.

The fix is the obvious one once you see the number: build the tree once and hand it to each run. Ninety minutes became thirty.

The second cost was invisible from inside. That much filesystem churn holds macOS’s fseventsd at 100%+ CPU with several gigabytes resident, and it stays there for hours after the sweep ends — so everything else on the machine, including the next sweep, ran up to eight times slower. An hour went into reading that slowdown as a deadlock in the interpreter. ps aux | sort -k3 -rn named it in one command.

The harness was deciding the answers

With the sweep three times faster, the obvious next move was to run it in parallel: the groups are independent and the machine has ten cores. That worked, and then the record moved — twice, with no change to the interpreter at all.

bounds	what the record said
sequential	core/dir 18 DIFF, 1 SLOW; 0 CRASH overall
six workers, same bounds	core/dir 14 DIFF, 5 SLOW
six workers, both bounds ×6	SLOW 13 → 4, and CRASH 0 → 4

One binary, three different tables. The gap slid between DIFF, SLOW and CRASH according to which limit fired first — and every limit was wall clock. A file that takes 24 seconds alone takes 40 with five other workers on the machine, so the verdict was a fact about the load, not about the interpreter.

There is a second lesson buried in that table. The first attempt to fix it scaled the outer bound and changed nothing, because the files were crossing a different, inner one. A harness with two limits for one question will hide one of them from you.

Bound the thing you actually mean

“Does this finish” is a question about CPU, not about the clock. A file that burns 25 CPU-seconds burns 25 whether one worker runs or six. So:

• SPEC_CPU (25s, via RLIMIT_CPU) answers does this finish.
• SPEC_WALL is 24× that, and only catches a process that is not running at all — blocked, not slow. Expressing it as a ratio states the intent: a process that has spent under a twenty-fourth of its wall time on the CPU is waiting.
• The outer bound is derived from SPEC_WALL, so it can never be the one that fires first.
• Bytes are the third limit, and the sweep now starts its own memory guard instead of asking the operator to remember. It had been down for half a day.

The premise I planned all of this on was false, and measuring said so immediately: I had written that several specs block on stdin and burn no CPU, so a CPU bound could not stand alone. Measured, all nine of the record’s slow files are compute-bound, 84–99% CPU. I had written the sentence from memory of what those specs are about.

A SIGKILL is not the interpreter aborting

CRASH is defined in the table as “mere-ruby aborts where ruby does not” — a claim about the interpreter. A run the memory guard kills arrives at the classifier as “no output”, so it was recorded there: the record said the interpreter had aborted on a file that works and wants seven gigabytes.

All three limits now produce one verdict — the harness stopped it — with the row naming which one. CRASH means one thing again.

⚠ This restores CRASH 0 and nothing about the interpreter earned that. It is a reclassification, so the underlying fact — two spec files drive this interpreter past 6 GB where ruby needs megabytes — is recorded in the gap document, where a gap belongs.

And a record is not a measurement

The first version of that fix put the measured numbers in the row: used 25.3s of 25s CPU, peaked 5.22 GB. The classification became stable, and the record got worse: two unreproducible rows became seven, because 5.22 GB and 5.01 GB are the same fact and two different bytes.

A record and a measurement want opposite things. A record must read the same twice; a measurement is interesting exactly where it varies. The row carries the class; the numbers go to a per-run log that is not checked in.

The record caught me

After all of this the sweep came back with MATCH 1758, not 1764. Six files, all in core/env, had gone from MATCH to DIFF.

One environment variable. To pass the wall bound into an inner shell I had added it to the harness’s allowlist, and core/env counts ENV keys. The two sides build their view of the environment differently, so an extra key is not free even when both sides get it — and the comment above that allowlist says exactly this, naming the five files it cost the last time. I added the variable anyway.

Removing it left the count still off by one: the extra shell was a level too. The shell went away entirely. perl was already in the chain for the alarm, so it now forks, redirects, execs a list (never a shell) and on the alarm kills the child. Nothing is added to the environment.

The one I would not have found by reading

With the record reproducing again, one row still moved between one worker and six: core/exception/interrupt_spec. Sequentially it completes and reports DIFF. Under six workers the reference ruby sat at ten minutes of wall clock and 0.07 seconds of CPU, then hit the wall bound.

The spec waits on a child that is supposed to die of its own SIGINT.

A shell sets SIGINT and SIGQUIT to SIG_IGN for a job it starts in the background — and SIG_IGN is inherited across fork and exec. Workers are ( … ) &. So with six workers every spec process below one ignored SIGINT, and with one worker, in the foreground, none of them did.

the same popen, run from	result
the foreground	child dies, SIGINT (signal 2)
a background subshell	child never dies

The parallel sweep was not scheduling the subjects differently. It was changing them. Two lines in the child before exec fixed it, and a ten-minute tail disappeared from every parallel run.

I had recorded this symptom earlier in the day as “two facts that have not been connected — an open question, not a finding”, with three tidier explanations above it that were all wrong. Leaving it explicitly unexplained is what kept it findable. A confident sentence would have closed the question.

Six ideas that were measured and thrown away

The rejected list is the part of the record I expect to be most reused, because the next person to look at the same numbers will have the same ideas.

idea	measured	verdict
cache the reference output between sweeps	would save ~2 min of 30	worth ten times more an hour earlier, before the tree fix
take the verdict from peak RSS	the two ambiguous files exceed both bounds	cannot resolve what has no answer
put the measured numbers in the row	2 unstable rows became 7	see above
deal the biggest groups first	719.9s vs a 646–662s baseline	slower
ten workers instead of six	736.7s, and CPU up 50s	slower; the bottleneck is shared and serial
unique /tmp paths per corpus process	one program prints File.basename(__FILE__)	the two sides are two processes; byte-equality breaks

The last two are worth a sentence each. Ten workers costing more CPU for the same result is contention, and it says the remaining bottleneck is a shared serial resource — half the sweep’s CPU is system time, so: the filesystem. Neither scheduling nor worker count moves that.

What it came to

	before	after
build + gates	~6 min	~4 min
full record sweep	90 min, then 30	11 min
the eight source gates	~29s	4.95s
one of them, dead_defs_check	22.99s	0.64s
bracket_depth	75.04s	11.97s
corpus, both modes	111.65s	70.0s
CI	11m04s	8m34s

dead_defs_check is the plainest of them: it ran one awk per definition, each scanning the whole uses table — 2,575 processes over 7,577 identifiers, 19.5 million line-scans. One awk over both tables answers the same question.

The record itself did not move: 103 groups, 2,498 files, MATCH 1764, CRASH 0. It is now byte-identical at one worker and at six, which is the actual claim; the speed is a consequence of it.

The part I got wrong about measuring

Two scheduling ideas came back slower while macOS’s storage indexer was eating 150% of CPU. I retracted both as unmeasurable — three sweeps hours apart are not a comparison.

Then I ran the control: the unchanged harness, under the same load. 646s, consistent with baselines taken seven hours apart. The load was high but steady — a constant, not a confound — and both changes sat well outside it. The retraction was the error, and the control is what found that out.

⚠ The uncomfortable half: that indexer had been visible since late morning and I had noted it at the time. It became “a confound” only once the numbers came out against the change I was testing. Had longest-first measured 10% faster, it would have been committed without a control.

So the rule is not “be suspicious of surprising results”. It is: pair the before and after in the same window, and decide whether to doubt from how a number was measured, never from which way it came out.

Coda: the document had the same disease

Asked whether all of this was written up, I said yes. Then I checked.

The loop document is append-only, and three successive edits had left three copies of a section answering a live question the way it had stopped being true. A reader hits the oldest first. Another section still claimed something a later measurement had refuted. A hundred and seventy-three lines were contradicting the rest of the file.

I had spent the day writing “the record caught my mistake” and had made the record itself the one thing nobody checked. The gate that refuses a machine path in a checked-in record now also refuses a document with two sections of the same title — the signature of an edit that replaced one copy and missed another.

Verified against every tracked document, and poisoned by adding one.