From fed3a83ba4cf403f9704b958300b2be8ce28f76c Mon Sep 17 00:00:00 2001 From: James Rosewell Date: Mon, 9 Nov 2026 21:12:38 +0000 Subject: [PATCH 1/7] Measure the share usage overhead as a median over warmed up rounds --- .../performance/ShareUsageOverheadTests.java | 97 +++++++++++-------- 1 file changed, 58 insertions(+), 39 deletions(-) diff --git a/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java b/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java index 9583850a7..9c2f1c6fc 100644 --- a/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java +++ b/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java @@ -50,6 +50,7 @@ import java.nio.file.Files; import java.nio.file.Paths; import java.util.ArrayList; +import java.util.Arrays; import java.util.LinkedHashMap; import java.util.List; import java.util.Map; @@ -115,14 +116,29 @@ public void cleanUp() throws Exception { pipeline.close(); } - // The FlowData are all processed before any is closed, so that closing - // them is not part of the time measured. They are closed together in a - // finally block rather than one by one with try-with-resources. - @Test + private static final String USER_AGENT = + "Mozilla/5.0 (iPad; U; CPU OS 3_2_1 like Mac OS X; en-us) " + + "AppleWebKit/531.21.10 (KHTML, like Gecko) Mobile/7B405"; + + /** + * Rounds measured, and the number discarded first so that the JIT has + * compiled the code. The median of the rounds is checked, so one round + * slowed by a busy runner or a garbage collection does not fail a test, + * whilst a cost on every call does. + */ + private static final int MeasuredRounds = 7; + private static final int WarmUpRounds = 2; + + /** + * Returns the milliseconds per Process call, for one round of calls with + * the evidence given. The FlowData are all processed before any is closed, + * so that closing them is not part of the time measured. They are closed + * together in a finally block rather than one by one with + * try-with-resources. + */ @SuppressWarnings("PMD.FlowDataInTryWithResources") - public void ShareUsageOverhead_SingleEvidence() throws Exception { - int iterations = 10_000; - double maxOverheadPerCall = 0.1; + private double measureRound(int iterations, int evidenceCount) + throws Exception { List data = new ArrayList<>(); long start; long end; @@ -130,59 +146,62 @@ public void ShareUsageOverhead_SingleEvidence() throws Exception { for (int i = 0; i < iterations; i++) { FlowData flowData = pipeline.createFlowData(); data.add(flowData); - flowData.addEvidence("header.user-agent", "Mozilla/5.0 (iPad; U; CPU OS 3_2_1 like Mac OS X; en-us) AppleWebKit/531.21.10 (KHTML, like Gecko) Mobile/7B405"); + for (int j = 0; j < evidenceCount; j++) { + flowData.addEvidence("header." + j, j); + } + flowData.addEvidence("header.user-agent", USER_AGENT); } - - start = System.currentTimeMillis(); + start = System.nanoTime(); for (FlowData entry : data) { entry.process(); } - end = System.currentTimeMillis(); + end = System.nanoTime(); } finally { closeAll(data); } + return (end - start) / 1_000_000.0 / iterations; + } + + /** + * Returns the median over the measured rounds, after the warm up rounds. + */ + private double measureMedian(int iterations, int evidenceCount) + throws Exception { + for (int i = 0; i < WarmUpRounds; i++) { + measureRound(iterations, evidenceCount); + } + double[] rounds = new double[MeasuredRounds]; + for (int i = 0; i < rounds.length; i++) { + rounds[i] = measureRound(iterations, evidenceCount); + } + Arrays.sort(rounds); + logger.info("Rounds in millis per call {}", Arrays.toString(rounds)); + return rounds[rounds.length / 2]; + } + + @Test + public void ShareUsageOverhead_SingleEvidence() throws Exception { + int iterations = 10_000; + double maxOverheadPerCall = 0.1; - double msOverheadPerCall = (double)(end - start) / iterations; + double msOverheadPerCall = measureMedian(iterations, 0); overheadMillis.put("ShareUsageOverhead_SingleEvidence_ms", msOverheadPerCall); - System.out.println("ShareUsageOverhead_SingleEvidence: " + msOverheadPerCall + "ms per call"); + System.out.println("ShareUsageOverhead_SingleEvidence: " + msOverheadPerCall + "ms per call"); logger.info("Overhead was {} millis", msOverheadPerCall); Assertions.assertTrue(msOverheadPerCall < maxOverheadPerCall, "Pipeline with share usage overhead per Process call was " + msOverheadPerCall + "ms. Maximum permitted is " + maxOverheadPerCall); } - // See ShareUsageOverhead_SingleEvidence for why the FlowData are closed - // in a finally block. @Test - @SuppressWarnings("PMD.FlowDataInTryWithResources") public void ShareUsageOverhead_ThousandEvidence() throws Exception { - int iterations = 1_000; + int iterations = 250; int evidenceCount = 1_000; int maxOverheadPerCallMillis = 10; - List data = new ArrayList<>(); - long start; - long end; - try { - for (int i = 0; i < iterations; i++) { - FlowData flowData = pipeline.createFlowData(); - data.add(flowData); - for (int j = 0; j < evidenceCount; j++) { - flowData.addEvidence("header." + j, j); - } - flowData.addEvidence("header.user-agent", "Mozilla/5.0 (iPad; U; CPU OS 3_2_1 like Mac OS X; en-us) AppleWebKit/531.21.10 (KHTML, like Gecko) Mobile/7B405"); - } - start = System.currentTimeMillis(); - for (FlowData entry : data) { - entry.process(); - } - end = System.currentTimeMillis(); - } finally { - closeAll(data); - } - double msOverheadPerCall = (double)(end - start) / iterations; + double msOverheadPerCall = measureMedian(iterations, evidenceCount); overheadMillis.put("ShareUsageOverhead_HundredEvidence_ms", msOverheadPerCall); - System.out.println("ShareUsageOverhead_HundredEvidence: " + msOverheadPerCall + "ms per call"); + System.out.println("ShareUsageOverhead_HundredEvidence: " + msOverheadPerCall + "ms per call"); logger.info("Overhead was {} millis", msOverheadPerCall); Assertions.assertTrue(msOverheadPerCall < maxOverheadPerCallMillis, "Pipeline with share usage overhead per Process call was " + From b76239ea5ea90c5b2abc19dc7f2e66487fce6d0b Mon Sep 17 00:00:00 2001 From: James Rosewell Date: Fri, 13 Nov 2026 06:36:46 +0000 Subject: [PATCH 2/7] Set the share usage overhead limits to fit the slowest runner 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. --- .../performance/ShareUsageOverheadTests.java | 49 +++++++++++++------ 1 file changed, 33 insertions(+), 16 deletions(-) diff --git a/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java b/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java index 9c2f1c6fc..370210447 100644 --- a/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java +++ b/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java @@ -129,6 +129,14 @@ public void cleanUp() throws Exception { private static final int MeasuredRounds = 7; private static final int WarmUpRounds = 2; + /** + * The most one Process call may take. Each limit is about ten times the + * highest time per call that the slowest runner (Intel macOS) measures, + * so that a runner slowed for the whole test still passes. + */ + private static final double SingleEvidenceLimitMillis = 0.25; + private static final double ThousandEvidenceLimitMillis = 50; + /** * Returns the milliseconds per Process call, for one round of calls with * the evidence given. The FlowData are all processed before any is closed, @@ -163,9 +171,10 @@ private double measureRound(int iterations, int evidenceCount) } /** - * Returns the median over the measured rounds, after the warm up rounds. + * Returns the milliseconds per Process call of each measured round, + * lowest first, after the warm up rounds. */ - private double measureMedian(int iterations, int evidenceCount) + private double[] measureRounds(int iterations, int evidenceCount) throws Exception { for (int i = 0; i < WarmUpRounds; i++) { measureRound(iterations, evidenceCount); @@ -175,37 +184,45 @@ private double measureMedian(int iterations, int evidenceCount) rounds[i] = measureRound(iterations, evidenceCount); } Arrays.sort(rounds); - logger.info("Rounds in millis per call {}", Arrays.toString(rounds)); - return rounds[rounds.length / 2]; + return rounds; + } + + /** + * Fails when the median round is not below the limit. The message lists + * every round, because the build log shows only the message, and the + * rounds tell a runner slow for the whole test from a slow round or two. + */ + private static void assertBelowLimit(double[] rounds, double limitMillis) { + double median = rounds[rounds.length / 2]; + logger.info("Overhead was {} millis, rounds {}", median, + Arrays.toString(rounds)); + Assertions.assertTrue(median < limitMillis, + "Pipeline with share usage overhead per Process call was " + + median + "ms. Maximum permitted is " + limitMillis + + ". Rounds in ms per call " + Arrays.toString(rounds)); } @Test public void ShareUsageOverhead_SingleEvidence() throws Exception { int iterations = 10_000; - double maxOverheadPerCall = 0.1; - double msOverheadPerCall = measureMedian(iterations, 0); + double[] rounds = measureRounds(iterations, 0); + double msOverheadPerCall = rounds[rounds.length / 2]; overheadMillis.put("ShareUsageOverhead_SingleEvidence_ms", msOverheadPerCall); System.out.println("ShareUsageOverhead_SingleEvidence: " + msOverheadPerCall + "ms per call"); - logger.info("Overhead was {} millis", msOverheadPerCall); - Assertions.assertTrue(msOverheadPerCall < maxOverheadPerCall, - "Pipeline with share usage overhead per Process call was " + - msOverheadPerCall + "ms. Maximum permitted is " + maxOverheadPerCall); + assertBelowLimit(rounds, SingleEvidenceLimitMillis); } @Test public void ShareUsageOverhead_ThousandEvidence() throws Exception { int iterations = 250; int evidenceCount = 1_000; - int maxOverheadPerCallMillis = 10; - double msOverheadPerCall = measureMedian(iterations, evidenceCount); + double[] rounds = measureRounds(iterations, evidenceCount); + double msOverheadPerCall = rounds[rounds.length / 2]; overheadMillis.put("ShareUsageOverhead_HundredEvidence_ms", msOverheadPerCall); System.out.println("ShareUsageOverhead_HundredEvidence: " + msOverheadPerCall + "ms per call"); - logger.info("Overhead was {} millis", msOverheadPerCall); - Assertions.assertTrue(msOverheadPerCall < maxOverheadPerCallMillis, - "Pipeline with share usage overhead per Process call was " + - msOverheadPerCall + "ms. Maximum permitted is " + maxOverheadPerCallMillis); + assertBelowLimit(rounds, ThousandEvidenceLimitMillis); } private static void closeAll(List data) throws Exception { From b96922b1b5d7938feab8fc3cb6601dd273e71a7f Mon Sep 17 00:00:00 2001 From: James Rosewell Date: Fri, 13 Nov 2026 06:55:55 +0000 Subject: [PATCH 3/7] Say what the share usage overhead limits leave room for 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. --- .../fiftyone/performance/ShareUsageOverheadTests.java | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java b/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java index 370210447..3417679cb 100644 --- a/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java +++ b/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java @@ -130,9 +130,10 @@ public void cleanUp() throws Exception { private static final int WarmUpRounds = 2; /** - * The most one Process call may take. Each limit is about ten times the - * highest time per call that the slowest runner (Intel macOS) measures, - * so that a runner slowed for the whole test still passes. + * The most one Process call may take. Each limit is set from the figures + * the slowest runner (Intel macOS) prints in the performance step, with + * room for that runner to run five times slower than usual for the whole + * test. */ private static final double SingleEvidenceLimitMillis = 0.25; private static final double ThousandEvidenceLimitMillis = 50; From db7e36cf737468be3fb766297c14d3ce5d114b5a Mon Sep 17 00:00:00 2001 From: James Rosewell Date: Fri, 13 Nov 2026 13:55:17 +0000 Subject: [PATCH 4/7] Set the share usage overhead limits from the warmed up medians 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. --- .../performance/ShareUsageOverheadTests.java | 35 +++++++++---------- 1 file changed, 17 insertions(+), 18 deletions(-) diff --git a/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java b/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java index 3417679cb..f20361b51 100644 --- a/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java +++ b/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java @@ -40,7 +40,6 @@ import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; import org.slf4j.ILoggerFactory; -import org.slf4j.Logger; import org.slf4j.LoggerFactory; import java.io.IOException; @@ -59,8 +58,13 @@ import static org.mockito.Mockito.mock; import static org.mockito.Mockito.when; +/** + * Times Process calls through the usage sharing element. Every call in a + * test carries the same Evidence, so after the first call the tracker turns + * each one away as a repeat and nothing more is queued. The measured rounds + * time that path, which finds the values to share and checks the tracker. + */ public class ShareUsageOverheadTests { - static Logger logger = LoggerFactory.getLogger("testLogger"); private Pipeline pipeline; private static final Map overheadMillis = new LinkedHashMap<>(); @@ -130,13 +134,12 @@ public void cleanUp() throws Exception { private static final int WarmUpRounds = 2; /** - * The most one Process call may take. Each limit is set from the figures - * the slowest runner (Intel macOS) prints in the performance step, with - * room for that runner to run five times slower than usual for the whole - * test. + * The most the median Process call may take. Each limit is ten times the + * highest median measured on any CI runner, so a runner several times + * slower than usual still passes. */ - private static final double SingleEvidenceLimitMillis = 0.25; - private static final double ThousandEvidenceLimitMillis = 50; + private static final double SingleEvidenceLimitMillis = 0.06; + private static final double ThousandEvidenceLimitMillis = 30; /** * Returns the milliseconds per Process call, for one round of calls with @@ -195,8 +198,6 @@ private double[] measureRounds(int iterations, int evidenceCount) */ private static void assertBelowLimit(double[] rounds, double limitMillis) { double median = rounds[rounds.length / 2]; - logger.info("Overhead was {} millis, rounds {}", median, - Arrays.toString(rounds)); Assertions.assertTrue(median < limitMillis, "Pipeline with share usage overhead per Process call was " + median + "ms. Maximum permitted is " + limitMillis + @@ -204,25 +205,23 @@ private static void assertBelowLimit(double[] rounds, double limitMillis) { } @Test - public void ShareUsageOverhead_SingleEvidence() throws Exception { + public void ShareUsageOverhead_RepeatedSingleEvidence() throws Exception { int iterations = 10_000; double[] rounds = measureRounds(iterations, 0); - double msOverheadPerCall = rounds[rounds.length / 2]; - overheadMillis.put("ShareUsageOverhead_SingleEvidence_ms", msOverheadPerCall); - System.out.println("ShareUsageOverhead_SingleEvidence: " + msOverheadPerCall + "ms per call"); + overheadMillis.put("ShareUsageOverhead_SingleEvidence_ms", + rounds[rounds.length / 2]); assertBelowLimit(rounds, SingleEvidenceLimitMillis); } @Test - public void ShareUsageOverhead_ThousandEvidence() throws Exception { + public void ShareUsageOverhead_RepeatedThousandEvidence() throws Exception { int iterations = 250; int evidenceCount = 1_000; double[] rounds = measureRounds(iterations, evidenceCount); - double msOverheadPerCall = rounds[rounds.length / 2]; - overheadMillis.put("ShareUsageOverhead_HundredEvidence_ms", msOverheadPerCall); - System.out.println("ShareUsageOverhead_HundredEvidence: " + msOverheadPerCall + "ms per call"); + overheadMillis.put("ShareUsageOverhead_HundredEvidence_ms", + rounds[rounds.length / 2]); assertBelowLimit(rounds, ThousandEvidenceLimitMillis); } From 9bd1ce1ccd5d9898f05f77fccb656e74febda3d5 Mon Sep 17 00:00:00 2001 From: James Rosewell Date: Fri, 13 Nov 2026 15:55:29 +0000 Subject: [PATCH 5/7] Set the 1,000 evidence limit to ten times the highest usual median 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. --- .../fiftyone/performance/ShareUsageOverheadTests.java | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java b/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java index f20361b51..3afdd5219 100644 --- a/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java +++ b/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java @@ -134,12 +134,12 @@ public void cleanUp() throws Exception { private static final int WarmUpRounds = 2; /** - * The most the median Process call may take. Each limit is ten times the - * highest median measured on any CI runner, so a runner several times - * slower than usual still passes. + * The most the median Process call may take. Each limit is at least ten + * times the highest median the CI runners measure at their usual speed, + * so a runner several times slower than usual still passes. */ private static final double SingleEvidenceLimitMillis = 0.06; - private static final double ThousandEvidenceLimitMillis = 30; + private static final double ThousandEvidenceLimitMillis = 40; /** * Returns the milliseconds per Process call, for one round of calls with From 26a51a41d19e18b8b7fa0f766bc551f6916fb0dd Mon Sep 17 00:00:00 2001 From: James Rosewell Date: Fri, 13 Nov 2026 20:12:52 +0000 Subject: [PATCH 6/7] Set the one evidence limit to ten times the highest usual 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. From 6ca326e3139db4b77d02892509fea9944f02c6d4 Mon Sep 17 00:00:00 2001 From: James Rosewell Date: Fri, 13 Nov 2026 20:13:58 +0000 Subject: [PATCH 7/7] Set the one evidence limit to 0.07 ms 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 9bd1ce1c 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. --- .../engines/fiftyone/performance/ShareUsageOverheadTests.java | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java b/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java index 3afdd5219..71a362e7e 100644 --- a/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java +++ b/pipeline/pipeline.engines.fiftyone/src/test/java/fiftyone/pipeline/engines/fiftyone/performance/ShareUsageOverheadTests.java @@ -134,11 +134,11 @@ public void cleanUp() throws Exception { private static final int WarmUpRounds = 2; /** - * The most the median Process call may take. Each limit is at least ten + * The most the median Process call may take. Each limit is about ten * times the highest median the CI runners measure at their usual speed, * so a runner several times slower than usual still passes. */ - private static final double SingleEvidenceLimitMillis = 0.06; + private static final double SingleEvidenceLimitMillis = 0.07; private static final double ThousandEvidenceLimitMillis = 40; /**