Ivan Artiukhov created IGNITE-20919:
---------------------------------------
Summary: "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
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)
