Exception - Could not collect latency metric for request

nkapre · August 10, 2016, 12:24am

Stack Trace: java.lang.ArrayIndexOutOfBoundsException: value outside of histogram covered range. Caused by: java.lang.IndexOutOfBoundsException: index 3951
	at com.couchbase.client.deps.org.HdrHistogram.AbstractHistogram.handleRecordException(AbstractHistogram.java:441)
	at com.couchbase.client.deps.org.HdrHistogram.AbstractHistogram.recordSingleValue(AbstractHistogram.java:433)
	at com.couchbase.client.deps.org.HdrHistogram.AbstractHistogram.recordValue(AbstractHistogram.java:346)
	at com.couchbase.client.deps.org.LatencyUtils.LatencyStats.recordLatency(LatencyStats.java:201)
	at com.couchbase.client.core.metrics.AbstractLatencyMetricsCollector.record(AbstractLatencyMetricsCollector.java:85)
	at com.couchbase.client.core.endpoint.AbstractGenericHandler.writeMetrics(AbstractGenericHandler.java:270)
	at com.couchbase.client.core.endpoint.AbstractGenericHandler.decode(AbstractGenericHandler.java:233)
	at com.couchbase.client.deps.io.netty.handler.codec.MessageToMessageCodec$2.decode(MessageToMessageCodec.java:81)
	at com.couchbase.client.deps.io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:89)
	at com.couchbase.client.deps.io.netty.handler.codec.MessageToMessageCodec.channelRead(MessageToMessageCodec.java:111)
	at com.couchbase.client.deps.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:292)
	at com.couchbase.client.deps.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:278)
	at com.couchbase.client.deps.io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:428)
	at com.couchbase.client.deps.io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:277)
	at com.couchbase.client.deps.io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:264)
	at com.couchbase.client.deps.io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:243)
	at com.couchbase.client.deps.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:292)
	at com.couchbase.client.deps.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:278)
	at com.couchbase.client.deps.io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:266)
	at com.couchbase.client.deps.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:292)
	at com.couchbase.client.deps.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:278)
	at com.couchbase.client.deps.io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:962)
	at com.couchbase.client.deps.io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131)
	at com.couchbase.client.deps.io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:528)
	at com.couchbase.client.deps.io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:485)
	at com.couchbase.client.deps.io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:399)
	at com.couchbase.client.deps.io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:371)
	at com.couchbase.client.deps.io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
	at com.couchbase.client.deps.io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)
	at java.lang.Thread.run(Thread.java:745)

Couchbase (4.5) has been running for several days with very minimal load. Started seeing this recently.

simonbasle · August 11, 2016, 9:34am

Hey @nkapre

Do you know if the application was executing a long-running operation? Which version of the SDK are you using?
Can you confirm the exception didn’t bubble up to your application code but was caught and logged? If that’s the case there should be an additional line of code “Could not collect latency metric” above it, can you copy that as well?

The data structure used to collect latency metrics, an HdrHistogram accessed through the utility library LatencyUtils, is sized to record timings between 1 microsecond and 1 hour, and if I understand correctly this can happen if the recorded timing goes beyond 1 hour…

nkapre · August 11, 2016, 4:32pm

Thanks @simonbasle for responding.

We are using Java Client 2.3.1 SDK.

Couchbase has been running for quite some time, but without any load. Only operation our application performing is getting Bucket Info every 30 seconds.

This exception is separate, its not thrown from our application code. But it was occurring continuoulsy with 30 second interval.

Here is the message for the exception:

Logger: com.couchbase.client.core.endpoint.AbstractGenericHandler

Log Level: WARN

Class Name: com.couchbase.client.core.logging.Slf4JLogger

Message: Could not collect latency metric for request + KeepAliveRequest{observable=rx.subjects.AsyncSubject@3a4d0843, bucket=‘null’}(65881591305357)

simonbasle · August 16, 2016, 3:00pm

wow that indicates that a keep alive request was responded to with a perceived latency of 18 hours…
do you know of any particular exception that occurred in that timeframe before the first occurrence of the exception?

nkapre · August 17, 2016, 1:36am

I checked the log again. I don’t see any exception from Couchbase before first occurrence of this.

hudsonmd · August 17, 2016, 2:15pm

Hello, I am also experiencing a very similar issue.

I am using
java client : com.couchbase.client:java-client:2.3.1
Couchbase : 4.1.1-5914 Enterprise Edition (build-5914)

The exception occurs inconsistently, but has been reproducible with queries that include the LIKE operator and run against a bucket with a very large number of documents.Once experienced, this error repeats until I restart the java server. When running the query, I recieve 2 histogram exceptions in short succession, shortly after which, I recieve a connectionTimeout in my applicaiton.

Couchbase’s stacktrace
> 2016-08-17 08:26:16.748 WARN 599 — [ cb-io-1-3] c.c.c.c.endpoint.AbstractGenericHandler : Could not collect latency metric for request + KeepAliveRequest{observable=rx.subjects.AsyncSubject@5c2e7ab, bucket=‘null’}(49508953305493)

java.lang.ArrayIndexOutOfBoundsException: value outside of histogram covered range. Caused by: java.lang.IndexOutOfBoundsException: index 3892
at com.couchbase.client.deps.org.HdrHistogram.AbstractHistogram.handleRecordException(AbstractHistogram.java:441) ~[core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.org.HdrHistogram.AbstractHistogram.recordSingleValue(AbstractHistogram.java:433) ~[core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.org.HdrHistogram.AbstractHistogram.recordValue(AbstractHistogram.java:346) ~[core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.org.LatencyUtils.LatencyStats.recordLatency(LatencyStats.java:201) ~[core-io-1.3.1.jar!/:na]
at com.couchbase.client.core.metrics.AbstractLatencyMetricsCollector.record(AbstractLatencyMetricsCollector.java:85) ~[core-io-1.3.1.jar!/:na]
at com.couchbase.client.core.endpoint.AbstractGenericHandler.writeMetrics(AbstractGenericHandler.java:270) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.core.endpoint.AbstractGenericHandler.decode(AbstractGenericHandler.java:233) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.handler.codec.MessageToMessageCodec$2.decode(MessageToMessageCodec.java:81) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:89) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.handler.codec.MessageToMessageCodec.channelRead(MessageToMessageCodec.java:111) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:292) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:278) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:428) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:277) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:264) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:243) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:292) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:278) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:266) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:292) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:278) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:962) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:131) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:528) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:485) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:399) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:371) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112) [core-io-1.3.1.jar!/:na]
at com.couchbase.client.deps.io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137) [core-io-1.3.1.jar!/:na]
at java.lang.Thread.run(Thread.java:745) [na:1.8.0_92]

which triggers a timeout in my applicaiton

java.lang.RuntimeException: java.util.concurrent.TimeoutException
at com.couchbase.client.java.util.Blocking.blockForSingle(Blocking.java:71)
at com.couchbase.client.java.CouchbaseBucket.query(CouchbaseBucket.java:652)
at com.couchbase.client.java.CouchbaseBucket.query(CouchbaseBucket.java:577)

These are the only two exceptions that I can detect in my applicaoitn