Skip to content

Measure the share usage overhead as a median over warmed up rounds - #91

Merged
jwrosewell merged 9 commits into
rcfrom
feature/share-usage-overhead-median
Nov 13, 2026
Merged

jwrosewell merged 9 commits into
rcfrom
feature/share-usage-overhead-median

Conversation

@jwrosewell

@jwrosewell jwrosewell commented Nov 9, 2026 •

Copy link
Copy Markdown
Contributor

Problem

ShareUsageOverheadTests.ShareUsageOverhead_SingleEvidence failed on an Intel macOS runner in the release build of #112, which took rc at d99b7acf into main. It failed in run 43364257944, attempt 1, job MacOS_X64_Java_11, and passed when the failed jobs were run again in attempt 2.

ShareUsageOverheadTests.ShareUsageOverhead_SingleEvidence:149 Pipeline with share usage overhead per Process call was 0.1083ms. Maximum permitted is 0.1

The job runs the test class twice, once with the unit tests and once in the performance step. The unit test pass ran both tests in 2.991 seconds and passed. The performance pass, 36 minutes later on the same runner, took 13.553 seconds for the same two tests and failed, so the runner was about four and a half times slower for the whole of that pass, not for one call. The ten other jobs that ran the test in that attempt measured 0.005 to 0.012 ms.

The test on rc times one pass of 10,000 calls (1,000 calls for the 1,000 evidence test) with System.currentTimeMillis and no warm up, and checks that one number against 0.1 ms (10 ms for 1,000 evidence). The highest figure Intel macOS printed in the 22 jobs that passed in the builds listed below is 0.0246 ms, so the limit left that runner about four times its highest passing figure.

The 1,000 evidence test failed the same way before this draft was opened, at 13.345 ms against 10 ms, in job MacOS_X64_Java_17 of run 42645701438, attempt 1, the full build of #78. In the same attempt job MacOS_X64_Java_11 passed at 9.365 ms, in a performance pass that took 18.148 seconds against 3.873 seconds for its unit test pass.

A test that fails on timing needs a limit that fits the slowest runner it runs on, or a fix for whatever makes it slow, rather than another run. This draft measures so that one slow round cannot decide the result, and sets each limit from the medians every runner prints.

What the specification says

The usage sharing element specification, Processing says this in lines 120 to 123, at the latest commit to that file.

The process function SHOULD get the data it needs and complete as soon as possible.
We recommend implementing a producer/consumer approach where the process function just adds the raw data to a shared queue.

This test checks that a Process call through the usage sharing element stays cheap. The specification sets no figure, so the limits are set from what the runners measure.

What changed

