Skip to content

fix: keep late observations out of subsequent collection buffers - #2471

Open
zeitlinger wants to merge 4 commits into
mainfrom
fix/buffer-generation-handoff
Open

zeitlinger wants to merge 4 commits into
mainfrom
fix/buffer-generation-handoff

Conversation

@zeitlinger

@zeitlinger zeitlinger commented Sep 15, 2026

Copy link
Copy Markdown
Member

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:

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 and
#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 4450 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 and #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>
@github-actions

github-actions Bot commented Sep 15, 2026

Copy link
Copy Markdown
Contributor

Benchmark results

Benchmark run succeeded for 08760dd48fc75d0b60d265bfbd4113ec65b4e776.

Prometheus Java Client Benchmarks

Run Information

  • Date: 2026-09-15T17:58:12Z
  • Commit: 08760dd
  • JDK: 25.0.3 (OpenJDK 64-Bit Server VM)
  • Benchmark config: 3 fork(s), 3 warmup, 5 measurement, 1/4 threads
  • Hardware: AMD EPYC 9V45 96-Core Processor, 4 cores, 16 GB RAM
  • OS: Linux 6.17.0-1022-azure

Comparison with base

  • Head: 08760dd
  • Base: 59ca1f0
  • Metric direction: Throughput scores are higher-is-better; positive Head vs base deltas indicate faster performance.
  • Uncertainty: values include JMH 99.9% confidence intervals; verdicts use interval overlap and a practical-change threshold as a conservative heuristic, not as a statistical significance test.
  • Note: Base and head are compared on the same runner within each topic.
Benchmark PR (99.9% CI) Base (99.9% CI) Head vs base Regression verdict
CounterBenchmark.prometheusAdd 60.73K [58.08K, 63.39K] 57.06K [55.94K, 58.18K] +6.4% inconclusive (overlapping intervals)
CounterBenchmark.prometheusCachedLabelValuesInc 650.12M [612.38M, 687.86M] 685.89M [624.13M, 747.64M] -5.2% inconclusive (overlapping intervals)
CounterBenchmark.prometheusCachedLabelValuesIncSingleThread 211.42M [206.21M, 216.63M] 212.20M [205.63M, 218.76M] -0.4% inconclusive (overlapping intervals)
CounterBenchmark.prometheusInc 67.48K [66.10K, 68.87K] 67.07K [65.16K, 68.97K] +0.6% inconclusive (overlapping intervals)
CounterBenchmark.prometheusLabelValuesInc 144.99M [142.60M, 147.39M] 145.45M [140.75M, 150.14M] -0.3% inconclusive (overlapping intervals)
CounterBenchmark.prometheusLabelValuesIncSingleThread 74.50M [73.08M, 75.92M] 75.07M [73.78M, 76.35M] -0.8% inconclusive (overlapping intervals)
CounterBenchmark.prometheusNoLabelsInc 64.87K [63.95K, 65.79K] 65.81K [63.00K, 68.61K] -1.4% inconclusive (overlapping intervals)
HistogramBenchmark.prometheusClassic 7.19K [6.06K, 8.31K] 7.74K [5.95K, 9.53K] -7.2% inconclusive (overlapping intervals)
HistogramBenchmark.prometheusClassicPerThread 12.07K [12.03K, 12.11K] 11.88K [11.86K, 11.90K] +1.6% below 5% threshold
HistogramBenchmark.prometheusClassicSingleThread 4.54K [4.54K, 4.55K] 4.37K [4.34K, 4.39K] +4.1% below 5% threshold
HistogramBenchmark.prometheusNative 2.61K [2.19K, 3.03K] 2.72K [2.39K, 3.05K] -4.0% inconclusive (overlapping intervals)
HistogramTextFormatBenchmark.openMetricsWriteToNull 24.30K [23.91K, 24.70K] 24.45K [24.04K, 24.86K] -0.6% inconclusive (overlapping intervals)
HistogramTextFormatBenchmark.prometheusWriteToNull 24.49K [24.18K, 24.80K] 24.85K [24.47K, 25.22K] -1.4% inconclusive (overlapping intervals)
TextFormatUtilBenchmark.openMetricsWriteToByteArray 321.36K [317.10K, 325.63K] 324.16K [319.72K, 328.59K] -0.9% inconclusive (overlapping intervals)
TextFormatUtilBenchmark.openMetricsWriteToNull 324.06K [320.69K, 327.44K] 326.37K [322.55K, 330.19K] -0.7% inconclusive (overlapping intervals)
TextFormatUtilBenchmark.prometheusWriteToByteArray 343.65K [337.59K, 349.71K] 343.83K [341.65K, 346.02K] -0.1% inconclusive (overlapping intervals)
TextFormatUtilBenchmark.prometheusWriteToNull 344.55K [341.42K, 347.67K] 345.61K [344.11K, 347.12K] -0.3% inconclusive (overlapping intervals)

Results for PR head

CounterBenchmark

Benchmark Score Error Units
prometheusCachedLabelValuesInc 650.12M ± 37739.81K ops/s
prometheusCachedLabelValuesIncSingleThread 211.42M ± 5210.63K ops/s
prometheusLabelValuesInc 144.99M ± 2395.45K ops/s
prometheusLabelValuesIncSingleThread 74.50M ± 1415.66K ops/s
prometheusInc 67.48K ± 1.38K ops/s
prometheusNoLabelsInc 64.87K ± 920.05 ops/s
prometheusAdd 60.73K ± 2.65K ops/s

HistogramBenchmark

Benchmark Score Error Units
prometheusClassicPerThread 12.07K ± 39.64 ops/s
prometheusClassic 7.19K ± 1.13K ops/s
prometheusClassicSingleThread 4.54K ± 8.49 ops/s
prometheusNative 2.61K ± 419.45 ops/s

HistogramTextFormatBenchmark

Benchmark Score Error Units
prometheusWriteToNull 24.49K ± 312.17 ops/s
openMetricsWriteToNull 24.30K ± 396.48 ops/s

TextFormatUtilBenchmark

Benchmark Score Error Units
prometheusWriteToNull 344.55K ± 3.12K ops/s
prometheusWriteToByteArray 343.65K ± 6.06K ops/s
openMetricsWriteToNull 324.06K ± 3.38K ops/s
openMetricsWriteToByteArray 321.36K ± 4.27K ops/s

Allocation per operation

JMH GC profiler gc.alloc.rate.norm, in bytes per benchmark operation (lower is better).
Delta is PR minus base, shown only for matching benchmark configurations. Values are descriptive, not statistical regression verdicts; — means unavailable or not comparable. Each benchmark defines its own operation.

Benchmark PR B/op Base B/op Delta B/op
CounterBenchmark.prometheusAdd 0.061 0.065 -0.004
CounterBenchmark.prometheusCachedLabelValuesInc 0.000 0.000 +0.000
CounterBenchmark.prometheusCachedLabelValuesIncSingleThread 0.000 0.000 -0.000
CounterBenchmark.prometheusInc 0.055 0.055 -0.000
CounterBenchmark.prometheusLabelValuesInc 64.000 64.000 +0.000
CounterBenchmark.prometheusLabelValuesIncSingleThread 64.000 64.000 +0.000
CounterBenchmark.prometheusNoLabelsInc 0.057 0.056 +0.001
HistogramBenchmark.prometheusClassic 0.523 0.498 +0.025
HistogramBenchmark.prometheusClassicPerThread 0.666 0.673 -0.008
HistogramBenchmark.prometheusClassicSingleThread 0.641 0.667 -0.026
HistogramBenchmark.prometheusNative 417707.616 335793.376 +81914.240
HistogramTextFormatBenchmark.openMetricsWriteToNull 43648.144 43648.143 +0.001
HistogramTextFormatBenchmark.prometheusWriteToNull 43648.143 43648.141 +0.002
TextFormatUtilBenchmark.openMetricsWriteToByteArray 18424.002 18424.002 +0.000
TextFormatUtilBenchmark.openMetricsWriteToNull 18424.002 18424.002 +0.000
TextFormatUtilBenchmark.prometheusWriteToByteArray 18485.335 18448.002 +37.333
TextFormatUtilBenchmark.prometheusWriteToNull 18429.335 18448.002 -18.667

