Uploaded image for project: 'Ignite'
  1. Ignite
  2. IGNITE-20919

"TransactionException: Replication is timed out" after inserting 9M entries

    XMLWordPrintableJSON

Details

    Description

      AI3, rev. e1c9b1c4cf589c71aecc4815a3c8a14ae8fbf2f3 (Nov 21 2023)

       

      Benchmark: https://github.com/gridgain/YCSB/blob/ycsb-2023.8/ignite3/src/main/java/site/ycsb/db/ignite3/IgniteClient.java 

      The benchmark uses key-value API to put/get entries. 

      Setup

      1 server node

      aipersist, 25 partitions, raft.fsync=false

      Steps

      Run a single instance of the benchmark in preload mode with 1 thread. Number of unique entries – 25 million.

      Command line: -db site.ycsb.db.ignite3.IgniteClient -load -P /opt/pubagent/poc/config/ycsb/workloads/workloadc -threads 1 -p recordcount=250000 -p warmupops=50000 -p dataintegrity=true -p measurementtype=timeseries -p status.interval=1 -p hosts=192.168.1.107 -p recordcount=25000000 -p operationcount=25000000 -s

      Expected result

      All 25 million entries were loaded without errors. 

      Actual result

      TransactionException: Replication is timed out after inserting 9.1 million entries:

      Starting test.
