search

OpenTSDB / opentsdb

A scalable, distributed Time Series Database.
http://opentsdb.net
GNU Lesser General Public License v2.1
5.01k stars 1.25k forks source link

net.opentsdb.uid.UniqueId.getOrCreateId "RuntimeException: Should never be here" when under high query load #1323

Open twegener-embertec opened 6 years ago

twegener-embertec commented 6 years ago

Hit the following "Should never be here" runtime exception, during a time when the server was under high query load (i.e. many concurrent range queries that each took quite a while to run, along with many last value queries):

2018-08-25 14:40:28,944 [OpenTSDB Old I/O server worker (parentId: -235470477, [id: 0xf1f70173, /0.0.0.0:4242])] WARN  [HttpQuery.logWarn] - [id: 0x3a0da750, /redacted:36181 => /redacted:4242] Bad Request on /api/query/last?back_scan=96&timeseries=redacted{redacted}: Call queue is full on redacted,16020,1532606892138, too many items queued ?
Caused by RPC: GetRequest(table="tsdb", key=[0, 0, 1, 91, 126, 7, 16, 0, 0, 1, 0, 6, -12, 0, 0, 2, 0, 0, 11, 0, 0, 3, 0, 0, -89, 0, 0, 6, 0, 6, -11, 0, 0, 7, 0, 0, -92], family="t", qualifiers=null, attempt=1, region=RegionInfo(table="tsdb", region_name="tsdb,\x00\x00\x01Z\x06\x91\xE0\x00\x00\x01\x00\x02\xDD\x00\x00\x02\x00\x00\x0B\x00\x00\x03\x00\x00\xA7\x00\x00\x04\x00\x02\x9D\x00\x00\x06\x00\x02\xDE\x00\x00\x07\x00\x00H,1530793207434.e3b7f3a13eff43ad4a37f68ef9b6c83a.",
 stop_key=[0, 0, 2, 87, -77, 112, -64, 0, 0, 1, 0, 1, 43, 0, 0, 2, 0, 0, 11, 0, 0, 3, 0, 0, 13]))
2018-08-25 14:40:28,945 [OpenTSDB Old I/O server worker (parentId: -235470477, [id: 0xf1f70173, /0.0.0.0:4242])] INFO  [ConnectionManager.handleUpstream] - [id: 0x8ae6d784, /redacted:38388 :> /redacted:4242] DISCONNECTED
2018-08-25 14:40:28,946 [OpenTSDB Old I/O server worker (parentId: -235470477, [id: 0xf1f70173, /0.0.0.0:4242])] INFO  [ConnectionManager.handleUpstream] - [id: 0x8ae6d784, /redacted:38388 :> /redacted:4242] UNBOUND
2018-08-25 14:40:28,946 [OpenTSDB Old I/O server worker (parentId: -235470477, [id: 0xf1f70173, /0.0.0.0:4242])] INFO  [ConnectionManager.handleUpstream] - [id: 0x8ae6d784, /redacted:38388 :> /redacted:4242] CLOSED
2018-08-25 14:40:28,954 [OpenTSDB Old I/O server worker (parentId: -235470477, [id: 0xf1f70173, /0.0.0.0:4242])] WARN  [HttpQuery.logWarn] - [id: 0x7026c79a, /redacted:35669 => /redacted:4242] Bad Request on /api/query/last?back_scan=96&timeseries=redacted{redacted}: Call queue is full on redacted,16020,1532606892138, too many items queued ?
Caused by RPC: GetRequest(table="tsdb", key=[0, 0, 32, 91, 125, -36, -32, 0, 0, 1, 0, 3, 11, 0, 0, 3, 0, 2, -58, 0, 0, 6, 0, 4, 114, 0, 0, 7, 0, 0, 72], family="t", qualifiers=null, attempt=1, region=RegionInfo(table="tsdb", region_name="tsdb,\x00\x00\nYg`\xC0\x00\x00\x01\x00\x00M,1530793092866.f3799a9bbdd2959f48ca11898f83a650.", stop_key=[0, 0, 40, 89, -120, -16, -16, 0, 0, 1, 0, 2, -67, 0, 0, 2, 0, 1, 57, 0, 0, 3, 0, 0, -89, 0, 0, 4, 0, 2, -99, 0, 0, 6, 0, 2, -23, 0, 0,
 7, 0, 0, 73]))
2018-08-25 14:40:28,961 [OpenTSDB Old I/O server worker (parentId: -235470477, [id: 0xf1f70173, /0.0.0.0:4242])] ERROR [RpcHandler.logError] - [id: 0x918072f4, /redacted:35512 => /redacted:4242] Unexpected exception caught while serving [null, onoff, 1535207792, 1, redacted]
java.lang.RuntimeException: Should never be here
        at net.opentsdb.uid.UniqueId.getOrCreateId(UniqueId.java:737) ~[tsdb-2.3.0.jar:bfd5628]
        at net.opentsdb.core.Tags.resolveAllInternal(Tags.java:618) ~[tsdb-2.3.0.jar:bfd5628]
        at net.opentsdb.core.Tags.resolveOrCreateAll(Tags.java:604) ~[tsdb-2.3.0.jar:bfd5628]
        at net.opentsdb.core.IncomingDataPoints.rowKeyTemplate(IncomingDataPoints.java:145) ~[tsdb-2.3.0.jar:bfd5628]
        at net.opentsdb.core.TSDB.addPointInternal(TSDB.java:963) ~[tsdb-2.3.0.jar:bfd5628]
        at net.opentsdb.core.TSDB.addPoint(TSDB.java:873) ~[tsdb-2.3.0.jar:bfd5628]
        at net.opentsdb.tsd.PutDataPointRpc.importDataPoint(PutDataPointRpc.java:460) ~[tsdb-2.3.0.jar:bfd5628]
        at net.opentsdb.tsd.PutDataPointRpc.execute(PutDataPointRpc.java:78) ~[tsdb-2.3.0.jar:bfd5628]
        at net.opentsdb.tsd.RpcHandler.handleTelnetRpc(RpcHandler.java:162) ~[tsdb-2.3.0.jar:bfd5628]
        at net.opentsdb.tsd.RpcHandler.messageReceived(RpcHandler.java:132) ~[tsdb-2.3.0.jar:bfd5628]
        at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.handler.timeout.IdleStateAwareChannelUpstreamHandler.handleUpstream(IdleStateAwareChannelUpstreamHandler.java:36) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.handler.timeout.IdleStateHandler.messageReceived(IdleStateHandler.java:294) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.handler.codec.oneone.OneToOneDecoder.handleUpstream(OneToOneDecoder.java:70) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:296) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.handler.codec.frame.FrameDecoder.unfoldAndFireMessageReceived(FrameDecoder.java:462) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.handler.codec.frame.FrameDecoder.callDecode(FrameDecoder.java:443) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.handler.codec.frame.FrameDecoder.messageReceived(FrameDecoder.java:310) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.SimpleChannelHandler.messageReceived(SimpleChannelHandler.java:142) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.SimpleChannelHandler.handleUpstream(SimpleChannelHandler.java:88) [netty-3.9.4.Final.jar:na]
        at net.opentsdb.tsd.ConnectionManager.handleUpstream(ConnectionManager.java:128) [tsdb-2.3.0.jar:bfd5628]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.socket.oio.OioWorker.process(OioWorker.java:71) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.socket.oio.AbstractOioWorker.run(AbstractOioWorker.java:73) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.socket.oio.OioWorker.run(OioWorker.java:51) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42) [netty-3.9.4.Final.jar:na]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_144]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_144]
        at java.lang.Thread.run(Thread.java:748) [na:1.8.0_144]
Caused by: org.hbase.async.CallQueueTooBigException: Call queue is full on redacted,16020,1532606892138, too many items queued ?
Caused by RPC: GetRequest(table="tsdb-uid", key="877a9ba7a98f75b90a9d49f53f15a858", family="id", qualifiers=["tagv"], attempt=1, region=RegionInfo(table="tsdb-uid", region_name="tsdb-uid,,1448601361316.f4b729d245ffae6465c640e79f85b83a.", 
stop_key=""))
        at org.hbase.async.CallQueueTooBigException.make(CallQueueTooBigException.java:62) ~[asynchbase-1.8.0.jar:na]
        at org.hbase.async.CallQueueTooBigException.make(CallQueueTooBigException.java:34) ~[asynchbase-1.8.0.jar:na]
        at org.hbase.async.RegionClient.makeException(RegionClient.java:1756) ~[asynchbase-1.8.0.jar:na]
        at org.hbase.async.RegionClient.decodeException(RegionClient.java:1776) ~[asynchbase-1.8.0.jar:na]
        at org.hbase.async.RegionClient.decode(RegionClient.java:1488) ~[asynchbase-1.8.0.jar:na]
        at org.hbase.async.RegionClient.decode(RegionClient.java:88) ~[asynchbase-1.8.0.jar:na]
        at org.jboss.netty.handler.codec.replay.ReplayingDecoder.callDecode(ReplayingDecoder.java:500) ~[netty-3.9.4.Final.jar:na]
        at org.jboss.netty.handler.codec.replay.ReplayingDecoder.messageReceived(ReplayingDecoder.java:435) ~[netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) [netty-3.9.4.Final.jar:na]
        at org.hbase.async.RegionClient.handleUpstream(RegionClient.java:1226) ~[asynchbase-1.8.0.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.SimpleChannelHandler.messageReceived(SimpleChannelHandler.java:142) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.SimpleChannelHandler.handleUpstream(SimpleChannelHandler.java:88) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.handler.timeout.IdleStateAwareChannelHandler.handleUpstream(IdleStateAwareChannelHandler.java:36) ~[netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:791) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.handler.timeout.IdleStateHandler.messageReceived(IdleStateHandler.java:294) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:70) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559) [netty-3.9.4.Final.jar:na]
        at org.hbase.async.HBaseClient$RegionClientPipeline.sendUpstream(HBaseClient.java:3678) ~[asynchbase-1.8.0.jar:na]
        at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:268) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.Channels.fireMessageReceived(Channels.java:255) [netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:88) ~[netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.socket.nio.AbstractNioWorker.process(AbstractNioWorker.java:108) ~[netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:318) ~[netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:89) ~[netty-3.9.4.Final.jar:na]
        at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178) ~[netty-3.9.4.Final.jar:na]
        ... 5 common frames omitted

OpenTSDB 2.3.0 HBase 1.2.3

It looks like the code is neglecting to handle the following exception: "org.hbase.async.CallQueueTooBigException: Call queue is full on redacted,16020,1532606892138, too many items queued ?"

twegener-embertec commented 6 years ago

Possibly related to #1286?

manolama commented 5 years ago

Yes it is related to that. Try out the AsyncHBase 1.9.0-SNAPSHOT driver and it should help. Still some patches I need to make to it.