One test file, ShareUsageOverheadTests.java. No package code changes. The branch merges rc at b78810ff (which adds #118, two Markdown files at the root) and changes only the test file against it.

  1. Warmed up rounds and a median. Two rounds are run and thrown away, so that the JIT (the part of Java that compiles code to machine code while it runs) has compiled the code. Then seven rounds are measured with System.nanoTime, each over its own set of FlowData, with closing them outside the timed part. The median round is checked, so one round slowed by a garbage collection no longer decides the result, whilst a cost on every call still does. The one evidence test makes 10,000 calls a round and the 1,000 evidence test makes 250.
  2. Limits set from the medians. 0.07 ms for one evidence and 40 ms for 1,000 evidence, set as the next section describes. The comment above them states the rule.
  3. Names that say what is timed. Every call in a test carries the same Evidence. The tracker lets a set of Evidence be shared once in each repeat interval (ShareUsageTracker.match), which is 20 minutes by default. So after the first call it turns each call away and nothing more is queued. The measured rounds time that path, where ShareUsageBase.processData asks the tracker and the tracker finds the values the call would share to make its key. The tests are renamed ShareUsageOverhead_RepeatedSingleEvidence and ShareUsageOverhead_RepeatedThousandEvidence, and a class comment says what the rounds time. The results keep their names, ShareUsageOverhead_SingleEvidence_ms and ShareUsageOverhead_HundredEvidence_ms, so they line up with those of earlier builds.
  4. Every round in the failure message. The message now lists all seven rounds, so a failure shows at once whether every round was slow or only a few.
  5. Output that reached no log is removed. The two System.out.println calls and the log line are gone, with the logger. pipeline/pom.xml sets redirectTestOutputToFile, so test output goes to files under target that no build log shows, and the full log of job MacOS_X64_Java_17 in run 43382362370 runs the test and has no ms per call line. The failure message and the results file carry the figures.

The class now takes 3.9 to 16.6 seconds a pass in this draft's builds (18.0 seconds in the one slowed pass), against 1.9 to 9.5 seconds at usual speed for the single pass test. Each job runs it twice, so in the green build each job spent 2 to 10 seconds longer on it than the same job did in release build 43364257944, in jobs that took 20 to 75 minutes. That buys a figure that the JIT warming up and one slow round cannot move, which is what lets each limit sit about ten times above the medians rather than above one cold pass.

How each limit is set

Each limit is ten times the highest median any runner has printed at its usual speed, rounded up to one significant figure. A pass counts as at its usual speed when the test class took less than twice as long as in the same job's unit test pass. Every pass of this draft did except one, at 2.3 times, and the rest took 0.76 to 1.60 times as long. Intel macOS printed both of the highest usual medians, so the limits fit the slowest runner.

Test Highest median at usual speed Where Ten times Limit Old limit
One evidence 0.0066 ms Intel macOS, Java 17, run 43457504599 0.066 ms 0.07 ms 0.1 ms
1,000 evidence 3.231 ms Intel macOS, Java 17, run 43437941585 32.3 ms 40 ms 10 ms

Ten is about twice the largest slowdown seen for a whole pass, 4.7 times in job MacOS_X64_Java_11 of run 42645701438, so a runner that slow still passes. The test fails when the median per call reaches 10.6 times (one evidence) or 12.4 times (1,000 evidence) the highest usual median. Growth below that passes, and shows only in the figures each performance step prints.

These are the slowest whole passes seen, each measured as the class time against the same job's unit test pass. Only the last is a median of this draft, and it is under its new limit.

Pass Test Figure Class time
Run 43364257944, attempt 1, MacOS_X64_Java_11 single pass, one evidence 0.1083 ms, failed the old 0.1 ms 13.553 s against 2.991 s, 4.5 times
Run 42645701438, attempt 1, MacOS_X64_Java_17 single pass, 1,000 evidence 13.345 ms, failed the old 10 ms 17.837 s against 4.437 s, 4.0 times
Run 42645701438, attempt 1, MacOS_X64_Java_11 single pass, 1,000 evidence 9.365 ms, passed 18.148 s against 3.873 s, 4.7 times
Run 43411790985, attempt 2, MacOS_X64_Java_21 median, 1,000 evidence 6.542 ms, passed 17.99 s against 7.72 s, 2.3 times

Each runner's figures

This draft's median, in milliseconds per Process call, lowest to highest over the jobs counted, from the LowerIsBetter.ShareUsageOverhead_SingleEvidence_ms and LowerIsBetter.ShareUsageOverhead_HundredEvidence_ms lines the performance step prints. The second is the 1,000 evidence test, whose result keeps its older name.

Runner Image Jobs One evidence 1,000 evidence
Ubuntu x64, Java 8, 11, 17, 21 ubuntu-22.04 24 0.0006 to 0.0035 1.019 to 2.764
Ubuntu ARM, Java 17 ubuntu-22.04-arm 6 0.0012 to 0.0019 1.286 to 1.736
Windows, Java 8, 11, 17, 21 windows-2025-vs2026 24 0.0013 to 0.0038 1.173 to 2.678
macOS arm64, Java 11, 17, 21 macos-15-arm64 15 0.0013 to 0.0056 1.247 to 1.641
Intel macOS, Java 11, 17, 21 macos-15 13 0.0019 to 0.0066 1.858 to 6.542, the highest from the slowed pass above

These come from the full builds 42717428349 on fed3a83b, 43382362370 and 43411790985 (both attempts) on b96922b1, 43437941585 on db7e36cf, 43457504599 on 9bd1ce1c and 43499659322 on 6ca326e3. Every one measured the same way, because the later commits change only the limits, the failure message, the names, the comments and the output.

For comparison, the single pass test before this draft printed these figures in jobs that passed.

Runner Image Jobs One evidence 1,000 evidence
Ubuntu x64, Java 8, 11, 17, 21 ubuntu-22.04 12 0.0049 to 0.0133 1.565 to 3.243
Ubuntu ARM, Java 17 ubuntu-22.04-arm 3 0.0060 to 0.0067 1.415 to 1.909
Windows, Java 8, 11, 17, 21 windows-2025-vs2026 12 0.0050 to 0.0123 1.105 to 3.718
macOS arm64, Java 11, 17, 21 macos-15-arm64 9 0.0034 to 0.0101 1.294 to 2.948
Intel macOS, Java 11, 17, 21 macos-15 22 0.0088 to 0.0246 2.102 to 9.365, the highest from the slowed pass above

Every runner's figures come from the release builds of rc at 9a668883, 6644140a and d99b7acf (43130836772, 43151568806 and 43364257944, both attempts). Intel macOS's also come from attempt 1 of the full build of #78's head 90eac597 (42645701438) and from every attempt of the nightly runs 42747966370, 42951328299 and 43146786827. Those nightly jobs build main, apart from the three Build and Test jobs of run 42951328299, which build the head of #103, 93568c50.

Builds

Red, the test before this draft. Run 43364257944, attempt 1 on rc failed at 0.1083 ms against 0.1 ms, and run 42645701438, attempt 1 on the head of #78 failed at 13.345 ms against 10 ms, as described above.

Green. Full build run 43499659322 of 6ca326e3 passed on all 15 jobs in attempt 1, macOS included, and every job's Setting 'PullRequestSha' line is 6ca326e3139db4b77d02892509fea9944f02c6d4.

Job Image One evidence median 1,000 evidence median
Ubuntu_Java_8 ubuntu-22.04 0.0006 1.207
Ubuntu_Java_11 ubuntu-22.04 0.0028 1.670
Ubuntu_Java_17 ubuntu-22.04 0.0014 1.019
Ubuntu_Java_21 ubuntu-22.04 0.0026 2.222
Ubuntu_ARM_Java_17 ubuntu-22.04-arm 0.0017 1.297
Windows_Java_8 windows-2025-vs2026 0.0023 2.094
Windows_Java_11 windows-2025-vs2026 0.0022 1.434
Windows_Java_17 windows-2025-vs2026 0.0020 1.811
Windows_Java_21 windows-2025-vs2026 0.0035 2.236
MacOS_Java_11 macos-15-arm64 0.0017 1.354
MacOS_Java_17 macos-15-arm64 0.0016 1.505
MacOS_Java_21 macos-15-arm64 0.0019 1.625
MacOS_X64_Java_11 macos-15 0.0042 2.229
MacOS_X64_Java_17 macos-15 0.0026 2.185
MacOS_X64_Java_21 macos-15 0.0043 2.057

Earlier builds of this branch. Run 43437941585 of db7e36cf and run 43457504599 of 9bd1ce1c each passed on all 15 jobs in attempt 1. Their medians of 3.231 ms (1,000 evidence) and 0.0066 ms (one evidence), both from MacOS_X64_Java_17 at its usual speed, raised the highest usual medians, so the commits after them raised the 1,000 evidence limit from 30 ms to 40 ms and the one evidence limit from 0.06 ms to 0.07 ms. Commit 26a51a41, after 9bd1ce1c, changes nothing, because the file it was given still held 0.06 ms. Its build, run 43499485416, was cancelled, and the commit after it, 6ca326e3, makes that change.

Two failures that are not this change. Both were on Intel macOS, in tests that do not run the one file this draft changes, and ShareUsageOverheadTests passed in the unit test step of both failing jobs.

  1. Full build run 43382362370 of b96922b1 failed on job MacOS_X64_Java_17 in fiftyone.geolocation.data.tests.FiftyoneValueTests, the geo-location cloud value tests. ValueTests_Cloud_AvailableProperties spent 30.63 seconds before processing raised AggregateException: Exception(s) occurred processing evidence., and the other two tests raised the same within 0.02 seconds. The Cloud Request Engine's default request timeout is 2 seconds. The same tests passed on the twelve jobs of that build that completed, including MacOS_X64_Java_11 on the same image and head in 3.4 seconds, and on MacOS_X64_Java_21 in 3.5 seconds before the failure cancelled it. No other run among this repository's 40 most recent failed runs, back to 11 November, shows them failing. The log does not carry the exception's causes, so it does not say which request failed or why.
  2. In run 43411790985, attempt 1, job MacOS_X64_Java_11 failed in the Selenium contract tests against the cloud example. Example_RendersClientSideOverridesOnThePage gave up after 60 seconds waiting for the browser driver to load the page (The HTTP request to the remote WebDriver server for URL http://localhost:49484/session/9a336c17f263d38dbf1b8527e8d7fff6/url timed out after 60 seconds). The other eight tests against the cloud example passed, and all nine against the on-premise example passed straight after. The four macOS jobs that failure stopped passed when run again in attempt 2.

Remains

  • The rounds time a Process call whose Evidence the tracker has already seen. The cost of queueing new usage data on the calling thread is not measured here. A test of it needs Evidence that changes on every call and a queue large enough for a round, because the default queue holds 1,000 entries and, with its add timeout of 0, discards a new entry at once when it is full. It would also run beside the thread that sends the data.
  • The limits leave room for a slow runner, so growth below them passes. The figures each performance step prints are where smaller growth shows, and they show whether the limits still fit if the runners change.
  • The two failures above are timing failures in other tests on Intel macOS, and neither is fixed here. Each needs its own change. The geo-location tests first need to print the exception's causes, because without them the log does not say what failed or what it waited for.

ShareUsageOverhead_SingleEvidence failed on an Intel macOS runner in the
release build at 0.1083 ms per call against a 0.1 ms limit, in a pass
where the same job ran the same tests four and a half times slower than
in its own first pass. Intel macOS is the slowest runner the test runs
on. Over 16 earlier jobs it measured 0.0088 to 0.021 ms for one evidence
and 2.14 to 4.85 ms for 1,000.

Each limit is now about ten times the highest of those, 0.25 ms and
50 ms, so a runner slowed for the whole test still passes. The failure
message lists every round, because the build log shows only the message.
The comment said each limit is about ten times the slowest runner's
highest figure. That holds for the single pass figures the limits were
set from, but the warmed up medians the test now checks are lower, so the
ratio would read as wrong against them. The comment now says what the
limits allow for, which is the slowest runner running five times slower
than usual for the whole test.
@jwrosewell jwrosewell mentioned this pull request Nov 13, 2026
The limits were set from the figures of the single pass test this branch
replaces, which are higher than the medians the test now checks. Each
limit is now ten times the highest median any runner has printed at its
usual speed, 0.06 ms for one evidence and 30 ms for 1,000 evidence.

Every call carries the same Evidence, so after the first call the tracker
turns each call away as a repeat. The tests are renamed to say they time
repeated Evidence, and a class comment says what the rounds measure.

The printed figures and the log line are removed, because the build sends
test output to files that no build log shows. The failure message and the
results file carry the figures.
The full build of the last commit measured a median of 3.231 ms for 1,000
evidence on Intel macOS at its usual speed, so 30 ms was less than ten
times the highest usual median. The limit is now 40 ms, and the comment
says each limit is at least ten times that median.
The full build of the last commit measured a median of 0.0066 ms for one
evidence on Intel macOS at its usual speed, so 0.06 ms was less than ten
times the highest usual median. The limit is now 0.07 ms. The comment says
each limit is about ten times that median, because each build can move the
highest median a little.
The commit before this one changed nothing, because the file it was given
still held the old limit and comment, so this commit makes the change its
message describes. The full build of 9bd1ce1 measured a median of
0.0066 ms for one evidence on Intel macOS at its usual speed, so 0.06 ms
was less than ten times the highest usual median. The limit is now
0.07 ms, and the comment says each limit is about ten times that median,
because each build can move the highest median a little.
@jwrosewell
jwrosewell marked this pull request as ready for review November 13, 2026 22:20
@jwrosewell
jwrosewell merged commit 30e4886 into rc Nov 13, 2026
3 checks passed
@jwrosewell
jwrosewell deleted the feature/share-usage-overhead-median branch November 13, 2026 22:20
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant