[jwrosewell]

The problem

The release build of #83,
rc into main, failed on macOS_Node_22 and on no other job. The test was
"a dictionary read is no slower than it was" in
pipeline/fiftyone.pipeline.engines/tests/engines.test.js,
asserting at line 228, and it failed like this.

expect(received).toBeLessThanOrEqual(expected)
Expected: <= 157.8674185
Received:    158.15229

Its own log line for that run read as follows.

Dictionary read of one, fastest of 10 rounds of 200000, before 143.5 ns,
after 158.2 ns. A read of One, which found nothing before, 466.9 ns.

So it failed by 0.28 nanoseconds on a bound of 157.87, which is 0.18 per cent
over. The run is
43130083012
on head d68a9463, attempt 1, job 130894721984, runner label macos-latest,
and that job's own count was 1 failed, 2 skipped, 1232 passed, 1235 total.

Nothing else on the run disagreed with it. The three Ubuntu jobs passed, and
the other four Build jobs, macOS_Node_24 and both Windows jobs among them,
were cancelled when this one failed, which left Compare Performance,
Report Compare Performance and Complete all skipped. The performance
figures are the thing a release build is for, so a tenth of a per cent on one
timing test cost the whole run its purpose.

That the code was never the cause is plain from the reruns. Attempt 2 of the
same job on the same head passed, and the earlier release build of #83,
43124475695
on head c5d31b5b, passed this test on both of its macOS jobs.

How often it failed, measured

Run
43149627241
restores the test file from rc 13ad4ebb, so its three Rate (n, old) jobs
run the test exactly as it is today, twenty times each on macos-latest with
node 22. They gave 18, 18 and 19 passes, so 5 failures in 60 runs, which is
one run in twelve on the runner that shows the fault.

Those 60 after-over-before ratios ran from 0.905 to 1.255 against the test's
bound of 1.1, with a middle of 1.001. The worst was 1.255, before 109.5 ns and
after 137.4 ns, on a read whose true cost had not moved at all. That is the
size of the noise the old bound of a tenth was trying to sit above, and it does
not fit under it.

What the specification says

pipeline-specification/features/access-to-results.md lines 5 to 11 at
67ead698,
under "General guidance", sets the rules for string keys.

Where string keys are used, the following rules apply:

• Strings SHOULD only contain alphanumeric characters, full stop or hyphen.
• Some 51Degrees Properties also use the '/' character. No new Properties
  will be added with this character, but it will need to be accommodated.
• Lower-case SHOULD be used.
• String comparisons MUST be case insensitive.

That last line is what
#68 implemented and what
the new counting test pins. A read of One must find the value stored
under one, which the test asserts, and the specification asks for nothing
beyond that, so a read that already finds its key as given has no comparison
left to make and must not pay for one. The test asserts that too, as a count of
zero rather than as a time.

What the test is for, and why the allowance was not simply widened

The test arrived with
#68, "Compare property
names ignoring case, in the restricted list and in every read". That change
made every read compare names without regard to letter case, and this test is
what stops the new read being materially slower than the read it replaced.
Making every read fold letter case measures 2.13 times the read it
replaced, which the Red run below shows directly, so the cost being guarded
against is real and large.

Raising the allowance until the test passes would have left a test that cannot
fail, and the next person to slow this path down needs it to catch them. So the
allowance is unchanged in spirit and the measurement under it was made steady
instead, and a second test now asserts the guarantee exactly, with no clock at
all.

What changed

1. A test with no clock, which is the exact guarantee

a read that finds its key as given never looks at letter case subclasses
AspectDataDictionary and counts calls to getInternalIgnoringCase. A read
whose key is found as given must cost 0 of them, and a read found only by
folding case costs exactly 1. That is precisely what #68 promised, it is
asserted rather than timed, and it cannot be flaky on any runner.

The count is held in a closure rather than in a field on the dictionary,
because ElementData's constructor hands back a Proxy whose getter is
data[key] || data.get(key)
(elementData.js lines 52 to 72),
so a count of zero is falsy and the read falls through to a property lookup
that throws. A field worked everywhere except at the one moment that matters.
The first full build of this branch caught it,
43150984588
failing on Ubuntu_ARM_Node_24 with Property "caseLookups" not found in data for element "caseWork".

2. The timing test kept, as a backstop, and settled

The count cannot see a slowdown put somewhere else, such as letter case folded
inside getInternal rather than in the second look, so the timing test stays
and keeps its job. Three things changed in how it decides.

It times a before and an after side by side in every round, and keeps that
round's own ratio. The old test took the fastest before over ten rounds and
the fastest after over ten rounds and divided one by the other, so the two
numbers could come from rounds minutes apart on a machine whose speed had moved
in between. Now each round times both and the round carries its own ratio, so a
runner that speeds up or slows down moves both together and cancels out.

The middle of 200 such rounds decides it, 10 freshly built pairs of 20
rounds of 10,000 reads, rather than one fastest pair. Each pair is built fresh
because the engine can settle on a faster internal shape for one object within
a process, which has nothing to do with the code under test.

The bound is 1.05, replacing the fixed tenth, and it is set from
measurement rather than picked.

3. A measurement over the bound is taken again

A whole measurement can land in a slow patch, so one over 1.05 is measured
again and the better of the two decides. A read that really is slower is slower
in both. The timing test also gets its own 60 second timeout, because
pipeline/setup.js sets jest.setTimeout(10000) for the package and a runner
busy enough to need the second measurement is also one that takes longer over
both, so the second measurement could otherwise have introduced a timeout
failure of its own.

The measurements the choices were made on

Sweep run
43143953881,
three macos-latest jobs on node 22, 15 repeats each of 8 shapes and 4
statistics, with a control that puts the before code on both sides, so the
true answer is exactly 1.0 and anything above it is measurement noise. 720
records, pooled to 90 measurements per shape.

shape	pairs x rounds x reads	ms	median	p95	worst	sd	over 1.05
A	7 x 2 x 200000	1218	1.003	1.096	1.184	0.0461	11 of 90
C	5 x 20 x 25000	1066	1.003	1.020	1.035	0.0150	0 of 90
D	10 x 10 x 25000	1079	1.003	1.018	1.082	0.0135	2 of 90
E	10 x 20 x 10000	846	1.003	1.015	1.021	0.0063	0 of 90
F	5 x 40 x 10000	842	1.004	1.014	1.024	0.0066	0 of 90
G	1 x 100 x 25000	1051	1.004	1.017	1.030	0.0103	0 of 90
H	5 x 20 x 50000	2162	1.003	1.012	1.074	0.0131	1 of 90

Shape E is the steadiest and among the cheapest, so it is the one chosen, and
it is a little cheaper than the shape it replaces. The bound of 1.05 sits
about seven standard deviations above its mean of 1.003, and more than double
its worst of 1.021 over 90 measurements, whilst the regression it guards
against measures 2.13. Shape A, which is closest to the old
test in what it costs to run, went over 1.05 eleven times in 90 and reached
1.184 on the control, where before and after are the same code.

What was weighed and not taken

• Fastest of many more rounds. The sweep measured that statistic alongside
  the others, and on the same shape E it reached 1.050 on the control where the
  middle of the paired ratios reached 1.015, with the worst of all its shapes
  being 1.279 on the control at shape A. Taking the fastest keeps one round and
  throws the other 199 away, so a single lucky round on one side decides it.
• An allowance computed from the run's own spread. The spread of single
  rounds inside one run is enormous on a shared runner, shape E's 18,000 rounds
  having a 99th percentile of 2.722 and a worst of 21.076, so an allowance built
  from that would grow exactly when the machine is busy, which is also when a
  real slowdown would need catching. The fixed 1.05 is set from 90
  measurements across three jobs instead, and does not loosen itself under
  load.
• Comparing against other work the same run does. The test already does
  this, because ReadByKeyOnly is the read as it was, built from the same
  class and timed in the same round. The change is that the comparison is now
  made round by round rather than once at the end.
• Requiring two failures in a row and nothing else. Measuring again is in
  the change, but on its own it would have left the single measurement as loose
  as it was. Of the sweep measurements over 1.05 that had a next measurement on
  the same job, 1 of 15 was also over, so a high measurement does not predict
  the next one, which is what makes measuring again worth doing and also what
  makes it insufficient alone.

The runs

All on macos-latest with node 22, the runner and version that showed the
fault.

Red. Run
43152929133
job Red swapped getInternal and getInternalIgnoringCase in
aspectData.js, so every read folds letter case, which is the regression both
tests exist to catch. Each test was run five times. Both failed all five
times, RESULT red failed=10 of 10.

The counting test failed with Expected: 0, Received: 2, naming the two reads
that should never have looked past letter case. The timing test's five ratios
were 2.122, 2.123, 2.137, 2.139 and 2.142, against its bound of 1.05. All
five took the second measurement and all five were still over, which is the
retry working as designed rather than merely present.

So the three numbers sit well apart. A healthy read measures 0.983 to 1.024
across 60 runs, the bound is 1.05, and the regression measures about 2.13. The
gap below the bound is twice the widest healthy reading and the gap above it is
more than twenty times, so the bound has room on both sides.

Green, repeated. One green run proves nothing about a test that usually
passes. So the same run's three Rate jobs each ran the whole engines test
file twenty times, and run
43149627241
did the same three times over with the test file restored from rc 13ad4ebb,
which is the test as it is today. That is 60 runs of each, on the runner
and node version that shows the fault.

	runs	passed	failed	middle ratios
the test as it is today, bound 1.1	60	55	5	0.905 to 1.255
the test in this draft, bound 1.05	60	60	0	0.983 to 1.024

Not one of the 60 runs of the new test needed the second measurement, every log
line reading "from 1 measurement", so the retry is a safety net that has not
been called on yet rather than something these figures lean on. The widest
single measurement sat 0.026 below the bound.

Full build, with macOS. Run
43152810700
on f91be51, green, Configure and all eight Build jobs. Every job's
Setting 'PullRequestSha' reads
f91be51938c58f1fa46474b3c71afe0351f6bc5a. The two jobs that matter:

• macOS_Node_22, the job that showed the fault, passed 1,234 of 1,236 with
  2 skipped. Middle ratio 1.007, before 169.3 ns, after 174.1 ns, from 1
  measurement, and the read of One at 452.5 ns.
• macOS_Node_24 passed the same counts. Middle ratio 1.001, before 147.4
  ns, after 146.9 ns, from 1 measurement, and the read of One at 441.7 ns.

The head then moved once, to 3d20c7f, which changes four lines of one
comment and nothing else. The comment over allowedRatio had said that
folding case on every read costs about three times a plain read and pointed at
the read of One as its evidence. That took the figure for one path and attached
it to another, because the read of One is a miss on getInternal followed by
the second look, which is dearer again, whilst the regression this bound
catches measures 2.13. The comment now says about twice, and says that the read
of One is a different path and is not what the bound is set from.

Full build on the head, with macOS. Run
43164784192
on 3d20c7f, completed and success. Configure, all eight Build jobs,
Compare Performance and Complete all green, with Report Compare Performance skipped as it is on a passing build. All nine
Setting 'PullRequestSha' lines read
3d20c7f2755b1be17dc3cee308712928a1ffd27f and no other value appears, and
Configure printed no "Left out N macOS entries" line. macOS_Node_22 gave
middle ratio 0.998, before 153.3 ns and after 152.8 ns from 1 measurement,
and macOS_Node_24 gave 1.012, before 163.9 ns and after 168.8 ns from 1
measurement, both passing 1,234 of 1,236.

Compare Performance ran and succeeded here, which is the job the original
failure had left skipped, so the thing the release build needed is back.

macOS was put into this draft's full builds with --mac, in place of the
usual sentence. A draft normally builds without macOS under the 9 November
decision, and Configure accordingly printed no "Left out N macOS entries" line
here. macOS is the whole point of this draft, so leaving it out would have
proved nothing.

What remains

Draft builds have left macOS out since the 9 November decision, and #68 merged
at 12:47 on 11 November. Every one of the 31 node runs named "Temporary full
build of pull request N" created between that merge and midnight ran zero macOS
jobs, main does not carry the test so the 03:00 Nightly Pipeline never ran it,
and
.github/workflows/pull-requests.yml
only runs on workflow_dispatch. So this test first ran on macOS at
43124475695,
the first release build of #83, 11 hours and 16 minutes after it merged.

The same happened in .NET on the same night, where
ShareUsageElement_Dispose_SendsEveryRemainingEntry, merged on 10 November,
failed on macOS x64 at the release build and was fixed in
51degrees-dotnet#140,
which has since merged into rc.
Two timing tests, both merged since 9 November, both meeting macOS for the
first time at a release build, where a failure cancels the other jobs and costs
the release its performance figures. That pattern is worth an issue of its own,
because the cost of leaving macOS out of draft builds is not that macOS breaks,
it is that the release build is the first place anything finds out.

Two things this change does not do. It does not guard the restricted list path
that #68 also changed, which has its own tests but none that time it. It does
not set a floor, so a read that became much faster than the read it replaced
would pass silently, which is the right way round for this test but means the
figure in the log is the only record of how fast the read actually is.