Raw Results

Benchmark                                            Mode  Cnt          Score        Error  Units
CounterBenchmark.prometheusAdd                      thrpt   15      60733.174   ± 2651.969  ops/s
CounterBenchmark.prometheusCachedLabelValuesInc     thrpt   15  650123302.562 ± 37739806.962  ops/s
CounterBenchmark.prometheusCachedLabelValuesIncSingleThread  thrpt   15  211419181.201 ± 5210634.973  ops/s
CounterBenchmark.prometheusInc                      thrpt   15      67484.026   ± 1382.771  ops/s
CounterBenchmark.prometheusLabelValuesInc           thrpt   15  144994196.718 ± 2395454.161  ops/s
CounterBenchmark.prometheusLabelValuesIncSingleThread  thrpt   15   74500590.343 ± 1415661.503  ops/s
CounterBenchmark.prometheusNoLabelsInc              thrpt   15      64872.904    ± 920.046  ops/s
HistogramBenchmark.prometheusClassic                thrpt   15       7186.720   ± 1125.201  ops/s
HistogramBenchmark.prometheusClassicPerThread       thrpt   15      12066.530     ± 39.645  ops/s
HistogramBenchmark.prometheusClassicSingleThread    thrpt   15       4544.250      ± 8.495  ops/s
HistogramBenchmark.prometheusNative                 thrpt   15       2609.067    ± 419.450  ops/s
HistogramTextFormatBenchmark.openMetricsWriteToNull  thrpt   15      24301.836    ± 396.484  ops/s
HistogramTextFormatBenchmark.prometheusWriteToNull  thrpt   15      24492.453    ± 312.169  ops/s
TextFormatUtilBenchmark.openMetricsWriteToByteArray  thrpt   15     321364.271   ± 4266.985  ops/s
TextFormatUtilBenchmark.openMetricsWriteToNull      thrpt   15     324063.108   ± 3375.475  ops/s
TextFormatUtilBenchmark.prometheusWriteToByteArray  thrpt   15     343649.834   ± 6061.243  ops/s
TextFormatUtilBenchmark.prometheusWriteToNull       thrpt   15     344547.278   ± 3124.029  ops/s

Notes

  • Score = the JMH primary metric; throughput is higher-is-better and latency is lower-is-better.
  • Error = 99.9% confidence interval
  • Regression verdict requires comparable benchmark metadata, non-overlapping JMH confidence intervals, and a change of at least 5%; otherwise it is marked "below the practical threshold" or "inconclusive". This is a conservative heuristic, not a statistical significance test.
  • Scores for different benchmark methods are not ranked against one another; they may measure different workloads.

Benchmark Descriptions

Benchmark Description
CounterBenchmark Counter updates and label-value lookup (selected methods only)
HistogramBenchmark Histogram observation performance (classic vs native/exponential)
TextFormatUtilBenchmark Metric exposition format writing speed

@jaydeluca jaydeluca left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Comments are all non-blocking.

Signed-off-by: Gregor Zeitlinger <gregor.zeitlinger@grafana.com>
Signed-off-by: Gregor Zeitlinger <gregor.zeitlinger@grafana.com>
Signed-off-by: Gregor Zeitlinger <gregor.zeitlinger@grafana.com>
@zeitlinger

Copy link
Copy Markdown
Member Author

The reviewed hook plumbing caused a measurable JIT regression: Buffer.append grew from 321 bytes and inlined (hot) on the original fix to 330 bytes and failed to inline (hot) after the review changes.

I split the ticket/active-bit hot path from the generation/lock path. The resulting Buffer.append is 52 bytes and inlines hot; the cold helper is 287 bytes. All hooks and generation guards remain unchanged. This adds no locks or allocations.

A same-host paired JMH run (JDK 25.0.3, 3 forks, 3x3s warmup, 5x3s measurement, classic histogram methods) improved the reviewed head by +11.3% per-thread and +15.0% single-thread (34,074 vs 30,626 ops/s; 9,278 vs 8,063 ops/s). This is a smaller local sample than CI, so a fresh CI benchmark is still needed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants