cartridge-java icon indicating copy to clipboard operation
cartridge-java copied to clipboard

In case of lengthy exception stacktrace, the delay between retries may be very long

Open akudiyar opened this issue 3 years ago • 0 comments

Description:

The retry attempts are configured to 20ms delay. The exact delay between attempts is close to 500ms in case of ~30 stack frames.

Example stacktrace:

2021-03-08 12:27:41.001 WARN 1222 --- [Pool-1-worker-3] r.v.c.c.s.c.c.t.TarantoolConfiguration : retry attempt after error
java.util.concurrent.CompletionException: TarantoolFunctionCallException: {"type":"ClientError","code":77,"message":"Connection reset by peer","trace":[{"file":"builtin/box/net_box.lua","line":263}]}
at java.base/java.util.concurrent.CompletableFuture.encodeRelay(CompletableFuture.java:367) ~[na:na]
at java.base/java.util.concurrent.CompletableFuture.completeRelay(CompletableFuture.java:376) ~[na:na]
at java.base/java.util.concurrent.CompletableFuture$UniRelay.tryFire(CompletableFuture.java:1019) ~[na:na]
at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[na:na]
at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088) ~[na:na]
at io.tarantool.driver.handlers.TarantoolResponseHandler.channelRead0(TarantoolResponseHandler.java:53) ~[cartridge-driver-0.4.1.jar:na]
at io.tarantool.driver.handlers.TarantoolResponseHandler.channelRead0(TarantoolResponseHandler.java:23) ~[cartridge-driver-0.4.1.jar:na]
at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-all-4.1.54.Final.jar:4.1.54.Final]
at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]
Caused by: io.tarantool.driver.exceptions.TarantoolFunctionCallException: null
at io.tarantool.driver.api.SingleValueCallResultImpl.<init>(SingleValueCallResultImpl.java:28) ~[cartridge-driver-0.4.1.jar:na]
at io.tarantool.driver.mappers.SingleValueCallResultConverter.fromValue(SingleValueCallResultConverter.java:23) ~[cartridge-driver-0.4.1.jar:na]
at io.tarantool.driver.mappers.SingleValueCallResultConverter.fromValue(SingleValueCallResultConverter.java:13) ~[cartridge-driver-0.4.1.jar:na]
at io.tarantool.driver.mappers.DefaultMessagePackMapper.fromValue(DefaultMessagePackMapper.java:107) ~[cartridge-driver-0.4.1.jar:na]
at io.tarantool.driver.mappers.DefaultMessagePackMapper.fromValue(DefaultMessagePackMapper.java:87) ~[cartridge-driver-0.4.1.jar:na]
at io.tarantool.driver.mappers.AbstractResultMapper.fromValue(AbstractResultMapper.java:27) ~[cartridge-driver-0.4.1.jar:na]
at io.tarantool.driver.handlers.TarantoolResponseHandler.channelRead0(TarantoolResponseHandler.java:51) ~[cartridge-driver-0.4.1.jar:na]
... 23 common frames omitted
2021-03-08 12:27:41.498 WARN 1222 --- [Pool-1-worker-3] r.v.c.c.s.c.c.t.TarantoolConfiguration : retry attempt after error
io.tarantool.driver.exceptions.TarantoolFunctionCallException: null
at io.tarantool.driver.api.SingleValueCallResultImpl.<init>(SingleValueCallResultImpl.java:28) ~[cartridge-driver-0.4.1.jar:na]
at io.tarantool.driver.mappers.SingleValueCallResultConverter.fromValue(SingleValueCallResultConverter.java:23) ~[cartridge-driver-0.4.1.jar:na]
at io.tarantool.driver.mappers.SingleValueCallResultConverter.fromValue(SingleValueCallResultConverter.java:13) ~[cartridge-driver-0.4.1.jar:na]
at io.tarantool.driver.mappers.DefaultMessagePackMapper.fromValue(DefaultMessagePackMapper.java:107) ~[cartridge-driver-0.4.1.jar:na]
at io.tarantool.driver.mappers.DefaultMessagePackMapper.fromValue(DefaultMessagePackMapper.java:87) ~[cartridge-driver-0.4.1.jar:na]

Possible root cause:

The exception generation in Java is slow

Possible solution:

Introduce exception caching

akudiyar avatar Mar 08 '21 11:03 akudiyar