2023-11-21 18:11:29:396 [WARM-UP] 0 sec: 0 operations; est completion in 0 second 
...
2023-11-21 19:06:21:394 [PAYLOAD] 3292 sec: 9151900 operations; 1880 current ops/sec; est completion in 1 hour 35 minutes [INSERT AverageLatency(us)=522.76] 
2023-11-21 19:06:21:394 [PAYLOAD] 3292 sec: 9151900 operations; 1880 current ops/sec; est completion in 1 hour 35 minutes [INSERT AverageLatency(us)=522.76] 
2023-11-21 19:06:22:394 [PAYLOAD] 3293 sec: 9153100 operations; 1200 current ops/sec; est completion in 1 hour 35 minutes [INSERT AverageLatency(us)=531.8] 
2023-11-21 19:06:22:394 [PAYLOAD] 3293 sec: 9153100 operations; 1200 current ops/sec; est completion in 1 hour 35 minutes [INSERT AverageLatency(us)=531.8] 
2023-11-21 19:06:23:394 [PAYLOAD] 3294 sec: 9153100 operations; 0 current ops/sec; est completion in 1 hour 35 minutes  
2023-11-21 19:06:23:394 [PAYLOAD] 3294 sec: 9153100 operations; 0 current ops/sec; est completion in 1 hour 35 minutes  
2023-11-21 19:06:24:394 [PAYLOAD] 3295 sec: 9153100 operations; 0 current ops/sec; est completion in 1 hour 35 minutes  
2023-11-21 19:06:24:394 [PAYLOAD] 3295 sec: 9153100 operations; 0 current ops/sec; est completion in 1 hour 35 minutes  
[19:06:25][ERROR][Thread-2] Error inserting key: user3519618738173805240
org.apache.ignite.tx.TransactionException: Replication is timed out [replicaGrpId=5_part_19]
	at java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:710) ~[?:?]
	at org.apache.ignite.internal.util.ExceptionUtils$1.copy(ExceptionUtils.java:754) ~[ignite-core-3.0.0-SNAPSHOT.jar:?]
	at org.apache.ignite.internal.util.ExceptionUtils$ExceptionFactory.createCopy(ExceptionUtils.java:688) ~[ignite-core-3.0.0-SNAPSHOT.jar:?]
	at org.apache.ignite.internal.util.ExceptionUtils.copyExceptionWithCause(ExceptionUtils.java:525) ~[ignite-core-3.0.0-SNAPSHOT.jar:?]
	at org.apache.ignite.internal.client.ClientUtils.copyExceptionWithCauseIfPossible(ClientUtils.java:73) ~[ignite-client-3.0.0-SNAPSHOT.jar:?]
	at org.apache.ignite.internal.client.ClientUtils.ensurePublicException(ClientUtils.java:54) ~[ignite-client-3.0.0-SNAPSHOT.jar:?]
	at org.apache.ignite.internal.client.ClientUtils.sync(ClientUtils.java:97) ~[ignite-client-3.0.0-SNAPSHOT.jar:?]
	at org.apache.ignite.internal.client.table.ClientKeyValueBinaryView.put(ClientKeyValueBinaryView.java:168) ~[ignite-client-3.0.0-SNAPSHOT.jar:?]
	at org.apache.ignite.internal.client.table.ClientKeyValueBinaryView.put(ClientKeyValueBinaryView.java:47) ~[ignite-client-3.0.0-SNAPSHOT.jar:?]
	at site.ycsb.db.ignite3.IgniteClient.insert(IgniteClient.java:127) [ignite3-binding-2023.8.jar:?]
	at site.ycsb.DBWrapper.insert(DBWrapper.java:237) [core-2023.8.jar:?]
	at site.ycsb.workloads.CoreWorkload.doInsert(CoreWorkload.java:623) [core-2023.8.jar:?]
	at site.ycsb.ClientThread.run(ClientThread.java:167) [core-2023.8.jar:?]
	at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: org.apache.ignite.tx.TransactionException: Replication is timed out [replicaGrpId=5_part_19]
	at java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:710) ~[?:?]
	at org.apache.ignite.internal.util.ExceptionUtils$1.copy(ExceptionUtils.java:754) ~[ignite-core-3.0.0-SNAPSHOT.jar:?]
	at org.apache.ignite.internal.util.ExceptionUtils$ExceptionFactory.createCopy(ExceptionUtils.java:688) ~[ignite-core-3.0.0-SNAPSHOT.jar:?]
	at org.apache.ignite.internal.util.ExceptionUtils.copyExceptionWithCause(ExceptionUtils.java:525) ~[ignite-core-3.0.0-SNAPSHOT.jar:?]
	at org.apache.ignite.internal.client.TcpClientChannel.readError(TcpClientChannel.java:469) ~[ignite-client-3.0.0-SNAPSHOT.jar:?]
	at org.apache.ignite.internal.client.TcpClientChannel.processNextMessage(TcpClientChannel.java:420) ~[ignite-client-3.0.0-SNAPSHOT.jar:?]
	at org.apache.ignite.internal.client.TcpClientChannel.onMessage(TcpClientChannel.java:229) ~[ignite-client-3.0.0-SNAPSHOT.jar:?]
	at org.apache.ignite.internal.client.io.netty.NettyClientConnection.onMessage(NettyClientConnection.java:111) ~[ignite-client-3.0.0-SNAPSHOT.jar:?]
	at org.apache.ignite.internal.client.io.netty.NettyClientMessageHandler.channelRead(NettyClientMessageHandler.java:33) ~[ignite-client-3.0.0-SNAPSHOT.jar:?]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) ~[netty-transport-4.1.87.Final.jar:4.1.87.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[netty-transport-4.1.87.Final.jar:4.1.87.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) ~[netty-transport-4.1.87.Final.jar:4.1.87.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346) ~[netty-codec-4.1.87.Final.jar:4.1.87.Final]
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318) ~[netty-codec-4.1.87.Final.jar:4.1.87.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444) ~[netty-transport-4.1.87.Final.jar:4.1.87.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[netty-transport-4.1.87.Final.jar:4.1.87.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) ~[netty-transport-4.1.87.Final.jar:4.1.87.Final]
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) ~[netty-transport-4.1.87.Final.jar:4.1.87.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440) ~[netty-transport-4.1.87.Final.jar:4.1.87.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[netty-transport-4.1.87.Final.jar:4.1.87.Final]
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) ~[netty-transport-4.1.87.Final.jar:4.1.87.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) ~[netty-transport-4.1.87.Final.jar:4.1.87.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788) ~[netty-transport-4.1.87.Final.jar:4.1.87.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724) ~[netty-transport-4.1.87.Final.jar:4.1.87.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650) ~[netty-transport-4.1.87.Final.jar:4.1.87.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562) ~[netty-transport-4.1.87.Final.jar:4.1.87.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[netty-common-4.1.87.Final.jar:4.1.87.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.87.Final.jar:4.1.87.Final]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.87.Final.jar:4.1.87.Final]
	... 1 more

      Full logs: logs.zip

      Attachments

        1. logs.zip
          1.55 MB
          Ivan Artiukhov

        Issue Links

          relates to

          Bug - A problem which impairs or prevents the functions of the product. IGNITE-20723 Tests fail on TC because a primary replica is not assigned or does not respond

          • Major - Major loss of function.
          • Open

          Activity

            People

              Unassigned Unassigned
              Artukhov Ivan Artiukhov
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

                Created:
                Updated: