Repository navigation
Exponential histogram throws ArrayIndexOutOfBoundsException #5740
Description
Describe the bug
We get this exception when using a Timer to emit exponential histograms. It seems like it's trying to put a value in bucket index 254614 while there are only 40 buckets (40 is what we set for max number of buckets)
We are currently still trying to log this error when it happens to understand what value produces this exception. We'll update here once we'll have more information.
This is the stack trace:
caused by ArrayIndexOutOfBoundsException: Index 254614 out of bounds for length 40
...
java.lang.invoke.VarHandle$1.apply(VarHandle.java:2187)
java.lang.invoke.VarHandle$1.apply(VarHandle.java:2184)
jdk.internal.util.Preconditions$1.apply(Preconditions.java:177)
jdk.internal.util.Preconditions$1.apply(Preconditions.java:174)
jdk.internal.util.Preconditions.outOfBounds(Preconditions.java:62)
jdk.internal.util.Preconditions.outOfBoundsCheckIndex(Preconditions.java:70)
jdk.internal.util.Preconditions.checkIndex(Preconditions.java:266)
java.lang.invoke.VarHandleLongs$Array.getAndAdd(VarHandleLongs.java:926)
java.util.concurrent.atomic.AtomicLongArray.addAndGet(AtomicLongArray.java:259)
io.micrometer.registry.otlp.internal.CircularCountHolder.increment(CircularCountHolder.java:84)
io.micrometer.registry.otlp.internal.Base2ExponentialHistogram.recordDouble(Base2ExponentialHistogram.java:172)
io.micrometer.registry.otlp.internal.Base2ExponentialHistogram.recordLong(Base2ExponentialHistogram.java:151)
io.micrometer.core.instrument.AbstractTimer.record(AbstractTimer.java:261)
io.micrometer.core.instrument.composite.CompositeTimer.record(CompositeTimer.java:54)
- Micrometer version: 1.14.0
- Micrometer registry: OTLP
- OS: linux
- Java version: 11
Activity
jonatan-ivanov commentedon Dec 11, 2024
Thank you for the issue!
I've edited your comment to improve the formatting. You might want to check out this Mastering Markdown guide for future reference.
For the record, this discussion started on Slack: https://micrometer-metrics.slack.com/archives/C662HUJC9/p1733775869763389
I understand that you are still working on a reproducer but could you please provide a bit more details?
Timercreated and used?sfc-gh-dguy commentedon Dec 12, 2024
sfc-gh-dguy commentedon Dec 12, 2024
Full stack trace:
jonatan-ivanov commentedon Dec 12, 2024
Thank you for the details.
I don't think any of this will resolve the issue but a few notes about the code above:
timerPoolis some sort of aMap. What you do here is also done by the registry (except the registry handles more use-cases like transformed meter names)..register(...)is actually agetOrCreateNew(...)with a cache backed by aMap, like what you do above. Also, you might want to look into theMeterProviderconcept. Please don't use a secondMapfor this and use theBuilderorMeterProviderdirectly.currentMillis, I assume you callSystem.currentTimeMillis(). It's a very common mistake, please don't use it to measure elapsed time, here's why. Instead you can useTimer.Sampleorrecord(Runnable/Callable).Metrics.globalRegistry). It's hard to test and it can cause other issues due to its static nature. Use a registry instance instead and inject in into your components.jonatan-ivanov commentedon Dec 12, 2024
Yesterday I tried reproduce this, basically had the same config as yours but I was not able to so a reproducer would be really appreciated.
Also, now that I posted my previous comment and said it probably does not solve the issue, could you please try out what happens if you solve the second point? Please read the article I linked and use
Timer.Sampleorrecord(Runnable/Callable) instead of trying to measure elapsed time on your own. It can happen that you get some weird results (i.e.: record negative numbers). I tried negative values as well yesterday when I tried to repro your issue but it was ok for me, though just for sure, could you please fix that issue and check if you still get an exception?Also, how frequent is this issue?
lenin-jaganathan commentedon Dec 16, 2024
I guess this might be related to concurrent around re-scaling. That is the only thing I could think of when the index returned seems to be very high. One thing I was initially tempted to do was full synchronization of the histogram but thought that could have negative performance issues. Let me see if I can reproduce this with some concurrency tests.
@sfc-gh-dguy Is this issue re-producible or is it very hard to re-produce (later would mean this might be related to concurrency but former might hint at something else)?
sfc-gh-tyuan commentedon Dec 17, 2024
@lenin-jaganathan @jonatan-ivanov We reverted the change since it was impacting our production environment. It definitely seems to be a concurrency issue, since it only created an incident in our workload tests and production environment. @sfc-gh-dguy and I are adding a try/catch around the record call to safely reproduce the issue. We will update you when we have more information.
sfc-gh-tyuan commentedon Dec 19, 2024
@jonatan-ivanov @lenin-jaganathan Here are some additional logs:
Stacktrace for both:
The difference is this stacktrace happens during downscaling while the previous does not.
lenin-jaganathan commentedon Dec 20, 2024
I have added this PR which would fix these concurrency issues. If you have a reproducer that would catch, please share it. Otherwise, I will try to work on concurrency tests sometime (possibly before next patch)
lenin-jaganathan commentedon Dec 23, 2024
I was able to reproduce this in the concurrency stress tests here. Updated the PR with results from before and after changes.
Fix concurrency issue with Exponential Histogram (#5749)
shakuzen commentedon Dec 25, 2024
Thanks to @lenin-jaganathan, a fix is in the latest snapshots 1.14.3-SNAPSHOT. Let us know if you're seeing any issues with that, and thank you @sfc-gh-dguy and @sfc-gh-tyuan for all the details in reporting this.