From afa3c40abf00e4709fd94b862dd2409f9a223985 Mon Sep 17 00:00:00 2001 From: Serge Huber Date: Tue, 21 Jul 2026 13:39:23 +0200 Subject: [PATCH 1/3] UNOMI-970: Fix IT ProgressListener ETA using live suite pace Re-evaluate remaining time from elapsed/completed after every test and treat historical timings as hints so early skips no longer collapse ETA. --- itests/README.md | 7 +- .../apache/unomi/itests/ProgressListener.java | 6 +- .../apache/unomi/itests/TestTimingCache.java | 122 +++++++++++++++--- .../unomi/itests/TestTimingCacheTest.java | 70 ++++++++-- 4 files changed, 173 insertions(+), 32 deletions(-) diff --git a/itests/README.md b/itests/README.md index 0d587d2b4..55f3eed25 100644 --- a/itests/README.md +++ b/itests/README.md @@ -311,9 +311,10 @@ the `itests` module directory (survives `mvn clean`): `.test-timing-cache-.properties` One file per persistence provider (`elasticsearch`, `opensearch`, `postgresql`, …) -so ETAs are not mixed across backends. On later runs the listener sums remaining -historical times and scales them by how fast/slow the current run is vs history -(clamped). Safe to delete; missing/unwritable cache falls back to in-run averages. +so timings are not mixed across backends. ETA is re-evaluated from **live suite pace** +(`elapsed / completed`) after every test; historical per-test durations are only hints +that reweight remaining work when harder/easier tests than average are still ahead. +Safe to delete; missing/unwritable cache falls back to the in-run average. ### Built-in backends diff --git a/itests/src/test/java/org/apache/unomi/itests/ProgressListener.java b/itests/src/test/java/org/apache/unomi/itests/ProgressListener.java index 1ecdca270..66325fdc5 100644 --- a/itests/src/test/java/org/apache/unomi/itests/ProgressListener.java +++ b/itests/src/test/java/org/apache/unomi/itests/ProgressListener.java @@ -46,7 +46,7 @@ *
  • ASCII art logo display at test suite startup
    • *
  • Real-time progress bar with percentage completion
    • *
  • Colorized output (when ANSI is supported)
    • - *
  • Estimated time remaining from a per-persistence-provider historical timing cache
    • + *
  • Estimated time remaining from live suite pace, with historical timings as hints
    • *
  • Test success/failure counters
    • *
  • Top 10 slowest tests tracking and reporting
    • *
  • Motivational quotes displayed at progress milestones
    • @@ -493,8 +493,8 @@ private String escapeCsv(String value) { } /** - * Estimates remaining time using the provider-specific {@link TestTimingCache}, scaled by how - * fast/slow this run has been vs history for tests that already completed with a cache hit. + * Estimates remaining time from live suite pace ({@code elapsed / completed}), using the + * provider-specific {@link TestTimingCache} as hints for how heavy the remaining tests are. * * @param completed the number of tests completed so far * @param elapsedTime the time elapsed since the run started, in milliseconds diff --git a/itests/src/test/java/org/apache/unomi/itests/TestTimingCache.java b/itests/src/test/java/org/apache/unomi/itests/TestTimingCache.java index f6e5b7e55..d0793619e 100644 --- a/itests/src/test/java/org/apache/unomi/itests/TestTimingCache.java +++ b/itests/src/test/java/org/apache/unomi/itests/TestTimingCache.java @@ -56,10 +56,22 @@ final class TestTimingCache { /** * Clamp for the live-run vs historical scale factor so a few outliers cannot make ETA absurd. + * Used by {@link #computeScale}; {@link #estimateRemainingMs} prefers wall-clock pace instead. */ static final double MIN_SCALE = 0.25; static final double MAX_SCALE = 4.0; + /** + * Observed durations below this are treated as non-representative for scale (assumes / empty tests). + */ + static final long SUBSTANTIVE_OBSERVED_MS = 100L; + + /** + * Ignore observed/cached pairs more extreme than this when computing {@link #computeScale} + * (e.g. historically-slow test that skipped in milliseconds). + */ + static final double MAX_PAIR_SKEW = 20.0; + private TestTimingCache() { } @@ -169,16 +181,23 @@ static void save(String persistenceProvider, Map observedTimings) /** * Estimates remaining wall time for unfinished tests. *

    - * For each remaining test with a historical entry, uses that duration scaled by how fast/slow - * this run has been relative to history (ratio of observed vs cached for completed - * tests that had a cache hit). Uncached remaining tests use the in-run average of completed - * durations (or the median of historical values when nothing has completed yet). + * Real suite pace is primary: after every completion the estimate is rebuilt from + * {@code elapsed / completed}. Historical per-test durations are only hints that reweight + * remaining work when the leftover tests are historically heavier or lighter than the suite average + * (so a block of slow tests still ahead raises ETA above a flat per-test rate). + *

    + * A global “this run is 4× faster than cache” scale is not applied to shrink remaining + * historical time — that is what made ETAs chronically too low after early assumes/skips. + * If the run is slower than cache on substantive tests, remaining historical time is still + * raised accordingly. + *

    + * Cold start (nothing completed yet) falls back to the sum of historical hints (or a placeholder). * * @param remainingKeys keys still expected to run * @param cachedTimings historical durations for this persistence provider * @param observedVsCachedCompleted pairs of (observedMs, cachedMs) for completed tests that had history * @param completedDurations all completed durations this run (for fallback average) - * @param elapsedTimeMs wall time since suite start (unused for sum; kept for API clarity) + * @param elapsedTimeMs wall time since suite start * @return estimated remaining milliseconds (never negative) */ static long estimateRemainingMs(Collection remainingKeys, @@ -186,24 +205,66 @@ static long estimateRemainingMs(Collection remainingKeys, Collection observedVsCachedCompleted, Collection completedDurations, long elapsedTimeMs) { - double scale = computeScale(observedVsCachedCompleted); + int remainingCount = remainingKeys == null ? 0 : remainingKeys.size(); + if (remainingCount == 0) { + return 0L; + } + + int completedCount = completedDurations == null ? 0 : completedDurations.size(); double fallbackAvg = fallbackAverageMs(completedDurations, cachedTimings, elapsedTimeMs); + double globalHintAvg = averagePositive(cachedTimings != null ? cachedTimings.values() : null); + if (globalHintAvg <= 0.0) { + globalHintAvg = fallbackAvg; + } - long estimate = 0L; + long hintRemainingMs = 0L; for (String key : remainingKeys) { - Long cached = cachedTimings.get(key); + Long cached = cachedTimings != null ? cachedTimings.get(key) : null; if (cached != null && cached > 0L) { - estimate += Math.round(cached * scale); + hintRemainingMs += cached; } else { - estimate += Math.round(fallbackAvg); + hintRemainingMs += Math.round(fallbackAvg); } } - return Math.max(0L, estimate); + + // Cold start: only historical hints (or placeholder average) are available. + if (completedCount <= 0 || elapsedTimeMs <= 0L) { + return Math.max(0L, hintRemainingMs); + } + + double avgActualMs = elapsedTimeMs / (double) completedCount; + // Flat live pace: every remaining test takes as long as the average so far. + long rateEtaMs = Math.round(remainingCount * avgActualMs); + + // Hint-shaped live pace: same real average, but weight remaining tests by historical + // duration relative to the suite's average historical duration. + // predict(r) = avgActual * (hint(r) / globalHintAvg) + // sum = hintRemaining * avgActual / globalHintAvg + long hintShapedEtaMs = rateEtaMs; + if (globalHintAvg > 0.0) { + hintShapedEtaMs = Math.round(hintRemainingMs * (avgActualMs / globalHintAvg)); + } + + // Always re-evaluate from live pace; hints may raise ETA when heavier work remains. + long eta = Math.max(rateEtaMs, hintShapedEtaMs); + + // If substantive tests are slower than history, raise remaining toward scaled hints. + double robustScale = computeScale(observedVsCachedCompleted); + if (robustScale > 1.0) { + double shrink = completedCount / (double) (completedCount + 15); + double softenedScale = 1.0 + shrink * (robustScale - 1.0); + eta = Math.max(eta, Math.round(hintRemainingMs * softenedScale)); + } + + return Math.max(0L, eta); } /** * How fast/slow this run is vs the historical cache for the same provider. * {@code 1.0} = on pace; {@code >1} = slower than history; {@code <1} = faster. + *

    + * Pairs that look like assumes/skips (tiny observed, huge cached) are ignored so they do not + * drag the scale to {@link #MIN_SCALE}. */ static double computeScale(Collection observedVsCachedCompleted) { if (observedVsCachedCompleted == null || observedVsCachedCompleted.isEmpty()) { @@ -212,13 +273,11 @@ static double computeScale(Collection observedVsCachedCompleted) { long observedSum = 0L; long cachedSum = 0L; for (long[] pair : observedVsCachedCompleted) { - if (pair == null || pair.length < 2) { + if (!isSubstantivePair(pair)) { continue; } - if (pair[0] > 0L && pair[1] > 0L) { - observedSum += pair[0]; - cachedSum += pair[1]; - } + observedSum += pair[0]; + cachedSum += pair[1]; } if (cachedSum <= 0L || observedSum <= 0L) { return 1.0; @@ -233,6 +292,37 @@ static double computeScale(Collection observedVsCachedCompleted) { return scale; } + /** + * {@code true} when the pair is usable for pace scaling (not an assume/skip vs huge cache). + */ + static boolean isSubstantivePair(long[] pair) { + if (pair == null || pair.length < 2) { + return false; + } + long observed = pair[0]; + long cached = pair[1]; + if (observed < SUBSTANTIVE_OBSERVED_MS || cached <= 0L) { + return false; + } + double skew = cached / (double) observed; + return skew <= MAX_PAIR_SKEW && (observed / (double) cached) <= MAX_PAIR_SKEW; + } + + private static double averagePositive(Collection values) { + if (values == null || values.isEmpty()) { + return 0.0; + } + long sum = 0L; + int count = 0; + for (Long value : values) { + if (value != null && value > 0L) { + sum += value; + count++; + } + } + return count == 0 ? 0.0 : sum / (double) count; + } + private static double fallbackAverageMs(Collection completedDurations, Map cachedTimings, long elapsedTimeMs) { diff --git a/itests/src/test/java/org/apache/unomi/itests/TestTimingCacheTest.java b/itests/src/test/java/org/apache/unomi/itests/TestTimingCacheTest.java index a5030fe19..cd2f2b15e 100644 --- a/itests/src/test/java/org/apache/unomi/itests/TestTimingCacheTest.java +++ b/itests/src/test/java/org/apache/unomi/itests/TestTimingCacheTest.java @@ -86,26 +86,76 @@ public void computeScaleUsesObservedOverCachedRatioAndClamps() { List slower = Collections.singletonList(new long[]{2_000L, 1_000L}); Assert.assertEquals(2.0, TestTimingCache.computeScale(slower), 0.0); - List tooFast = Collections.singletonList(new long[]{10L, 10_000L}); + // Substantive but very fast vs cache → clamp to MIN_SCALE (not ignored as assume-like) + List tooFast = Collections.singletonList(new long[]{300L, 2_000L}); Assert.assertEquals(TestTimingCache.MIN_SCALE, TestTimingCache.computeScale(tooFast), 0.0); - List tooSlow = Collections.singletonList(new long[]{50_000L, 1_000L}); + // Substantive slowdown within skew guard → clamp to MAX_SCALE + List tooSlow = Collections.singletonList(new long[]{15_000L, 1_000L}); Assert.assertEquals(TestTimingCache.MAX_SCALE, TestTimingCache.computeScale(tooSlow), 0.0); } @Test - public void estimateRemainingUsesScaledHistoryAndFallbackAverage() { + public void computeScaleIgnoresAssumeLikePairs() { + // 10ms observed vs 10s cached looks like a skip — must not drag scale to MIN_SCALE. + List skipPlusNormal = Arrays.asList( + new long[]{10L, 10_000L}, + new long[]{2_000L, 2_000L}); + Assert.assertEquals(1.0, TestTimingCache.computeScale(skipPlusNormal), 0.0); + } + + @Test + public void estimateRemainingUsesLivePaceWithHistoricalHints() { Map cached = new HashMap<>(); + // Suite average historical = (1000+3000+2000)/3 = 2000 cached.put("A#a", 1_000L); - cached.put("B#b", 2_000L); + cached.put("B#b", 3_000L); + cached.put("C#c", 2_000L); + + // Completed A in 500ms wall; remaining B (heavier) and C (average). + Set remaining = new HashSet<>(Arrays.asList("B#b", "C#c")); + List observedVsCached = Collections.singletonList(new long[]{500L, 1_000L}); + List completed = Collections.singletonList(500L); + long elapsed = 500L; + + long eta = TestTimingCache.estimateRemainingMs(remaining, cached, observedVsCached, completed, elapsed); + + // rateEta = 2 * 500 = 1000 + // hintShaped = (3000+2000) * (500/2000) = 1250 → heavier remaining raises ETA + Assert.assertEquals(1_250L, eta); + } + + @Test + public void estimateRemainingTracksWallClockPaceNotMinScaleCollapse() { + Map cached = new HashMap<>(); + for (int i = 0; i < 50; i++) { + cached.put("DoneIT#t" + i, 5_000L); + } + for (int i = 0; i < 250; i++) { + cached.put("TodoIT#t" + i, 5_000L); + } + + Set remaining = new HashSet<>(); + for (int i = 0; i < 250; i++) { + remaining.add("TodoIT#t" + i); + } + + List observedVsCached = new java.util.ArrayList<>(); + List completed = new java.util.ArrayList<>(); + // 50 tests in 200s wall (~4s each) while cache said 5s — realistic mild speedup + for (int i = 0; i < 50; i++) { + observedVsCached.add(new long[]{4_000L, 5_000L}); + completed.add(4_000L); + } + long elapsed = 200_000L; - Set remaining = new HashSet<>(Arrays.asList("A#a", "C#c")); - List observedVsCached = Collections.singletonList(new long[]{1_500L, 1_000L}); - List completed = Collections.singletonList(1_500L); + long eta = TestTimingCache.estimateRemainingMs(remaining, cached, observedVsCached, completed, elapsed); + // rate / hint-shaped ≈ 250 * 4000 = 1_000_000ms (~16.7m) + Assert.assertEquals(1_000_000L, eta); - // scale = 1.5 → A contributes 1500; C uncached → fallback avg 1500 - long eta = TestTimingCache.estimateRemainingMs(remaining, cached, observedVsCached, completed, 0L); - Assert.assertEquals(3_000L, eta); + // Old bug: MIN_SCALE * 250 * 5000 = 312_500 (~5.2m) — chronically too low + long oldBuggyEta = Math.round(250 * 5_000L * TestTimingCache.MIN_SCALE); + Assert.assertTrue(eta > oldBuggyEta); } @Test From bb0f67e0aa6ac6c45498a9f1a43fecc5c1699d8e Mon Sep 17 00:00:00 2001 From: Serge Huber Date: Tue, 21 Jul 2026 14:46:20 +0200 Subject: [PATCH 2/3] UNOMI-970: Fix live-pace ETA regressions from PR review Address review findings on the live-pace ETA calculation: - Derive live pace from the average of substantive completed test durations instead of elapsed/completedCount, which chronically inflated the ETA after any failed test (wall time counted, but the failure was excluded from the denominator) and could still collapse the ETA when many fast assume/skip completions preceded a block of heavy tests. - Make computeScale's skew guard one-directional so a genuine per-test regression (historically fast, now much slower) is no longer silently excluded from raising the ETA. - Replace the untyped (observed, cached) long[] pairs with a TimingSample record to remove ordering ambiguity. - Fix fallbackAverageMs's averaging to be consistent with the new averagePositive/averageAtLeast helper. - Stop TestTimingCache.save() from blending near-instant assume/skip durations into a test's historical average, which would otherwise gradually erode the hint used by estimateRemainingMs. Adds regression tests for each fix (including a mutation-tested check that the old elapsed/completedCount bug is actually caught) plus edge-case coverage for null/empty inputs. --- itests/README.md | 11 +- .../apache/unomi/itests/ProgressListener.java | 13 +- .../apache/unomi/itests/TestTimingCache.java | 130 +++++---- .../unomi/itests/TestTimingCacheTest.java | 250 +++++++++++++++++- 4 files changed, 339 insertions(+), 65 deletions(-) diff --git a/itests/README.md b/itests/README.md index 55f3eed25..701debae0 100644 --- a/itests/README.md +++ b/itests/README.md @@ -311,10 +311,13 @@ the `itests` module directory (survives `mvn clean`): `.test-timing-cache-.properties` One file per persistence provider (`elasticsearch`, `opensearch`, `postgresql`, …) -so timings are not mixed across backends. ETA is re-evaluated from **live suite pace** -(`elapsed / completed`) after every test; historical per-test durations are only hints -that reweight remaining work when harder/easier tests than average are still ahead. -Safe to delete; missing/unwritable cache falls back to the in-run average. +so timings are not mixed across backends. ETA is re-evaluated after every test from the +**live pace of substantive completed tests** (real work, excluding near-instant assume/skip-like +completions and any failed/aborted test, which are never counted towards pace); historical +per-test durations are only hints that reweight remaining work when harder/easier tests than +average are still ahead, and that can additionally raise the ETA if completed tests are +individually running slower than their own cached history. Safe to delete; missing/unwritable +cache falls back to the in-run average. ### Built-in backends diff --git a/itests/src/test/java/org/apache/unomi/itests/ProgressListener.java b/itests/src/test/java/org/apache/unomi/itests/ProgressListener.java index 66325fdc5..08e3eb948 100644 --- a/itests/src/test/java/org/apache/unomi/itests/ProgressListener.java +++ b/itests/src/test/java/org/apache/unomi/itests/ProgressListener.java @@ -155,8 +155,8 @@ private static class TestTime { private final Set remainingTestKeys; /** Durations (ms) of tests completed in this run */ private final List completedDurations = new CopyOnWriteArrayList<>(); - /** Pairs of [observedMs, cachedMs] for completed tests that had a historical entry */ - private final List observedVsCached = new CopyOnWriteArrayList<>(); + /** Samples of (observedMs, cachedMs) for completed tests that had a historical entry */ + private final List observedVsCached = new CopyOnWriteArrayList<>(); /** * Creates a new ProgressListener instance. @@ -330,7 +330,7 @@ public void testFinished(Description description) { completedDurations.add(testDuration); Long historical = cachedTimings.get(testKey); if (historical != null && historical > 0L) { - observedVsCached.add(new long[]{testDuration, historical}); + observedVsCached.add(new TestTimingCache.TimingSample(testDuration, historical)); } TestTimingCache.save(persistenceProvider, Collections.singletonMap(testKey, testDuration)); } @@ -493,14 +493,13 @@ private String escapeCsv(String value) { } /** - * Estimates remaining time from live suite pace ({@code elapsed / completed}), using the + * Estimates remaining time from the live pace of substantive completed tests, using the * provider-specific {@link TestTimingCache} as hints for how heavy the remaining tests are. * - * @param completed the number of tests completed so far * @param elapsedTime the time elapsed since the run started, in milliseconds * @return the estimated remaining time, in milliseconds */ - private long estimateRemainingTime(int completed, long elapsedTime) { + private long estimateRemainingTime(long elapsedTime) { return TestTimingCache.estimateRemainingMs( remainingTestKeys, cachedTimings, @@ -518,7 +517,7 @@ private void displayProgress() { int completed = completedTests.get(); long elapsedTime = System.currentTimeMillis() - startTime; - long estimatedRemainingTime = estimateRemainingTime(completed, elapsedTime); + long estimatedRemainingTime = estimateRemainingTime(elapsedTime); String progressBar = generateProgressBar(((double) completed / totalTests) * 100); String humanReadableTime = formatTime(estimatedRemainingTime); diff --git a/itests/src/test/java/org/apache/unomi/itests/TestTimingCache.java b/itests/src/test/java/org/apache/unomi/itests/TestTimingCache.java index d0793619e..dbeb1698f 100644 --- a/itests/src/test/java/org/apache/unomi/itests/TestTimingCache.java +++ b/itests/src/test/java/org/apache/unomi/itests/TestTimingCache.java @@ -56,22 +56,35 @@ final class TestTimingCache { /** * Clamp for the live-run vs historical scale factor so a few outliers cannot make ETA absurd. - * Used by {@link #computeScale}; {@link #estimateRemainingMs} prefers wall-clock pace instead. + * Used by {@link #computeScale}; {@link #estimateRemainingMs} uses the live substantive-test + * average as its primary pace signal and only applies this scale as an additional boost when + * completed tests are individually slower than their cached history. */ static final double MIN_SCALE = 0.25; static final double MAX_SCALE = 4.0; /** - * Observed durations below this are treated as non-representative for scale (assumes / empty tests). + * Observed durations below this are treated as non-representative for pace/scale purposes + * (assumes / skipped-in-substance tests that return almost instantly). */ static final long SUBSTANTIVE_OBSERVED_MS = 100L; /** - * Ignore observed/cached pairs more extreme than this when computing {@link #computeScale} - * (e.g. historically-slow test that skipped in milliseconds). + * Ignore a pair in {@link #computeScale} when its cached entry is more than this many times + * bigger than what was actually observed (e.g. a historically-slow test that now looks like it + * skipped in milliseconds). This is intentionally one-directional: a pair where {@code observed} + * is much bigger than {@code cached} is a genuine regression signal and is not excluded, so it + * can still raise the ETA. */ static final double MAX_PAIR_SKEW = 20.0; + /** + * An (observed, cached) duration sample for a single completed test that had a historical cache + * entry, used by {@link #computeScale} to judge live pace vs history for individual tests. + */ + record TimingSample(long observedMs, long cachedMs) { + } + private TestTimingCache() { } @@ -144,6 +157,10 @@ static Map load(String persistenceProvider) { * Merges freshly observed durations into the persisted cache for the given persistence provider, * smoothing each updated entry with an exponential moving average so a single unusually slow/fast * run doesn't swing future ETAs too far. + *

    + * Durations below {@link #SUBSTANTIVE_OBSERVED_MS} (assume/skip-like) are ignored entirely rather + * than blended in — a test that occasionally short-circuits via an early assume/skip would + * otherwise gradually drag its historical average down toward that non-representative value. * * @param persistenceProvider provider id the run just executed against * @param observedTimings durations (in milliseconds) observed during the run that just finished @@ -155,12 +172,21 @@ static void save(String persistenceProvider, Map observedTimings) Path cacheFile = cacheFile(persistenceProvider); try { Map merged = load(persistenceProvider); + boolean changed = false; for (Map.Entry entry : observedTimings.entrySet()) { + Long observed = entry.getValue(); + if (observed == null || observed < SUBSTANTIVE_OBSERVED_MS) { + continue; + } Long previous = merged.get(entry.getKey()); long updated = previous == null - ? entry.getValue() - : Math.round(previous * (1 - SMOOTHING) + entry.getValue() * SMOOTHING); + ? observed + : Math.round(previous * (1 - SMOOTHING) + observed * SMOOTHING); merged.put(entry.getKey(), updated); + changed = true; + } + if (!changed) { + return; } Properties props = new Properties(); merged.forEach((key, value) -> props.setProperty(key, String.valueOf(value))); @@ -181,28 +207,37 @@ static void save(String persistenceProvider, Map observedTimings) /** * Estimates remaining wall time for unfinished tests. *

    - * Real suite pace is primary: after every completion the estimate is rebuilt from - * {@code elapsed / completed}. Historical per-test durations are only hints that reweight - * remaining work when the leftover tests are historically heavier or lighter than the suite average - * (so a block of slow tests still ahead raises ETA above a flat per-test rate). + * Live pace is primary: the pace is the average duration of substantive + * completed tests this run (real work, excluding near-instant assume/skip-like completions — see + * {@link #SUBSTANTIVE_OBSERVED_MS}). Historical per-test durations are only hints that + * reweight remaining work when the leftover tests are historically heavier or lighter than the + * suite average (so a block of slow tests still ahead raises ETA above a flat per-test rate). + *

    + * Deriving pace from substantive durations only — rather than {@code elapsedTimeMs / completed} + * over every finished test — avoids two failure modes: (1) failed/aborted tests are never added to + * {@code completedDurations} (see the caller), so their wall time cannot inflate the pace the way a + * naive elapsed/count ratio would; (2) a run of fast assumes/skips before a block of heavy tests + * cannot drag the pace toward zero, since those near-instant completions are excluded from the + * average rather than counted as "typical" tests. *

    * A global “this run is 4× faster than cache” scale is not applied to shrink remaining * historical time — that is what made ETAs chronically too low after early assumes/skips. * If the run is slower than cache on substantive tests, remaining historical time is still - * raised accordingly. + * raised accordingly via {@link #computeScale}. *

    - * Cold start (nothing completed yet) falls back to the sum of historical hints (or a placeholder). + * Cold start (nothing substantive completed yet) falls back to the historical average pace, so + * remaining tests are estimated at their full cached weight until real live data says otherwise. * * @param remainingKeys keys still expected to run * @param cachedTimings historical durations for this persistence provider - * @param observedVsCachedCompleted pairs of (observedMs, cachedMs) for completed tests that had history - * @param completedDurations all completed durations this run (for fallback average) - * @param elapsedTimeMs wall time since suite start + * @param observedVsCachedCompleted samples of (observedMs, cachedMs) for completed tests that had history + * @param completedDurations successful completed durations this run (for live pace and fallback average) + * @param elapsedTimeMs wall time since suite start (used only to gate the cold-start case) * @return estimated remaining milliseconds (never negative) */ static long estimateRemainingMs(Collection remainingKeys, Map cachedTimings, - Collection observedVsCachedCompleted, + Collection observedVsCachedCompleted, Collection completedDurations, long elapsedTimeMs) { int remainingCount = remainingKeys == null ? 0 : remainingKeys.size(); @@ -232,7 +267,13 @@ static long estimateRemainingMs(Collection remainingKeys, return Math.max(0L, hintRemainingMs); } - double avgActualMs = elapsedTimeMs / (double) completedCount; + // Live pace comes only from substantive completions so neither a batch of trivial + // assume/skip successes nor (by construction — see caller) any failed/aborted test's wall + // time can skew it; fall back to the historical average until we have such a data point. + double substantiveAvgMs = averageAtLeast(completedDurations, SUBSTANTIVE_OBSERVED_MS); + double avgActualMs = substantiveAvgMs > 0.0 ? substantiveAvgMs + : (globalHintAvg > 0.0 ? globalHintAvg : fallbackAvg); + // Flat live pace: every remaining test takes as long as the average so far. long rateEtaMs = Math.round(remainingCount * avgActualMs); @@ -266,18 +307,18 @@ static long estimateRemainingMs(Collection remainingKeys, * Pairs that look like assumes/skips (tiny observed, huge cached) are ignored so they do not * drag the scale to {@link #MIN_SCALE}. */ - static double computeScale(Collection observedVsCachedCompleted) { + static double computeScale(Collection observedVsCachedCompleted) { if (observedVsCachedCompleted == null || observedVsCachedCompleted.isEmpty()) { return 1.0; } long observedSum = 0L; long cachedSum = 0L; - for (long[] pair : observedVsCachedCompleted) { - if (!isSubstantivePair(pair)) { + for (TimingSample sample : observedVsCachedCompleted) { + if (!isSubstantivePair(sample)) { continue; } - observedSum += pair[0]; - cachedSum += pair[1]; + observedSum += sample.observedMs(); + cachedSum += sample.cachedMs(); } if (cachedSum <= 0L || observedSum <= 0L) { return 1.0; @@ -293,29 +334,38 @@ static double computeScale(Collection observedVsCachedCompleted) { } /** - * {@code true} when the pair is usable for pace scaling (not an assume/skip vs huge cache). + * {@code true} when the sample is usable for pace scaling (not an assume/skip vs huge cache). + * See {@link #MAX_PAIR_SKEW} for why this is one-directional. */ - static boolean isSubstantivePair(long[] pair) { - if (pair == null || pair.length < 2) { + static boolean isSubstantivePair(TimingSample sample) { + if (sample == null) { return false; } - long observed = pair[0]; - long cached = pair[1]; + long observed = sample.observedMs(); + long cached = sample.cachedMs(); if (observed < SUBSTANTIVE_OBSERVED_MS || cached <= 0L) { return false; } double skew = cached / (double) observed; - return skew <= MAX_PAIR_SKEW && (observed / (double) cached) <= MAX_PAIR_SKEW; + return skew <= MAX_PAIR_SKEW; } private static double averagePositive(Collection values) { + return averageAtLeast(values, 1L); + } + + /** + * Average of the values that are {@code >= minValue}, ignoring everything else (missing, + * non-positive, or below the threshold). {@code 0.0} when nothing qualifies. + */ + private static double averageAtLeast(Collection values, long minValue) { if (values == null || values.isEmpty()) { return 0.0; } long sum = 0L; int count = 0; for (Long value : values) { - if (value != null && value > 0L) { + if (value != null && value >= minValue) { sum += value; count++; } @@ -326,23 +376,13 @@ private static double averagePositive(Collection values) { private static double fallbackAverageMs(Collection completedDurations, Map cachedTimings, long elapsedTimeMs) { - if (completedDurations != null && !completedDurations.isEmpty()) { - long sum = 0L; - for (Long d : completedDurations) { - if (d != null && d > 0L) { - sum += d; - } - } - return sum / (double) completedDurations.size(); + double avg = averagePositive(completedDurations); + if (avg > 0.0) { + return avg; } - if (cachedTimings != null && !cachedTimings.isEmpty()) { - long sum = 0L; - for (Long d : cachedTimings.values()) { - if (d != null && d > 0L) { - sum += d; - } - } - return sum / (double) cachedTimings.size(); + avg = averagePositive(cachedTimings != null ? cachedTimings.values() : null); + if (avg > 0.0) { + return avg; } // Cold start: tiny placeholder so ETA is non-zero until the first test finishes return elapsedTimeMs > 0L ? elapsedTimeMs : 30_000L; diff --git a/itests/src/test/java/org/apache/unomi/itests/TestTimingCacheTest.java b/itests/src/test/java/org/apache/unomi/itests/TestTimingCacheTest.java index cd2f2b15e..bb32c4969 100644 --- a/itests/src/test/java/org/apache/unomi/itests/TestTimingCacheTest.java +++ b/itests/src/test/java/org/apache/unomi/itests/TestTimingCacheTest.java @@ -75,6 +75,48 @@ public void saveAndLoadRoundTripPerProvider() { Assert.assertTrue(TestTimingCache.load("opensearch").isEmpty()); } + @Test + public void saveIgnoresSkipLikeDurationForNewKey() { + // A brand new key whose only observation so far is a near-instant assume/skip must not create + // a cache entry at all — persisting it would seed the history with a non-representative value. + TestTimingCache.save("elasticsearch", Collections.singletonMap("SkipIT#skip", 50L)); + Assert.assertNull(TestTimingCache.load("elasticsearch").get("SkipIT#skip")); + } + + @Test + public void saveDoesNotErodeHistoryWithLaterSkipLikeDuration() { + // A test that's usually substantial (3000ms) but occasionally short-circuits via an assume/skip + // (50ms) must keep its real historical average — the skip observation must not be blended in. + TestTimingCache.save("elasticsearch", Collections.singletonMap("FlakySkipIT#test", 3_000L)); + Assert.assertEquals(Long.valueOf(3_000L), TestTimingCache.load("elasticsearch").get("FlakySkipIT#test")); + + TestTimingCache.save("elasticsearch", Collections.singletonMap("FlakySkipIT#test", 50L)); + Assert.assertEquals(Long.valueOf(3_000L), TestTimingCache.load("elasticsearch").get("FlakySkipIT#test")); + } + + @Test + public void saveStillSmoothsSubstantiveDurations() { + // Sanity check that the skip-filter didn't disable smoothing for genuine observations. + TestTimingCache.save("elasticsearch", Collections.singletonMap("SmoothedIT#test", 1_000L)); + TestTimingCache.save("elasticsearch", Collections.singletonMap("SmoothedIT#test", 2_000L)); + + // updated = 1000*(1-0.3) + 2000*0.3 = 1300 + Assert.assertEquals(Long.valueOf(1_300L), TestTimingCache.load("elasticsearch").get("SmoothedIT#test")); + } + + @Test + public void saveOnlyPersistsSubstantiveEntriesFromMixedBatch() { + Map mixed = new HashMap<>(); + mixed.put("HeavyIT#real", 5_000L); + mixed.put("SkipIT#skip", 10L); + + TestTimingCache.save("elasticsearch", mixed); + + Map loaded = TestTimingCache.load("elasticsearch"); + Assert.assertEquals(Long.valueOf(5_000L), loaded.get("HeavyIT#real")); + Assert.assertNull(loaded.get("SkipIT#skip")); + } + @Test public void computeScaleDefaultsToOneWithoutPairs() { Assert.assertEquals(1.0, TestTimingCache.computeScale(Collections.emptyList()), 0.0); @@ -83,27 +125,40 @@ public void computeScaleDefaultsToOneWithoutPairs() { @Test public void computeScaleUsesObservedOverCachedRatioAndClamps() { - List slower = Collections.singletonList(new long[]{2_000L, 1_000L}); + List slower = + Collections.singletonList(new TestTimingCache.TimingSample(2_000L, 1_000L)); Assert.assertEquals(2.0, TestTimingCache.computeScale(slower), 0.0); // Substantive but very fast vs cache → clamp to MIN_SCALE (not ignored as assume-like) - List tooFast = Collections.singletonList(new long[]{300L, 2_000L}); + List tooFast = + Collections.singletonList(new TestTimingCache.TimingSample(300L, 2_000L)); Assert.assertEquals(TestTimingCache.MIN_SCALE, TestTimingCache.computeScale(tooFast), 0.0); // Substantive slowdown within skew guard → clamp to MAX_SCALE - List tooSlow = Collections.singletonList(new long[]{15_000L, 1_000L}); + List tooSlow = + Collections.singletonList(new TestTimingCache.TimingSample(15_000L, 1_000L)); Assert.assertEquals(TestTimingCache.MAX_SCALE, TestTimingCache.computeScale(tooSlow), 0.0); } @Test public void computeScaleIgnoresAssumeLikePairs() { // 10ms observed vs 10s cached looks like a skip — must not drag scale to MIN_SCALE. - List skipPlusNormal = Arrays.asList( - new long[]{10L, 10_000L}, - new long[]{2_000L, 2_000L}); + List skipPlusNormal = Arrays.asList( + new TestTimingCache.TimingSample(10L, 10_000L), + new TestTimingCache.TimingSample(2_000L, 2_000L)); Assert.assertEquals(1.0, TestTimingCache.computeScale(skipPlusNormal), 0.0); } + @Test + public void computeScaleDoesNotIgnoreGenuineRegressions() { + // Historically fast (50ms) test now takes 25x longer (1_250ms): a real regression, not a + // skip/assume artifact, so it must still count towards raising the scale (clamped to MAX_SCALE + // since 25x exceeds it) rather than being filtered out by the skew guard. + List regressed = + Collections.singletonList(new TestTimingCache.TimingSample(1_250L, 50L)); + Assert.assertEquals(TestTimingCache.MAX_SCALE, TestTimingCache.computeScale(regressed), 0.0); + } + @Test public void estimateRemainingUsesLivePaceWithHistoricalHints() { Map cached = new HashMap<>(); @@ -114,7 +169,8 @@ public void estimateRemainingUsesLivePaceWithHistoricalHints() { // Completed A in 500ms wall; remaining B (heavier) and C (average). Set remaining = new HashSet<>(Arrays.asList("B#b", "C#c")); - List observedVsCached = Collections.singletonList(new long[]{500L, 1_000L}); + List observedVsCached = + Collections.singletonList(new TestTimingCache.TimingSample(500L, 1_000L)); List completed = Collections.singletonList(500L); long elapsed = 500L; @@ -140,11 +196,11 @@ public void estimateRemainingTracksWallClockPaceNotMinScaleCollapse() { remaining.add("TodoIT#t" + i); } - List observedVsCached = new java.util.ArrayList<>(); + List observedVsCached = new java.util.ArrayList<>(); List completed = new java.util.ArrayList<>(); // 50 tests in 200s wall (~4s each) while cache said 5s — realistic mild speedup for (int i = 0; i < 50; i++) { - observedVsCached.add(new long[]{4_000L, 5_000L}); + observedVsCached.add(new TestTimingCache.TimingSample(4_000L, 5_000L)); completed.add(4_000L); } long elapsed = 200_000L; @@ -158,6 +214,81 @@ public void estimateRemainingTracksWallClockPaceNotMinScaleCollapse() { Assert.assertTrue(eta > oldBuggyEta); } + @Test + public void estimateRemainingUnaffectedByFailedTestWallTime() { + // ProgressListener never adds a failed/aborted test's duration to completedDurations (see + // testFinished), but the suite-wide elapsed clock keeps advancing regardless of outcome. + // The ETA must be driven by the one substantive success, not by elapsed/completedCount + // (which would have been 50_200 / 1 = 50_200ms/test — a ~250x inflation). + Map cached = new HashMap<>(); + cached.put("FlakyIT#a", 200L); + cached.put("FlakyIT#b", 200L); + + Set remaining = new HashSet<>(Collections.singletonList("FlakyIT#b")); + List completed = Collections.singletonList(200L); + long elapsedIncludingFailures = 50_200L; // 10 failed tests @ 5s each + the 200ms success + + long eta = TestTimingCache.estimateRemainingMs( + remaining, cached, Collections.emptyList(), completed, elapsedIncludingFailures); + + Assert.assertEquals(200L, eta); + } + + @Test + public void estimateRemainingIgnoresAssumeDilutionInLivePace() { + // 50 assume-like tests complete in ~50ms each (below SUBSTANTIVE_OBSERVED_MS) before any of + // the 250 historically-heavy tests have run. The old elapsed/completedCount pace would have + // been dragged down to ~50ms/test, collapsing the ETA for the heavy tests still ahead. + Map cached = new HashMap<>(); + for (int i = 0; i < 50; i++) { + cached.put("SkipIT#t" + i, 50L); + } + for (int i = 0; i < 250; i++) { + cached.put("HeavyIT#t" + i, 5_000L); + } + + Set remaining = new HashSet<>(); + for (int i = 0; i < 250; i++) { + remaining.add("HeavyIT#t" + i); + } + + List completed = new java.util.ArrayList<>(); + for (int i = 0; i < 50; i++) { + completed.add(50L); + } + long elapsed = 50L * 50L; + + long eta = TestTimingCache.estimateRemainingMs( + remaining, cached, Collections.emptyList(), completed, elapsed); + + // No substantive completions yet → live pace falls back to the historical average, so the + // heavy remaining tests are estimated at their full cached weight (250 * 5_000 = 1_250_000), + // not diluted down toward the ~50ms/test pace of the skips seen so far. + Assert.assertEquals(1_250_000L, eta); + } + + @Test + public void estimateRemainingAppliesSlowdownBoostWhenSubstantiveScaleExceedsOne() { + // A completed on the same key family as remaining R, but 4x slower than its own cache entry — + // a genuine per-test regression that should raise the ETA above the plain hint-shaped estimate. + Map cached = new HashMap<>(); + cached.put("A#a", 50L); + cached.put("R#r", 1_000L); + + Set remaining = new HashSet<>(Collections.singletonList("R#r")); + List observedVsCached = + Collections.singletonList(new TestTimingCache.TimingSample(200L, 50L)); + List completed = Collections.singletonList(200L); + long elapsed = 200L; + + long eta = TestTimingCache.estimateRemainingMs(remaining, cached, observedVsCached, completed, elapsed); + + // Un-boosted hint-shaped estimate: 1000 * (200/525) ≈ 381 + // robustScale = 200/50 = 4.0 (MAX_SCALE); shrink = 1/(1+15); softenedScale = 1 + shrink*3 = 1.1875 + // boosted estimate: 1000 * 1.1875 = 1187.5 → 1188, which wins over the un-boosted 381 + Assert.assertEquals(1_188L, eta); + } + @Test public void estimateRemainingUsesHistoricalAverageWhenNothingCompleted() { Map cached = new HashMap<>(); @@ -170,4 +301,105 @@ public void estimateRemainingUsesHistoricalAverageWhenNothingCompleted() { // avg of history = 2000 Assert.assertEquals(2_000L, eta); } + + @Test + public void estimateRemainingReturnsZeroForEmptyOrNullRemainingKeys() { + Map cached = Collections.singletonMap("A#a", 1_000L); + List completed = Collections.singletonList(500L); + + Assert.assertEquals(0L, TestTimingCache.estimateRemainingMs( + Collections.emptySet(), cached, Collections.emptyList(), completed, 500L)); + Assert.assertEquals(0L, TestTimingCache.estimateRemainingMs( + null, cached, Collections.emptyList(), completed, 500L)); + } + + @Test + public void estimateRemainingHandlesNullCachedTimingsGracefully() { + // No historical cache at all (e.g. first-ever run, or an unreadable cache file) — must not NPE + // and should fall back entirely to the in-run average. + Set remaining = new HashSet<>(Collections.singletonList("X#x")); + List completed = Collections.singletonList(500L); + + long eta = TestTimingCache.estimateRemainingMs( + remaining, null, Collections.emptyList(), completed, 500L); + + // fallbackAvg = avg(completed) = 500; no cache to weigh against, so live pace and hint-shaped + // estimate both resolve to the plain average. + Assert.assertEquals(500L, eta); + } + + @Test + public void estimateRemainingUsesFallbackAverageForUncachedRemainingKey() { + // "Cached#x" has a direct historical entry; "Uncached#y" does not and must fall back to the + // average of the historical cache (not 0, and not just re-using Cached#x's own value). + Map cached = new HashMap<>(); + cached.put("Cached#x", 1_000L); + cached.put("Other#unrelated", 3_000L); + + Set remaining = new HashSet<>(Arrays.asList("Cached#x", "Uncached#y")); + long eta = TestTimingCache.estimateRemainingMs( + remaining, cached, Collections.emptyList(), Collections.emptyList(), 0L); + + // Cold start (nothing completed): hintRemainingMs = cached("Cached#x")=1000 + // + fallbackAvg(avg of cache = 2000) = 3000 + Assert.assertEquals(3_000L, eta); + } + + @Test + public void estimateRemainingTreatsNonPositiveElapsedAsColdStart() { + // A negative/zero elapsed reading (e.g. clock oddity) must be treated like cold start rather + // than feeding a nonsensical value into the live-pace division. + Map cached = Collections.singletonMap("X#x", 1_000L); + Set remaining = new HashSet<>(Collections.singletonList("X#x")); + List completed = Collections.singletonList(500L); + + long eta = TestTimingCache.estimateRemainingMs(remaining, cached, Collections.emptyList(), completed, -100L); + Assert.assertEquals(1_000L, eta); + } + + @Test + public void estimateRemainingIgnoresSkipDurationWhenAveragingSubstantiveCompletions() { + // A mix of one assume-like completion (50ms) and one substantive completion (3000ms) must + // average pace from the substantive one only (3000), not the diluted blended average (1525). + Map cached = Collections.singletonMap("R#r", 1_000L); + Set remaining = new HashSet<>(Collections.singletonList("R#r")); + List completed = Arrays.asList(50L, 3_000L); + + long eta = TestTimingCache.estimateRemainingMs( + remaining, cached, Collections.emptyList(), completed, 3_050L); + + Assert.assertEquals(3_000L, eta); + } + + @Test + public void isSubstantivePairBoundaryConditions() { + Assert.assertFalse(TestTimingCache.isSubstantivePair(null)); + + // Observed below SUBSTANTIVE_OBSERVED_MS → excluded regardless of cached. + Assert.assertFalse(TestTimingCache.isSubstantivePair(new TestTimingCache.TimingSample(99L, 1_000L))); + + // Observed exactly at the threshold → substantive (strict "<" check, not "<="). + Assert.assertTrue(TestTimingCache.isSubstantivePair(new TestTimingCache.TimingSample(100L, 100L))); + + // Non-positive cached → excluded regardless of observed. + Assert.assertFalse(TestTimingCache.isSubstantivePair(new TestTimingCache.TimingSample(1_000L, 0L))); + + // Skew exactly at MAX_PAIR_SKEW → still substantive ("<=" boundary is inclusive). + Assert.assertTrue(TestTimingCache.isSubstantivePair(new TestTimingCache.TimingSample(100L, 2_000L))); + + // Skew just past MAX_PAIR_SKEW → excluded as assume/skip-like. + Assert.assertFalse(TestTimingCache.isSubstantivePair(new TestTimingCache.TimingSample(100L, 2_001L))); + + // observed >> cached (a genuine regression, the opposite direction) has no upper bound and is + // never excluded — this is the one-directional behavior the skew guard is meant to have. + Assert.assertTrue(TestTimingCache.isSubstantivePair(new TestTimingCache.TimingSample(1_000_000L, 1L))); + } + + @Test + public void computeScaleToleratesNullSampleInCollection() { + List withNull = Arrays.asList( + null, + new TestTimingCache.TimingSample(1_000L, 1_000L)); + Assert.assertEquals(1.0, TestTimingCache.computeScale(withNull), 0.0); + } } From c78253536ea176026daf0754f47ee20f81b89737 Mon Sep 17 00:00:00 2001 From: Serge Huber Date: Tue, 21 Jul 2026 15:30:56 +0200 Subject: [PATCH 3/3] UNOMI-970: Address code-review findings on live-pace ETA logic MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - Fix ProgressListener to override testAssumptionFailure so JUnit Assume-based skips (e.g. RolloverIT's backend-capability gating) are excluded from the timing cache/live pace the same way hard failures already were — previously they silently flowed through testFinished as full successes, contradicting the documented behavior. - Make estimateRemainingMs's historical-hint reweighting genuinely bidirectional: remove the Math.max(rateEtaMs, hintShapedEtaMs) floor that made hints raise-only, so historically lighter remaining work can now lower the ETA below flat live pace, not just raise it. - Consolidate ProgressListener's two always-together-mutated lists (completedDurations, observedVsCached) into a single CompletedSample per completed test, removing an untyped-parallel-collection hazard without changing TestTimingCache's tested public API. - Cap the true-cold-start ETA placeholder (COLD_START_PLACEHOLDER_CAP_MS) so a stalled start with no successes/no cache can't balloon the displayed ETA unboundedly with elapsed time. - Harden TestTimingCache.save()/load(): distinguish expected I/O failures from unexpected RuntimeExceptions (the latter now logged at WARN with a full stack trace instead of silently swallowed), clean up orphaned temp files on a failed write, and log malformed cache entries instead of dropping them silently. - Fix stale/misleading Javadoc (MAX_PAIR_SKEW's own example was already excluded by a different gate; the elapsed/cold-start parameter docs didn't match the actual guard). - Add ProgressListenerTest exercising the real JUnit RunListener wiring (testFailure/testAssumptionFailure/testFinished/testIgnored), plus new TestTimingCacheTest coverage for the bidirectional hint fix, the slowdown-boost ramp at scale, and the capped cold-start placeholder. Co-Authored-By: Claude Sonnet 5 --- .../apache/unomi/itests/ProgressListener.java | 71 +++++-- .../unomi/itests/ProgressListenerTest.java | 183 ++++++++++++++++++ .../apache/unomi/itests/TestTimingCache.java | 95 +++++---- .../unomi/itests/TestTimingCacheTest.java | 85 +++++++- 4 files changed, 379 insertions(+), 55 deletions(-) create mode 100644 itests/src/test/java/org/apache/unomi/itests/ProgressListenerTest.java diff --git a/itests/src/test/java/org/apache/unomi/itests/ProgressListener.java b/itests/src/test/java/org/apache/unomi/itests/ProgressListener.java index 08e3eb948..0ac12d0d0 100644 --- a/itests/src/test/java/org/apache/unomi/itests/ProgressListener.java +++ b/itests/src/test/java/org/apache/unomi/itests/ProgressListener.java @@ -28,6 +28,7 @@ import java.time.format.DateTimeFormatter; import java.util.ArrayList; import java.util.Collections; +import java.util.HashSet; import java.util.List; import java.util.Map; import java.util.PriorityQueue; @@ -99,6 +100,18 @@ public class ProgressListener extends RunListener { "Hardships often prepare ordinary people for an extraordinary destiny. - C.S. Lewis" }; + /** + * A single successfully-completed test's duration this run, with its historical cached duration + * when one exists. Replaces what used to be two separately-mutated parallel lists (durations, and + * observed-vs-cached pairs) with one sample per completed test, so the two views derived from it + * (see {@link #estimateRemainingTime}) can never desync from each other. + */ + private record CompletedSample(long durationMs, Long cachedMs) { + boolean hasHistoricalMatch() { + return cachedMs != null && cachedMs > 0L; + } + } + /** * Inner class representing a test execution time record. * Used to track individual test performance for reporting the slowest tests. @@ -144,6 +157,13 @@ private static class TestTime { * timing cache (aborted / assertion failures skew historical ETAs). */ private boolean currentTestFailed; + /** + * Set in {@link #testAssumptionFailure} before {@link #testFinished}. An {@code Assume}-based skip + * is not a failure (JUnit does not count it as one — see {@link #testAssumptionFailure}), but its + * duration must be excluded from the timing cache/live pace the same way a hard failure's is, or a + * capability-check test that occasionally short-circuits via assume would pollute its own history. + */ + private boolean currentTestAssumptionFailed; /** Formatter for human-readable timestamps */ private static final DateTimeFormatter TIMESTAMP_FORMATTER = DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss"); @@ -153,10 +173,8 @@ private static class TestTime { private final Map cachedTimings; /** Timing-cache keys for tests not yet completed in this run */ private final Set remainingTestKeys; - /** Durations (ms) of tests completed in this run */ - private final List completedDurations = new CopyOnWriteArrayList<>(); - /** Samples of (observedMs, cachedMs) for completed tests that had a historical entry */ - private final List observedVsCached = new CopyOnWriteArrayList<>(); + /** Samples for tests completed successfully in this run; see {@link CompletedSample}. */ + private final List completedSamples = new CopyOnWriteArrayList<>(); /** * Creates a new ProgressListener instance. @@ -288,6 +306,7 @@ public void testRunStarted(Description description) { @Override public void testStarted(Description description) { currentTestFailed = false; + currentTestAssumptionFailed = false; startTestTime = System.currentTimeMillis(); // Print test start boundary with test name String testName = extractTestName(description); @@ -312,7 +331,9 @@ public void testFinished(Description description) { long endTestTime = System.currentTimeMillis(); long testDuration = endTestTime - startTestTime; boolean failed = currentTestFailed; + boolean skippedByAssumption = currentTestAssumptionFailed; currentTestFailed = false; + currentTestAssumptionFailed = false; completedTests.incrementAndGet(); successfulTests.incrementAndGet(); // Default to success unless a failure is recorded separately. @@ -324,14 +345,11 @@ public void testFinished(Description description) { String testKey = TestTimingCache.keyFor(description); remainingTestKeys.remove(testKey); - // Persist only successes: failure/abort durations pollute the provider cache and ETA scale. - // Write after every successful test (not only at suite end) so Ctrl-C / CI kill keeps progress. - if (!failed) { - completedDurations.add(testDuration); - Long historical = cachedTimings.get(testKey); - if (historical != null && historical > 0L) { - observedVsCached.add(new TestTimingCache.TimingSample(testDuration, historical)); - } + // Persist only substantive successes: a hard failure's or an assume-based skip's duration must + // not pollute the provider cache/ETA pace. Write after every such test (not only at suite end) + // so Ctrl-C / CI kill keeps progress. + if (!failed && !skippedByAssumption) { + completedSamples.add(new CompletedSample(testDuration, cachedTimings.get(testKey))); TestTimingCache.save(persistenceProvider, Collections.singletonMap(testKey, testDuration)); } @@ -360,6 +378,20 @@ public void testIgnored(Description description) { displayProgress(); } + /** + * Called when a test aborts via {@code Assume.assumeTrue}/{@code assumeFalse} (before + * {@link #testFinished}). JUnit does not treat this as a failure — {@link Result#wasSuccessful()} + * is unaffected and success/failure counters here are intentionally left untouched — but the test's + * duration must still be excluded from the timing cache/live pace, or a capability-gated test (e.g. + * {@code RolloverIT}) that occasionally short-circuits via assume would pollute its own history. + * + * @param failure the assumption-failure information + */ + @Override + public void testAssumptionFailure(Failure failure) { + currentTestAssumptionFailed = true; + } + /** * Called when a test fails (before {@link #testFinished}). Marks the test so its duration is * not written to the timing cache. @@ -500,6 +532,14 @@ private String escapeCsv(String value) { * @return the estimated remaining time, in milliseconds */ private long estimateRemainingTime(long elapsedTime) { + List completedDurations = new ArrayList<>(completedSamples.size()); + List observedVsCached = new ArrayList<>(); + for (CompletedSample sample : completedSamples) { + completedDurations.add(sample.durationMs()); + if (sample.hasHistoricalMatch()) { + observedVsCached.add(new TestTimingCache.TimingSample(sample.durationMs(), sample.cachedMs())); + } + } return TestTimingCache.estimateRemainingMs( remainingTestKeys, cachedTimings, @@ -508,6 +548,13 @@ private long estimateRemainingTime(long elapsedTime) { elapsedTime); } + /** + * Test-support accessor for the timing-cache keys not yet completed in this run. + */ + Set remainingTestKeysSnapshot() { + return new HashSet<>(remainingTestKeys); + } + /** * Displays the current progress of the test run including progress bar, * percentage completion, estimated time remaining, and success/failure counts. diff --git a/itests/src/test/java/org/apache/unomi/itests/ProgressListenerTest.java b/itests/src/test/java/org/apache/unomi/itests/ProgressListenerTest.java new file mode 100644 index 000000000..ade7b2ce6 --- /dev/null +++ b/itests/src/test/java/org/apache/unomi/itests/ProgressListenerTest.java @@ -0,0 +1,183 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.unomi.itests; + +import org.apache.unomi.itests.persistence.PersistenceITBackendResolver; +import org.junit.After; +import org.junit.Assert; +import org.junit.AssumptionViolatedException; +import org.junit.Before; +import org.junit.Test; +import org.junit.runner.Description; +import org.junit.runner.notification.Failure; + +import java.nio.file.Files; +import java.nio.file.Path; +import java.util.Arrays; +import java.util.concurrent.atomic.AtomicInteger; + +/** + * Exercises {@link ProgressListener}'s actual JUnit {@code RunListener} callback wiring — as opposed to + * {@link TestTimingCacheTest}, which only exercises {@link TestTimingCache}'s pure helpers directly with + * hand-built inputs. In particular this covers the {@code currentTestFailed}/{@code + * currentTestAssumptionFailed} flag lifecycle across {@code testStarted}/{@code testFailure}/{@code + * testAssumptionFailure}/{@code testFinished}, which decides whether a completed test's duration reaches + * {@link TestTimingCache}. + */ +public class ProgressListenerTest { + + /** Comfortably above {@link TestTimingCache#SUBSTANTIVE_OBSERVED_MS} so save() doesn't filter it out. */ + private static final long SUBSTANTIVE_SLEEP_MS = 150L; + + private String previousUserDir; + private Path tempDir; + + @Before + public void setUp() throws Exception { + previousUserDir = System.getProperty("user.dir"); + tempDir = Files.createTempDirectory("unomi-progress-listener-test"); + System.setProperty("user.dir", tempDir.toAbsolutePath().toString()); + } + + @After + public void tearDown() { + if (previousUserDir != null) { + System.setProperty("user.dir", previousUserDir); + } + } + + private static Description descriptionFor(String methodName) { + return Description.createTestDescription(ProgressListenerTest.class, methodName); + } + + private static ProgressListener newListener(String... testKeys) { + return new ProgressListener(testKeys.length, new AtomicInteger(0), Arrays.asList(testKeys)); + } + + private static String provider() { + return PersistenceITBackendResolver.resolveProviderId(); + } + + @Test + public void successfulTestPersistsDurationToTimingCache() throws Exception { + ProgressListener listener = newListener("ProgressListenerTest#ok"); + Description description = descriptionFor("ok"); + + listener.testStarted(description); + Thread.sleep(SUBSTANTIVE_SLEEP_MS); + listener.testFinished(description); + + Long persisted = TestTimingCache.load(provider()).get("ProgressListenerTest#ok"); + Assert.assertNotNull("a successful test's duration should be persisted to the timing cache", persisted); + Assert.assertTrue(persisted > 0L); + } + + @Test + public void failedTestDurationIsNotPersistedToTimingCache() throws Exception { + ProgressListener listener = newListener("ProgressListenerTest#failing"); + Description description = descriptionFor("failing"); + + listener.testStarted(description); + Thread.sleep(SUBSTANTIVE_SLEEP_MS); + listener.testFailure(new Failure(description, new AssertionError("boom"))); + listener.testFinished(description); + + Assert.assertNull("a failed test's duration must not pollute the timing cache", + TestTimingCache.load(provider()).get("ProgressListenerTest#failing")); + } + + @Test + public void assumptionFailureDurationIsNotPersistedToTimingCache() throws Exception { + // Regression coverage: ProgressListener must override testAssumptionFailure (JUnit's callback + // for Assume.assumeTrue/assumeFalse-based skips, e.g. RolloverIT's backend-capability gating) — + // without it, an assume-skipped test flows through testFinished exactly like a success and its + // duration would be persisted. + ProgressListener listener = newListener("ProgressListenerTest#skipped"); + Description description = descriptionFor("skipped"); + + listener.testStarted(description); + Thread.sleep(SUBSTANTIVE_SLEEP_MS); + listener.testAssumptionFailure(new Failure(description, + new AssumptionViolatedException("backend does not support this"))); + listener.testFinished(description); + + Assert.assertNull("an assume-skipped test's duration must not pollute the timing cache", + TestTimingCache.load(provider()).get("ProgressListenerTest#skipped")); + } + + @Test + public void currentTestFlagsResetBetweenTests() throws Exception { + // A failure on test #1 must not suppress the timing-cache write for test #2. + ProgressListener listener = newListener("ProgressListenerTest#first", "ProgressListenerTest#second"); + Description first = descriptionFor("first"); + Description second = descriptionFor("second"); + + listener.testStarted(first); + listener.testFailure(new Failure(first, new AssertionError("boom"))); + listener.testFinished(first); + + listener.testStarted(second); + Thread.sleep(SUBSTANTIVE_SLEEP_MS); + listener.testFinished(second); + + Assert.assertNull(TestTimingCache.load(provider()).get("ProgressListenerTest#first")); + Assert.assertNotNull("the failed flag must reset so the next test persists normally", + TestTimingCache.load(provider()).get("ProgressListenerTest#second")); + } + + @Test + public void currentTestAssumptionFlagResetsBetweenTests() throws Exception { + // Same as currentTestFlagsResetBetweenTests, but for the assumption-failure flag specifically. + ProgressListener listener = newListener("ProgressListenerTest#skippedFirst", "ProgressListenerTest#second"); + Description first = descriptionFor("skippedFirst"); + Description second = descriptionFor("second"); + + listener.testStarted(first); + listener.testAssumptionFailure(new Failure(first, new AssumptionViolatedException("skip"))); + listener.testFinished(first); + + listener.testStarted(second); + Thread.sleep(SUBSTANTIVE_SLEEP_MS); + listener.testFinished(second); + + Assert.assertNull(TestTimingCache.load(provider()).get("ProgressListenerTest#skippedFirst")); + Assert.assertNotNull("the assumption-failed flag must reset so the next test persists normally", + TestTimingCache.load(provider()).get("ProgressListenerTest#second")); + } + + @Test + public void ignoredTestIsRemovedFromRemainingKeys() { + ProgressListener listener = newListener("ProgressListenerTest#ignoredOne", "ProgressListenerTest#other"); + listener.testIgnored(descriptionFor("ignoredOne")); + + Assert.assertFalse(listener.remainingTestKeysSnapshot().contains("ProgressListenerTest#ignoredOne")); + Assert.assertTrue(listener.remainingTestKeysSnapshot().contains("ProgressListenerTest#other")); + } + + @Test + public void finishedTestIsRemovedFromRemainingKeys() throws Exception { + ProgressListener listener = newListener("ProgressListenerTest#done", "ProgressListenerTest#other"); + Description description = descriptionFor("done"); + + listener.testStarted(description); + Thread.sleep(SUBSTANTIVE_SLEEP_MS); + listener.testFinished(description); + + Assert.assertFalse(listener.remainingTestKeysSnapshot().contains("ProgressListenerTest#done")); + Assert.assertTrue(listener.remainingTestKeysSnapshot().contains("ProgressListenerTest#other")); + } +} diff --git a/itests/src/test/java/org/apache/unomi/itests/TestTimingCache.java b/itests/src/test/java/org/apache/unomi/itests/TestTimingCache.java index dbeb1698f..127951db2 100644 --- a/itests/src/test/java/org/apache/unomi/itests/TestTimingCache.java +++ b/itests/src/test/java/org/apache/unomi/itests/TestTimingCache.java @@ -71,13 +71,24 @@ final class TestTimingCache { /** * Ignore a pair in {@link #computeScale} when its cached entry is more than this many times - * bigger than what was actually observed (e.g. a historically-slow test that now looks like it - * skipped in milliseconds). This is intentionally one-directional: a pair where {@code observed} - * is much bigger than {@code cached} is a genuine regression signal and is not excluded, so it - * can still raise the ETA. + * bigger than what was actually observed. This only ever applies to pairs that already passed the + * {@link #SUBSTANTIVE_OBSERVED_MS} gate (i.e. {@code observed} is not itself assume/skip-like) but + * are still disproportionately faster than their own cached history — an outlier that would + * otherwise drag the scale toward {@link #MIN_SCALE}. This is intentionally one-directional: a pair + * where {@code observed} is much bigger than {@code cached} is a genuine regression signal and is + * not excluded, so it can still raise the ETA. */ static final double MAX_PAIR_SKEW = 20.0; + /** + * Upper bound for the true-cold-start placeholder average in {@link #fallbackAverageMs} (no + * completed test and no historical cache at all). Growing with elapsed time keeps the ETA display + * from looking frozen while nothing has finished yet, but must stay capped — otherwise a run that + * stalls (e.g. several early failures with nothing successful yet) would balloon the placeholder, + * and therefore the ETA for every remaining test, to an implausibly large number. + */ + static final long COLD_START_PLACEHOLDER_CAP_MS = 60_000L; + /** * An (observed, cached) duration sample for a single completed test that had a historical cache * entry, used by {@link #computeScale} to judge live pace vs history for individual tests. @@ -147,7 +158,8 @@ static Map load(String persistenceProvider) { try { timings.put(key, Long.parseLong(props.getProperty(key))); } catch (NumberFormatException e) { - // Ignore a malformed entry rather than failing the whole cache load + LOGGER.debug("Ignoring malformed test timing cache entry {}={} in {}: {}", + key, props.getProperty(key), cacheFile, e.getMessage()); } } return timings; @@ -193,14 +205,29 @@ static void save(String persistenceProvider, Map observedTimings) Path parent = cacheFile.toAbsolutePath().getParent(); Path tempFile = Files.createTempFile(parent, "test-timing-cache", ".tmp"); - try (Writer writer = Files.newBufferedWriter(tempFile, StandardCharsets.UTF_8)) { - props.store(writer, "Apache Unomi IT test timing cache per persistence provider " - + "(local dev aid, safe to delete)"); + try { + try (Writer writer = Files.newBufferedWriter(tempFile, StandardCharsets.UTF_8)) { + props.store(writer, "Apache Unomi IT test timing cache per persistence provider " + + "(local dev aid, safe to delete)"); + } + Files.move(tempFile, cacheFile, StandardCopyOption.REPLACE_EXISTING); + } finally { + // Best-effort cleanup only: after a successful move this is already gone, and any + // exception here must not mask a real failure from the write/move above. + try { + Files.deleteIfExists(tempFile); + } catch (IOException ignored) { + // Nothing more we can do; the temp file is harmless local dev-workspace clutter. + } } - Files.move(tempFile, cacheFile, StandardCopyOption.REPLACE_EXISTING); - } catch (IOException | RuntimeException e) { + } catch (IOException e) { LOGGER.debug("Unable to persist test timing cache at {} (ETAs will just use the in-run average next time): {}", cacheFile, e.getMessage()); + } catch (RuntimeException e) { + // Distinct from the expected-I/O-failure case above: an unexpected exception here means a + // real bug in the merge/blend logic, not just a read-only/ephemeral workspace. + LOGGER.warn("Unexpected error persisting test timing cache at {} (ETAs will just use the in-run average next time)", + cacheFile, e); } } @@ -210,29 +237,30 @@ static void save(String persistenceProvider, Map observedTimings) * Live pace is primary: the pace is the average duration of substantive * completed tests this run (real work, excluding near-instant assume/skip-like completions — see * {@link #SUBSTANTIVE_OBSERVED_MS}). Historical per-test durations are only hints that - * reweight remaining work when the leftover tests are historically heavier or lighter than the - * suite average (so a block of slow tests still ahead raises ETA above a flat per-test rate). + * reweight remaining work by how each remaining test's historical duration compares to the suite's + * average historical duration — a block of historically slow tests still ahead raises the ETA above + * a flat per-test rate, and a tail of historically light tests lowers it below that rate. *

    * Deriving pace from substantive durations only — rather than {@code elapsedTimeMs / completed} - * over every finished test — avoids two failure modes: (1) failed/aborted tests are never added to - * {@code completedDurations} (see the caller), so their wall time cannot inflate the pace the way a - * naive elapsed/count ratio would; (2) a run of fast assumes/skips before a block of heavy tests - * cannot drag the pace toward zero, since those near-instant completions are excluded from the - * average rather than counted as "typical" tests. + * over every finished test — avoids two failure modes: (1) the caller never adds a failed or + * assume-aborted test's duration to {@code completedDurations} (see {@link ProgressListener}), so + * its wall time cannot inflate the pace the way a naive elapsed/count ratio would; (2) a run of fast + * assumes/skips before a block of heavy tests cannot drag the pace toward zero, since those + * near-instant completions are excluded from the average rather than counted as "typical" tests. *

    * A global “this run is 4× faster than cache” scale is not applied to shrink remaining * historical time — that is what made ETAs chronically too low after early assumes/skips. * If the run is slower than cache on substantive tests, remaining historical time is still * raised accordingly via {@link #computeScale}. *

    - * Cold start (nothing substantive completed yet) falls back to the historical average pace, so - * remaining tests are estimated at their full cached weight until real live data says otherwise. + * Cold start (no completed test yet, substantive or not) falls back to the historical average pace, + * so remaining tests are estimated at their full cached weight until real live data says otherwise. * * @param remainingKeys keys still expected to run * @param cachedTimings historical durations for this persistence provider * @param observedVsCachedCompleted samples of (observedMs, cachedMs) for completed tests that had history * @param completedDurations successful completed durations this run (for live pace and fallback average) - * @param elapsedTimeMs wall time since suite start (used only to gate the cold-start case) + * @param elapsedTimeMs wall time since suite start; only its sign is used, to detect the cold-start case * @return estimated remaining milliseconds (never negative) */ static long estimateRemainingMs(Collection remainingKeys, @@ -247,6 +275,7 @@ static long estimateRemainingMs(Collection remainingKeys, int completedCount = completedDurations == null ? 0 : completedDurations.size(); double fallbackAvg = fallbackAverageMs(completedDurations, cachedTimings, elapsedTimeMs); + // fallbackAvg is guaranteed > 0 (see fallbackAverageMs), so this is always positive too. double globalHintAvg = averagePositive(cachedTimings != null ? cachedTimings.values() : null); if (globalHintAvg <= 0.0) { globalHintAvg = fallbackAvg; @@ -271,23 +300,16 @@ static long estimateRemainingMs(Collection remainingKeys, // assume/skip successes nor (by construction — see caller) any failed/aborted test's wall // time can skew it; fall back to the historical average until we have such a data point. double substantiveAvgMs = averageAtLeast(completedDurations, SUBSTANTIVE_OBSERVED_MS); - double avgActualMs = substantiveAvgMs > 0.0 ? substantiveAvgMs - : (globalHintAvg > 0.0 ? globalHintAvg : fallbackAvg); - - // Flat live pace: every remaining test takes as long as the average so far. - long rateEtaMs = Math.round(remainingCount * avgActualMs); + double avgActualMs = substantiveAvgMs > 0.0 ? substantiveAvgMs : globalHintAvg; - // Hint-shaped live pace: same real average, but weight remaining tests by historical - // duration relative to the suite's average historical duration. + // Weight remaining work by how each remaining test's historical duration compares to the + // suite's average historical duration, then rescale that shape to today's live pace: // predict(r) = avgActual * (hint(r) / globalHintAvg) // sum = hintRemaining * avgActual / globalHintAvg - long hintShapedEtaMs = rateEtaMs; - if (globalHintAvg > 0.0) { - hintShapedEtaMs = Math.round(hintRemainingMs * (avgActualMs / globalHintAvg)); - } - - // Always re-evaluate from live pace; hints may raise ETA when heavier work remains. - long eta = Math.max(rateEtaMs, hintShapedEtaMs); + // This is genuinely bidirectional: it raises the ETA above a flat live-pace rate when the + // remaining tests are historically heavier than average, and lowers it below that rate when + // they're historically lighter — both driven by today's real pace, not a historical multiplier. + long eta = Math.round(hintRemainingMs * (avgActualMs / globalHintAvg)); // If substantive tests are slower than history, raise remaining toward scaled hints. double robustScale = computeScale(observedVsCachedCompleted); @@ -384,8 +406,9 @@ private static double fallbackAverageMs(Collection completedDurations, if (avg > 0.0) { return avg; } - // Cold start: tiny placeholder so ETA is non-zero until the first test finishes - return elapsedTimeMs > 0L ? elapsedTimeMs : 30_000L; + // True cold start (no completions, no cache at all): a placeholder so ETA is non-zero and + // visibly grows until the first test finishes, capped so a stalled start can't balloon it. + return elapsedTimeMs > 0L ? Math.min(elapsedTimeMs, COLD_START_PLACEHOLDER_CAP_MS) : 30_000L; } static Path cacheFile(String persistenceProvider) { diff --git a/itests/src/test/java/org/apache/unomi/itests/TestTimingCacheTest.java b/itests/src/test/java/org/apache/unomi/itests/TestTimingCacheTest.java index bb32c4969..11a4d48af 100644 --- a/itests/src/test/java/org/apache/unomi/itests/TestTimingCacheTest.java +++ b/itests/src/test/java/org/apache/unomi/itests/TestTimingCacheTest.java @@ -182,7 +182,36 @@ public void estimateRemainingUsesLivePaceWithHistoricalHints() { } @Test - public void estimateRemainingTracksWallClockPaceNotMinScaleCollapse() { + public void estimateRemainingLowersBelowFlatRateWhenRemainingIsHistoricallyLighter() { + // Suite average historical = (3000+500+500)/3 = 1333.33; remaining B and C are both historically + // lighter than that average, so hint-shaped reweighting must lower the ETA below the flat + // live-pace rate (remainingCount * avgActual = 2 * 1000 = 2000), not just floor it there. + Map cached = new HashMap<>(); + cached.put("A#a", 3_000L); + cached.put("B#b", 500L); + cached.put("C#c", 500L); + + Set remaining = new HashSet<>(Arrays.asList("B#b", "C#c")); + List observedVsCached = + Collections.singletonList(new TestTimingCache.TimingSample(1_000L, 3_000L)); + List completed = Collections.singletonList(1_000L); + long elapsed = 1_000L; + + long eta = TestTimingCache.estimateRemainingMs(remaining, cached, observedVsCached, completed, elapsed); + + // hintRemaining = 500+500 = 1000; eta = 1000 * (1000/1333.33) = 750, well below the flat-rate 2000. + Assert.assertEquals(750L, eta); + long flatRateEta = Math.round(remaining.size() * 1_000.0); + Assert.assertTrue("hint-shaped ETA must be able to go below the flat live-pace rate", + eta < flatRateEta); + } + + @Test + public void estimateRemainingTracksActualDurationAverageNotElapsedOverCount() { + // Elapsed wall time (300s) deliberately does NOT match completedCount * avg duration (50*4s=200s) + // — e.g. time lost to setup/teardown between tests. A naive elapsedTimeMs/completedCount pace + // (300_000/50 = 6_000ms/test) would overestimate the remaining 250 tests at 1_500_000ms; live + // pace must instead come from the actual completed-test durations (avg 4_000ms/test). Map cached = new HashMap<>(); for (int i = 0; i < 50; i++) { cached.put("DoneIT#t" + i, 5_000L); @@ -198,20 +227,20 @@ public void estimateRemainingTracksWallClockPaceNotMinScaleCollapse() { List observedVsCached = new java.util.ArrayList<>(); List completed = new java.util.ArrayList<>(); - // 50 tests in 200s wall (~4s each) while cache said 5s — realistic mild speedup for (int i = 0; i < 50; i++) { observedVsCached.add(new TestTimingCache.TimingSample(4_000L, 5_000L)); completed.add(4_000L); } - long elapsed = 200_000L; + long elapsed = 300_000L; long eta = TestTimingCache.estimateRemainingMs(remaining, cached, observedVsCached, completed, elapsed); - // rate / hint-shaped ≈ 250 * 4000 = 1_000_000ms (~16.7m) + // avgActual = 4_000 (from completedDurations, not elapsed/count); globalHintAvg = 5_000; + // hintRemaining = 250*5_000 = 1_250_000; eta = 1_250_000 * (4_000/5_000) = 1_000_000ms (~16.7m) Assert.assertEquals(1_000_000L, eta); - // Old bug: MIN_SCALE * 250 * 5000 = 312_500 (~5.2m) — chronically too low - long oldBuggyEta = Math.round(250 * 5_000L * TestTimingCache.MIN_SCALE); - Assert.assertTrue(eta > oldBuggyEta); + // The naive elapsed/completedCount pace (6_000ms/test) would have produced 1_500_000ms instead. + long naiveElapsedOverCountEta = Math.round(250 * (elapsed / (double) completed.size())); + Assert.assertNotEquals(naiveElapsedOverCountEta, eta); } @Test @@ -289,6 +318,48 @@ public void estimateRemainingAppliesSlowdownBoostWhenSubstantiveScaleExceedsOne( Assert.assertEquals(1_188L, eta); } + @Test + public void estimateRemainingSlowdownBoostRampApproachesRobustScaleAtLargeCompletedCount() { + // At a small completedCount the shrink ramp (completedCount/(completedCount+15)) heavily damps + // the slowdown boost; at a large completedCount it should approach the raw (interior, unclamped) + // robustScale instead of staying suppressed — exercising the ramp away from the completedCount=1 + // case covered by estimateRemainingAppliesSlowdownBoostWhenSubstantiveScaleExceedsOne, and away + // from computeScale's own MIN_SCALE/MAX_SCALE clamp boundaries. + Map cached = new HashMap<>(); + cached.put("A#a", 100L); + cached.put("R#r", 1_000L); + + Set remaining = new HashSet<>(Collections.singletonList("R#r")); + List observedVsCached = new java.util.ArrayList<>(); + List completed = new java.util.ArrayList<>(); + for (int i = 0; i < 100; i++) { + observedVsCached.add(new TestTimingCache.TimingSample(200L, 100L)); + completed.add(200L); + } + long elapsed = 20_000L; + + long eta = TestTimingCache.estimateRemainingMs(remaining, cached, observedVsCached, completed, elapsed); + + // robustScale = 200/100 = 2.0 (interior, not clamped); shrink = 100/115 ≈ 0.8696; + // softenedScale = 1 + 0.8696*(2.0-1.0) ≈ 1.8696; boosted = 1000*1.8696 ≈ 1870, which wins over + // the un-boosted hint-shaped estimate (1000 * 200/550 ≈ 364). + Assert.assertEquals(1_870L, eta); + } + + @Test + public void estimateRemainingCapsColdStartPlaceholderForStalledStart() { + // No completions yet and no historical cache at all (e.g. the very first-ever run stalls before + // its first success) — the per-remaining-test placeholder must not grow unbounded with elapsed + // time; it should cap at COLD_START_PLACEHOLDER_CAP_MS rather than ballooning towards hours. + Set remaining = new HashSet<>(Arrays.asList("X#x", "Y#y", "Z#z")); + long stalledElapsed = 500_000L; // 8+ minutes with nothing completed and no cache + + long eta = TestTimingCache.estimateRemainingMs( + remaining, Collections.emptyMap(), Collections.emptyList(), Collections.emptyList(), stalledElapsed); + + Assert.assertEquals(3 * TestTimingCache.COLD_START_PLACEHOLDER_CAP_MS, eta); + } + @Test public void estimateRemainingUsesHistoricalAverageWhenNothingCompleted() { Map cached = new HashMap<>();