Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ArrayIndexOutOfBoundsException when using LongTaskTimer #3877

Open
rdehuyss opened this issue Jun 6, 2023 · 1 comment · May be fixed by #4511
Open

ArrayIndexOutOfBoundsException when using LongTaskTimer #3877

rdehuyss opened this issue Jun 6, 2023 · 1 comment · May be fixed by #4511
Labels
bug A general bug module: micrometer-core An issue that is related to our core module work-in-progress
Milestone
1.11.x

Comments

@rdehuyss
Copy link

rdehuyss commented Jun 6, 2023

Describe the bug / it may be a question
I'm seeing ArrayIndexOutOfBoundsException in my logs when using LongTaskTimer.

Environment

  • Micrometer version 1.11.0
  • Micrometer registry: SimpleMeterRegistry
  • OS: macOS
  • Java version: openjdk version "17.0.1" 2021-10-19

To Reproduce

    @Test
    void reproduceIssue() throws InterruptedException {
        SimpleMeterRegistry simpleMeterRegistry = new SimpleMeterRegistry();

        LongTaskTimer timer = LongTaskTimer.builder("jobrunr.jobs")
                .publishPercentiles(0.25, 0.5, 0.75, 0.8, 0.9, 0.95)
                .publishPercentileHistogram()
                .register(simpleMeterRegistry);
        LongTaskTimer.Sample start = timer.start();
        Thread.sleep(3640);
        System.out.println(simpleMeterRegistry.getMetersAsString());
        Thread.sleep(2640);
        System.out.println(start.stop());

        System.out.println(simpleMeterRegistry.getMetersAsString());
    }

This results in the following output:

08:46:23.327 [Test worker] WARN  i.m.c.i.internal.DefaultGauge - Failed to apply the value function for the gauge 'jobrunr.jobs.percentile'. Note that subsequent logs will be logged at debug level.
java.lang.ArrayIndexOutOfBoundsException: Index 5 out of bounds for length 5
	at io.micrometer.core.instrument.distribution.HistogramGauges.lambda$new$9(HistogramGauges.java:119)
	at io.micrometer.core.instrument.internal.DefaultGauge.value(DefaultGauge.java:53)
	at io.micrometer.core.instrument.Measurement.getValue(Measurement.java:54)
	at io.micrometer.core.instrument.simple.SimpleMeterRegistry.toString(SimpleMeterRegistry.java:206)
	at io.micrometer.core.instrument.simple.SimpleMeterRegistry.lambda$toString$1(SimpleMeterRegistry.java:195)
jobrunr.jobs(LONG_TASK_TIMER)[]; active_tasks=1.0, duration=3.651603291 seconds
jobrunr.jobs.percentile(GAUGE)[phi='0.25']; value=3.653785708 seconds
jobrunr.jobs.percentile(GAUGE)[phi='0.9']; value=3.653818208 seconds
jobrunr.jobs.percentile(GAUGE)[phi='0.8']; value=3.653818208 seconds
jobrunr.jobs.percentile(GAUGE)[phi='0.5']; value=3.653818208 seconds
jobrunr.jobs.percentile(GAUGE)[phi='0.95']; value=NaN seconds
jobrunr.jobs.percentile(GAUGE)[phi='0.75']; value=3.653818208 seconds
6322804041
jobrunr.jobs(LONG_TASK_TIMER)[]; active_tasks=0.0, duration=0.0 seconds
jobrunr.jobs.percentile(GAUGE)[phi='0.25']; value=0.0 seconds
jobrunr.jobs.percentile(GAUGE)[phi='0.9']; value=0.0 seconds
jobrunr.jobs.percentile(GAUGE)[phi='0.8']; value=0.0 seconds
jobrunr.jobs.percentile(GAUGE)[phi='0.5']; value=0.0 seconds
jobrunr.jobs.percentile(GAUGE)[phi='0.95']; value=0.0 seconds
jobrunr.jobs.percentile(GAUGE)[phi='0.75']; value=0.0 seconds

Expected behavior
No ArrayIndexOutOfBoundsException should happen.

Additional context
NA
@jvwilge
Copy link

jvwilge commented Sep 19, 2023 •
edited

We're having a problem that looks similar and might be related :

Failed to apply the value function for the gauge 'http.server.requests.active.percentile'. Note that subsequent logs will be logged at debug level.
java.lang.ArrayIndexOutOfBoundsException: Index 3 out of bounds for length 3
	at io.micrometer.core.instrument.distribution.HistogramGauges.lambda$new$9(HistogramGauges.java:119)
	at io.micrometer.core.instrument.internal.DefaultGauge.value(DefaultGauge.java:53)
	at io.micrometer.signalfx.SignalFxMeterRegistry.addGauge(SignalFxMeterRegistry.java:227)
	at io.micrometer.core.instrument.Meter.match(Meter.java:100)
	at io.micrometer.signalfx.SignalFxMeterRegistry.lambda$publish$1(SignalFxMeterRegistry.java:117)
	at java.base/java.util.stream.ReferencePipeline$3$1.accept(Unknown Source)
	at java.base/java.util.ArrayList$SubList$2.forEachRemaining(Unknown Source)
	at java.base/java.util.stream.AbstractPipeline.copyInto(Unknown Source)
	at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(Unknown Source)
	at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(Unknown Source)
	at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(Unknown Source)
	at java.base/java.util.stream.AbstractPipeline.evaluate(Unknown Source)
	at java.base/java.util.stream.ReferencePipeline.forEach(Unknown Source)
	at io.micrometer.signalfx.SignalFxMeterRegistry.publish(SignalFxMeterRegistry.java:128)
	at io.micrometer.core.instrument.push.PushMeterRegistry.publishSafely(PushMeterRegistry.java:67)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
	at java.base/java.util.concurrent.FutureTask.runAndReset(Unknown Source)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.base/java.lang.Thread.run(Unknown Source)

We're using SignalFxMeterRegistry and http.server.requests.active.percentile is something coming from the spring boot actuator.

When you change the example from @rdehuyss to .publishPercentiles(0.25, 0.51, 0.75, 0.8, 0.9, 0.95) it actually succeeds. So I suspect that

        List<Double> percentilesAboveInterpolatableLine = percentilesRequested.stream()
            .filter(p -> p * (activeTasks.size() + 1) > activeTasks.size())
            .collect(Collectors.toList());

in DefaultLongTaskTimer#takeSnapshot() might be the culprit (could it be > vs. >=?. It looks like one of the buckets is missing when creating the HistogramSnapshot in the return statement of the takeSnapshot() method.
The build of micrometer still succeeds after changing > into >=

There are also cases where multiple buckets are missing (0.11, 0.22, 0.33, 0.44) for example. When I add 3 samples it works again.

@marcingrzejszczak marcingrzejszczak added this to the 1.10.14 milestone Dec 27, 2023
marcingrzejszczak added a commit that referenced this issue Dec 27, 2023
@marcingrzejszczak
For long task timers fixes the percentiles above interpolatable line
4aec46f 
without this change for the provided test one of the histogram buckets gets removed and an ArrayIndexOutOfBoundsException is thrown
with this change the exception is not thrown anymore

fixes gh-3877
@marcingrzejszczak marcingrzejszczak linked a pull request Dec 27, 2023 that will close this issue
Open
marcingrzejszczak added a commit that referenced this issue Dec 27, 2023
@marcingrzejszczak
For long task timers fixes the percentiles above interpolatable line
421ff5b 
without this change for the provided test one of the histogram buckets gets removed and an ArrayIndexOutOfBoundsException is thrown
with this change the exception is not thrown anymore

fixes gh-3877
@shakuzen shakuzen added bug A general bug module: micrometer-core An issue that is related to our core module labels Jan 17, 2024
marcingrzejszczak added a commit that referenced this issue Jan 17, 2024
@marcingrzejszczak
For long task timers fixes the percentiles above interpolatable line
08a6383 
without this change for the provided test one of the histogram buckets gets removed and an ArrayIndexOutOfBoundsException is thrown
with this change the exception is not thrown anymore

fixes gh-3877
@jonatan-ivanov jonatan-ivanov modified the milestones: 1.10.14, 1.11.x Feb 12, 2024
@shakuzen shakuzen mentioned this issue Mar 5, 2024
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug A general bug module: micrometer-core An issue that is related to our core module work-in-progress
Projects
None yet
Milestone
1.11.x
Development

Successfully merging a pull request may close this issue.

For long task timers fixes the percentiles above interpolatable line micrometer-metrics/micrometer
5 participants
@jvwilge @rdehuyss @jonatan-ivanov @marcingrzejszczak @shakuzen