[
https://issues.apache.org/jira/browse/IGNITE-20919?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17788672#comment-17788672
]
Ivan Artiukhov edited comment on IGNITE-20919 at 11/22/23 8:29 AM:
-------------------------------------------------------------------
The similar error on reads via key-value API. See the same [^logs.zip].
{noformat}
Command line: -db site.ycsb.db.ignite3.IgniteClient -t -P
/opt/pubagent/poc/config/ycsb/workloads/workloadc -threads 1 -p
operationcount=250000 -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
YCSB Client 2023.8Loading workload...
Data integrity is enabled.
Starting test.
2023-11-21 19:06:29:570 [WARM-UP] 0 sec: 0 operations; est completion in 0
second
2023-11-21 19:06:29:570 [WARM-UP] 0 sec: 0 operations; est completion in 0
second
[19:06:29][INFO ][Thread-2] Create table request: CREATE TABLE IF NOT EXISTS
usertable (yscb_key VARCHAR PRIMARY KEY, field0 VARCHAR, field1 VARCHAR, field2
VARCHAR, field3 VARCHAR, field4 VARCHAR, field5 VARCHAR, field6 VARCHAR, field7
VARCHAR, field8 VARCHAR, field9 VARCHAR)
DBWrapper: report latency for each error is false and specific error codes to
track for latency are: []
2023-11-21 19:06:30:568 [WARM-UP] 1 sec: 1447 operations; 1447 current ops/sec;
est completion in 4 hours 48 minutes
2023-11-21 19:06:30:568 [WARM-UP] 1 sec: 1447 operations; 1447 current ops/sec;
est completion in 4 hours 48 minutes
...
...
2023-11-21 19:50:37:567 [PAYLOAD] 2648 sec: 11867826 operations; 4573 current
ops/sec; est completion in 49 minutes [READ AverageLatency(us)=246.56] [VERIFY
AverageLatency(us)=2.87] [READ-FAILED AverageLatency(us)=191.82]
2023-11-21 19:50:37:567 [PAYLOAD] 2648 sec: 11867826 operations; 4573 current
ops/sec; est completion in 49 minutes [READ AverageLatency(us)=246.56] [VERIFY
AverageLatency(us)=2.87] [READ-FAILED AverageLatency(us)=191.82]
2023-11-21 19:50:38:567 [PAYLOAD] 2649 sec: 11868355 operations; 529 current
ops/sec; est completion in 49 minutes [READ AverageLatency(us)=518.38] [VERIFY
AverageLatency(us)=3.23] [READ-FAILED AverageLatency(us)=695.92]
2023-11-21 19:50:38:567 [PAYLOAD] 2649 sec: 11868355 operations; 529 current
ops/sec; est completion in 49 minutes [READ AverageLatency(us)=518.38] [VERIFY
AverageLatency(us)=3.23] [READ-FAILED AverageLatency(us)=695.92]
2023-11-21 19:50:39:567 [PAYLOAD] 2650 sec: 11868355 operations; 0 current
ops/sec; est completion in 49 minutes
2023-11-21 19:50:39:567 [PAYLOAD] 2650 sec: 11868355 operations; 0 current
ops/sec; est completion in 49 minutes
2023-11-21 19:50:40:567 [PAYLOAD] 2651 sec: 11868355 operations; 0 current
ops/sec; est completion in 49 minutes
2023-11-21 19:50:40:567 [PAYLOAD] 2651 sec: 11868355 operations; 0 current
ops/sec; est completion in 49 minutes
...
...
2023-11-21 19:51:37:567 [PAYLOAD] 2708 sec: 11868394 operations; 0 current
ops/sec; est completion in 50 minutes
2023-11-21 19:51:38:567 [PAYLOAD] 2709 sec: 11868394 operations; 0 current
ops/sec; est completion in 50 minutes
2023-11-21 19:51:38:567 [PAYLOAD] 2709 sec: 11868394 operations; 0 current
ops/sec; est completion in 50 minutes
2023-11-21 19:51:39:567 [PAYLOAD] 2710 sec: 11868394 operations; 0 current
ops/sec; est completion in 50 minutes
2023-11-21 19:51:39:567 [PAYLOAD] 2710 sec: 11868394 operations; 0 current
ops/sec; est completion in 50 minutes
[19:51:40][ERROR][Thread-2] Error reading key: user3512309439425897761
org.apache.ignite.lang.IgniteException: The primary replica await timed out
[replicationGroupId=5_part_19, referenceTimestamp=HybridTimestamp
[physical=2023-11-21 19:51:10:466 +0300, logical=7,
composite=111449569392459783], currentLease=Lease
[leaseholder=poc-tester-SERVER-192.168.1.107-id-0,
leaseholderId=0ea1764c-7664-4b61-83da-b7ed592082ae, accepted=false,
startTime=HybridTimestamp [physical=2023-11-21 19:51:09:453 +0300, logical=46,
composite=111449569326071854], expirationTime=HybridTimestamp
[physical=2023-11-21 19:53:09:453 +0300, logical=0,
composite=111449577190391808], prolongable=false, replicationGroupId=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.get(ClientKeyValueBinaryView.java:69)
~[ignite-client-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.internal.client.table.ClientKeyValueBinaryView.get(ClientKeyValueBinaryView.java:47)
~[ignite-client-3.0.0-SNAPSHOT.jar:?]
at site.ycsb.db.ignite3.IgniteClient.read(IgniteClient.java:56)
[ignite3-binding-2023.8.jar:?]
at site.ycsb.DBWrapper.read(DBWrapper.java:145) [core-2023.8.jar:?]
at
site.ycsb.workloads.CoreWorkload.doTransactionRead(CoreWorkload.java:746)
[core-2023.8.jar:?]
at site.ycsb.workloads.CoreWorkload.doTransaction(CoreWorkload.java:666)
[core-2023.8.jar:?]
at site.ycsb.ClientThread.run(ClientThread.java:145) [core-2023.8.jar:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: org.apache.ignite.lang.IgniteException: The primary replica await
timed out [replicationGroupId=5_part_19, referenceTimestamp=HybridTimestamp
[physical=2023-11-21 19:51:10:466 +0300, logical=7,
composite=111449569392459783], currentLease=Lease
[leaseholder=poc-tester-SERVER-192.168.1.107-id-0,
leaseholderId=0ea1764c-7664-4b61-83da-b7ed592082ae, accepted=false,
startTime=HybridTimestamp [physical=2023-11-21 19:51:09:453 +0300, logical=46,
composite=111449569326071854], expirationTime=HybridTimestamp
[physical=2023-11-21 19:53:09:453 +0300, logical=0,
composite=111449577190391808], prolongable=false, replicationGroupId=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}
was (Author: artukhov):
The similar error on reads via key-value API. See the same [^logs.zip].
{noformat}
Command line: -db site.ycsb.db.ignite3.IgniteClient -t -P
/opt/pubagent/poc/config/ycsb/workloads/workloadc -threads 1 -p
operationcount=250000 -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
YCSB Client 2023.8Loading workload...
Data integrity is enabled.
Starting test.
2023-11-21 19:06:29:570 [WARM-UP] 0 sec: 0 operations; est completion in 0
second
2023-11-21 19:06:29:570 [WARM-UP] 0 sec: 0 operations; est completion in 0
second
[19:06:29][INFO ][Thread-2] Create table request: CREATE TABLE IF NOT EXISTS
usertable (yscb_key VARCHAR PRIMARY KEY, field0 VARCHAR, field1 VARCHAR, field2
VARCHAR, field3 VARCHAR, field4 VARCHAR, field5 VARCHAR, field6 VARCHAR, field7
VARCHAR, field8 VARCHAR, field9 VARCHAR)
DBWrapper: report latency for each error is false and specific error codes to
track for latency are: []
2023-11-21 19:06:30:568 [WARM-UP] 1 sec: 1447 operations; 1447 current ops/sec;
est completion in 4 hours 48 minutes
2023-11-21 19:06:30:568 [WARM-UP] 1 sec: 1447 operations; 1447 current ops/sec;
est completion in 4 hours 48 minutes
...
...
2023-11-21 19:50:37:567 [PAYLOAD] 2648 sec: 11867826 operations; 4573 current
ops/sec; est completion in 49 minutes [READ AverageLatency(us)=246.56] [VERIFY
AverageLatency(us)=2.87] [READ-FAILED AverageLatency(us)=191.82]
2023-11-21 19:50:37:567 [PAYLOAD] 2648 sec: 11867826 operations; 4573 current
ops/sec; est completion in 49 minutes [READ AverageLatency(us)=246.56] [VERIFY
AverageLatency(us)=2.87] [READ-FAILED AverageLatency(us)=191.82]
2023-11-21 19:50:38:567 [PAYLOAD] 2649 sec: 11868355 operations; 529 current
ops/sec; est completion in 49 minutes [READ AverageLatency(us)=518.38] [VERIFY
AverageLatency(us)=3.23] [READ-FAILED AverageLatency(us)=695.92]
2023-11-21 19:50:38:567 [PAYLOAD] 2649 sec: 11868355 operations; 529 current
ops/sec; est completion in 49 minutes [READ AverageLatency(us)=518.38] [VERIFY
AverageLatency(us)=3.23] [READ-FAILED AverageLatency(us)=695.92]
2023-11-21 19:50:39:567 [PAYLOAD] 2650 sec: 11868355 operations; 0 current
ops/sec; est completion in 49 minutes
2023-11-21 19:50:39:567 [PAYLOAD] 2650 sec: 11868355 operations; 0 current
ops/sec; est completion in 49 minutes
2023-11-21 19:50:40:567 [PAYLOAD] 2651 sec: 11868355 operations; 0 current
ops/sec; est completion in 49 minutes
2023-11-21 19:50:40:567 [PAYLOAD] 2651 sec: 11868355 operations; 0 current
ops/sec; est completion in 49 minutes
...
...
2023-11-21 19:51:37:567 [PAYLOAD] 2708 sec: 11868394 operations; 0 current
ops/sec; est completion in 50 minutes
2023-11-21 19:51:38:567 [PAYLOAD] 2709 sec: 11868394 operations; 0 current
ops/sec; est completion in 50 minutes
2023-11-21 19:51:38:567 [PAYLOAD] 2709 sec: 11868394 operations; 0 current
ops/sec; est completion in 50 minutes
2023-11-21 19:51:39:567 [PAYLOAD] 2710 sec: 11868394 operations; 0 current
ops/sec; est completion in 50 minutes
2023-11-21 19:51:39:567 [PAYLOAD] 2710 sec: 11868394 operations; 0 current
ops/sec; est completion in 50 minutes
[19:51:40][ERROR][Thread-2] Error reading key: user3512309439425897761
org.apache.ignite.lang.IgniteException: The primary replica await timed out
[replicationGroupId=5_part_19, referenceTimestamp=HybridTimestamp
[physical=2023-11-21 19:51:10:466 +0300, logical=7,
composite=111449569392459783], currentLease=Lease
[leaseholder=poc-tester-SERVER-192.168.1.107-id-0,
leaseholderId=0ea1764c-7664-4b61-83da-b7ed592082ae, accepted=false,
startTime=HybridTimestamp [physical=2023-11-21 19:51:09:453 +0300, logical=46,
composite=111449569326071854], expirationTime=HybridTimestamp
[physical=2023-11-21 19:53:09:453 +0300, logical=0,
composite=111449577190391808], prolongable=false, replicationGroupId=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.get(ClientKeyValueBinaryView.java:69)
~[ignite-client-3.0.0-SNAPSHOT.jar:?]
at
org.apache.ignite.internal.client.table.ClientKeyValueBinaryView.get(ClientKeyValueBinaryView.java:47)
~[ignite-client-3.0.0-SNAPSHOT.jar:?]
at site.ycsb.db.ignite3.IgniteClient.read(IgniteClient.java:56)
[ignite3-binding-2023.8.jar:?]
at site.ycsb.DBWrapper.read(DBWrapper.java:145) [core-2023.8.jar:?]
at
site.ycsb.workloads.CoreWorkload.doTransactionRead(CoreWorkload.java:746)
[core-2023.8.jar:?]
at site.ycsb.workloads.CoreWorkload.doTransaction(CoreWorkload.java:666)
[core-2023.8.jar:?]
at site.ycsb.ClientThread.run(ClientThread.java:145) [core-2023.8.jar:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: org.apache.ignite.lang.IgniteException: The primary replica await
timed out [replicationGroupId=5_part_19, referenceTimestamp=HybridTimestamp
[physical=2023-11-21 19:51:10:466 +0300, logical=7,
composite=111449569392459783], currentLease=Lease
[leaseholder=poc-tester-SERVER-192.168.1.107-id-0,
leaseholderId=0ea1764c-7664-4b61-83da-b7ed592082ae, accepted=false,
startTime=HybridTimestamp [physical=2023-11-21 19:51:09:453 +0300, logical=46,
composite=111449569326071854], expirationTime=HybridTimestamp
[physical=2023-11-21 19:53:09:453 +0300, logical=0,
composite=111449577190391808], prolongable=false, replicationGroupId=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}
> "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
> Priority: Major
> Labels: 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)
