Skip to content

Commit d78b149

Browse files
authored
fix: keep late observations out of subsequent collection buffers (#2471)
## Problem and proof A late appender can increment its stripe during collection A, then read `activeGeneration` only after A has completed and collection B has started. B already includes that observation in `expectedCount`. If the appender puts it into B's buffer, B waits for an observation that will only be replayed after B's wait ends. This deterministically causes the five-second collection timeout. The old late-appender test paused after reading the generation, missing this window. Moving the existing injected pause hook before that read, without the fix, reproduced: ```text BufferTest.lateAppenderCountedByNextGenerationMustNotBeBufferedAgain Time elapsed: 5.037 s ExecutionException: IllegalStateException: Timed out while waiting for in-flight observations. ``` The production hook remains a no-op; the test forces a scheduling window that real threads can hit. This has the same failure signature as the histogram failures observed in [#2468](#2468) and [#2441](#2441). The reproduction proves this race exists, not which interleaving occurred in any particular CI run. ## Fix - Record each stripe's absolute observation count at generation activation, under `appendLock`. - Under that same lock, reject buffering an observation whose ticket is already included in the current generation's starting count. It completes through the existing direct observation path. - Reuse a single cutoff array per Buffer: one additional long per stripe, plus array overhead, with no new per-collection allocation or additional fast-path lock. - Keep cutoffs independent of the reset-adjusted aggregate observation count. - Do not change the five-second timeout, buffer capacity, or public API. ## Regression coverage Strengthen the late-appender test to force the previously untested window and capture worker exceptions through futures, with bounded waits and executor cleanup. Cover both normal collection and a preceding reset. Each case also verifies that a genuinely new observation buffers normally, stays out of the current snapshot, replays exactly once, and appears in the following collection. ## Validation - Before fix: deterministic timeout reproduced as above. - After fix: `BufferTest`, `HistogramTest`, and `SummaryTest` — 50 tests passed. - Temporary local JUnit launcher: both regression cases and the original `HistogramTest.testObserveMultithreaded`, repeated 50 times with each of `-XX:ActiveProcessorCount=1`, `2`, and `4` — **450 successful test executions** on JDK 25. - `mise run lint:fix` — passed; formatter changes retained. - `mise run build -- -DskipITs=true` — passed. Docker-backed integration tests skipped because Docker is unavailable locally. - `mise run test` — full unit-test suite passed. - `./mvnw verify -pl prometheus-metrics-core -am` — passed, including coverage checks. - `git diff --check` — passed. Kept separate from the benchmark-only PR. ## Current scope after update onto main The original production fix is already present on `main` through [#2441](#2441) and [#2468](#2468). This PR now contains the remaining merge-update and review hardening: explicit coverage for both generation handoff windows, fail-closed absolute cutoffs, clearer test seams, and non-masking executor cleanup assertions. The historical race reproduction and validation context above are retained. --------- Signed-off-by: Gregor Zeitlinger <gregor.zeitlinger@grafana.com>
1 parent 085263b commit d78b149

2 files changed

Lines changed: 43 additions & 17 deletions

File tree

  • prometheus-metrics-core/src

‎prometheus-metrics-core/src/main/java/io/prometheus/metrics/core/metrics/Buffer.java‎

Lines changed: 24 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -62,23 +62,34 @@ private static final class Generation {
6262
private final Condition bufferSpaceAvailable = appendLock.newCondition();
6363
private final long maxSpinWaitNanos;
6464
private final int maxBufferSize;
65-
private final Runnable beforeAppendLock;
65+
// These hooks are test seams only; production buffers use no-op callbacks.
66+
private final Runnable beforeGenerationRead;
67+
private final Runnable afterGenerationRead;
6668

6769
Buffer() {
68-
this(DEFAULT_MAX_SPIN_WAIT_NANOS, DEFAULT_MAX_BUFFER_SIZE, () -> {});
70+
this(DEFAULT_MAX_SPIN_WAIT_NANOS, DEFAULT_MAX_BUFFER_SIZE, () -> {}, () -> {});
6971
}
7072

7173
Buffer(long maxSpinWaitNanos) {
72-
this(maxSpinWaitNanos, DEFAULT_MAX_BUFFER_SIZE, () -> {});
74+
this(maxSpinWaitNanos, DEFAULT_MAX_BUFFER_SIZE, () -> {}, () -> {});
7375
}
7476

75-
Buffer(long maxSpinWaitNanos, int maxBufferSize, Runnable beforeAppendLock) {
77+
Buffer(long maxSpinWaitNanos, int maxBufferSize, Runnable beforeGenerationRead) {
78+
this(maxSpinWaitNanos, maxBufferSize, beforeGenerationRead, () -> {});
79+
}
80+
81+
Buffer(
82+
long maxSpinWaitNanos,
83+
int maxBufferSize,
84+
Runnable beforeGenerationRead,
85+
Runnable afterGenerationRead) {
7686
if (maxBufferSize <= 0) {
7787
throw new IllegalArgumentException("maxBufferSize must be positive");
7888
}
7989
this.maxSpinWaitNanos = maxSpinWaitNanos;
8090
this.maxBufferSize = maxBufferSize;
81-
this.beforeAppendLock = beforeAppendLock;
91+
this.beforeGenerationRead = beforeGenerationRead;
92+
this.afterGenerationRead = afterGenerationRead;
8293
stripedObservationCounts = new AtomicLong[Runtime.getRuntime().availableProcessors()];
8394
generationStartCounts = new long[stripedObservationCounts.length];
8495
for (int i = 0; i < stripedObservationCounts.length; i++) {
@@ -87,6 +98,7 @@ private static final class Generation {
8798
}
8899

89100
boolean append(double value) {
101+
// Keep the uncontended hot path small enough for the JIT to inline into observations.
90102
int stripe = stripeIndex(Thread.currentThread().getId(), stripedObservationCounts.length);
91103
AtomicLong counter = stripedObservationCounts[stripe];
92104
long count = counter.incrementAndGet();
@@ -97,9 +109,14 @@ boolean append(double value) {
97109
if ((count & BUFFER_ACTIVE_BIT) == 0) {
98110
return false;
99111
}
112+
return appendToActiveGeneration(value, stripe, count);
113+
}
114+
115+
private boolean appendToActiveGeneration(double value, int stripe, long count) {
100116
// Allow tests to pause between allocating an observation ticket and reading the generation.
101-
beforeAppendLock.run();
117+
beforeGenerationRead.run();
102118
Generation generation = activeGeneration;
119+
afterGenerationRead.run();
103120
if (generation == null) {
104121
return false;
105122
}
@@ -193,7 +210,7 @@ <T extends DataPointSnapshot> T run(
193210
long total = 0;
194211
for (int i = 0; i < stripedObservationCounts.length; i++) {
195212
long count = stripedObservationCounts[i].getAndAdd(BUFFER_ACTIVE_BIT);
196-
generationStartCounts[i] = count;
213+
generationStartCounts[i] = count & ~BUFFER_ACTIVE_BIT;
197214
total += count;
198215
}
199216
expectedCount = total - observationCountOffset;

‎prometheus-metrics-core/src/test/java/io/prometheus/metrics/core/metrics/BufferTest.java‎

Lines changed: 19 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -223,15 +223,21 @@ void interruptedAppenderLeavesBoundedBufferWait() throws InterruptedException {
223223

224224
@Test
225225
void lateAppenderCountedByNextGenerationMustNotBeBufferedAgain() throws Exception {
226-
assertLateAppenderHandoff(false);
226+
assertLateAppenderHandoff(false, true);
227227
}
228228

229229
@Test
230230
void lateAppenderHandoffUsesAbsoluteStripeCountsAfterReset() throws Exception {
231-
assertLateAppenderHandoff(true);
231+
assertLateAppenderHandoff(true, true);
232232
}
233233

234-
private static void assertLateAppenderHandoff(boolean reset) throws Exception {
234+
@Test
235+
void lateAppenderAfterGenerationReadMustNotBeBufferedAgain() throws Exception {
236+
assertLateAppenderHandoff(false, false);
237+
}
238+
239+
private static void assertLateAppenderHandoff(boolean reset, boolean pauseBeforeGenerationRead)
240+
throws Exception {
235241
CountDownLatch firstSnapshotStarted = new CountDownLatch(1);
236242
CountDownLatch finishFirstSnapshot = new CountDownLatch(1);
237243
CountDownLatch observationCounted = new CountDownLatch(1);
@@ -240,16 +246,19 @@ private static void assertLateAppenderHandoff(boolean reset) throws Exception {
240246
AtomicLong completedObservations = new AtomicLong();
241247
AtomicLong secondExpectedCount = new AtomicLong();
242248
AtomicBoolean pauseFirstAppender = new AtomicBoolean(true);
249+
Runnable pauseHook =
250+
() -> {
251+
if (pauseFirstAppender.compareAndSet(true, false)) {
252+
observationCounted.countDown();
253+
awaitLatch(readGeneration);
254+
}
255+
};
243256
Buffer buffer =
244257
new Buffer(
245258
TimeUnit.SECONDS.toNanos(5),
246259
16,
247-
() -> {
248-
if (pauseFirstAppender.compareAndSet(true, false)) {
249-
observationCounted.countDown();
250-
awaitLatch(readGeneration);
251-
}
252-
});
260+
pauseBeforeGenerationRead ? pauseHook : () -> {},
261+
pauseBeforeGenerationRead ? () -> {} : pauseHook);
253262
if (reset) {
254263
assertThat(buffer.append(1.0)).isFalse();
255264
buffer.observeDirect(completedObservations::incrementAndGet);
@@ -329,8 +338,8 @@ private static void assertLateAppenderHandoff(boolean reset) throws Exception {
329338
finishFirstSnapshot.countDown();
330339
readGeneration.countDown();
331340
executor.shutdownNow();
332-
assertThat(executor.awaitTermination(10, TimeUnit.SECONDS)).isTrue();
333341
}
342+
assertThat(executor.awaitTermination(10, TimeUnit.SECONDS)).as("executor terminated").isTrue();
334343
}
335344

336345
private static void awaitLatch(CountDownLatch latch) {

0 commit comments

Comments
 (0)