[
https://issues.apache.org/jira/browse/IGNITE-20919?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Ivan Artiukhov reassigned IGNITE-20919:
---------------------------------------
Assignee: Ivan Artiukhov
> "TransactionException: Replication is timed out" after inserting 9M entries
> ---------------------------------------------------------------------------
>
> Key: IGNITE-20919
> URL: https://issues.apache.org/jira/browse/IGNITE-20919
> Project: Ignite
> Issue Type: Bug
> Components: persistence
> Reporter: Ivan Artiukhov
> Assignee: Ivan Artiukhov
> Priority: Major
> Labels: ignite-3, ignite3_performance
> Attachments: logs.zip
>
>
> 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.
> h1. Setup
> 1 server node
> aipersist, 25 partitions, raft.fsync=false
> h1. Steps
> Run a single instance of the benchmark in preload mode with 1 thread. Number
> of unique entries – 25 million.
> {noformat}
> 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
> {noformat}
> h1. Expected result
> All 25 million entries were loaded without errors.
> h1. Actual result
> {{TransactionException: Replication is timed out after inserting 9.1 million
> entries:}}
> {noformat}
> 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
> {noformat}
> Full logs: [^logs.zip]
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
