Igor created IGNITE-22324:
-----------------------------
Summary: The exception "The primary replica has changed" on
creation of 1000 tables
Key: IGNITE-22324
URL: https://issues.apache.org/jira/browse/IGNITE-22324
Project: Ignite
Issue Type: Bug
Components: general, persistence
Affects Versions: 3.0.0-beta1
Reporter: Igor
*Steps to reproduce:*
1. Start cluster with 1 node with JVM options: "-Xms4096m -Xmx4096m"
2. Create 1000 tables with 200 varchar columns each and insert 1 row into
each. One by one.
*Expected result:*
Tables are created.
*Actual result:*
On table 949 the exception is thrown:
{code:java}
java.sql.SQLException: Primary replica has expired, transaction will be rolled
back: [groupId = 1850_part_21, expected enlistment consistency token =
112069202113202526, commit timestamp = HybridTimestamp [physical=2024-03-10
03:13:16:057 +0000, logical=396, composite=112069207395991948], current primary
replica = null]
at
org.apache.ignite.internal.jdbc.proto.IgniteQueryErrorCode.createJdbcSqlException(IgniteQueryErrorCode.java:57)
at
org.apache.ignite.internal.jdbc.JdbcStatement.execute0(JdbcStatement.java:154)
at
org.apache.ignite.internal.jdbc.JdbcPreparedStatement.executeWithArguments(JdbcPreparedStatement.java:765)
at
org.apache.ignite.internal.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:173)
at
org.gridgain.ai3tests.tests.TablesAmountCapacityTest.lambda$insertRowAndAssertTimeout$1(TablesAmountCapacityTest.java:166)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:834) {code}
In server logs there is an exception:
{code:java}
2024-03-10 03:13:24:222 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-8][TxManagerImpl]
Failed to finish Tx. The operation will be retried
[txId=018e2659-b09f-009c-23c0-6ab500000001].
java.util.concurrent.CompletionException:
org.apache.ignite.internal.replicator.exception.ReplicationTimeoutException:
IGN-REP-3 TraceId:7ff7e851-9f18-4212-b317-a70a0a92fdfe Replication is timed out
[replicaGrpId=1850_part_21]
at
java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331)
at
java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346)
at
java.base/java.util.concurrent.CompletableFuture$UniAccept.tryFire(CompletableFuture.java:704)
at
java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
at
java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088)
at
org.apache.ignite.internal.replicator.ReplicaService.lambda$sendToReplica$0(ReplicaService.java:110)
at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:834)
Caused by:
org.apache.ignite.internal.replicator.exception.ReplicationTimeoutException:
IGN-REP-3 TraceId:7ff7e851-9f18-4212-b317-a70a0a92fdfe Replication is timed out
[replicaGrpId=1850_part_21]
... 4 more
2024-03-10 03:13:24:290 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-22][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:290 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-11][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:290 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-19][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:290 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-17][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:290 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-23][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:290 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-6][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:290 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-9][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:290 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-20][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:290 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-10][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:291 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-12][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:291 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-2][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:290 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-7][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:290 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-18][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:290 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-15][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:290 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-13][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:291 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-4][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:291 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-3][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:290 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-1][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:291 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%scheduled-idle-safe-time-sync-thread-0][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:291 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-21][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:291 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-24][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:291 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-14][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:291 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-5][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:290 +0000
[WARNING][%TablesAmountCapacityTest_cluster_0%partition-operations-16][TrackableNetworkMessageHandler]
Message handling has been too long [duration=67ms, message=[class
org.apache.ignite.raft.jraft.rpc.WriteActionRequestImpl]]
2024-03-10 03:13:24:397 +0000
[INFO][%TablesAmountCapacityTest_cluster_0%partition-operations-4][JdbcQueryEventHandlerImpl]
Exception while executing query [query=insert into test_table_922(id,
column_1, column_2, column_3, column_4, column_5, column_6, column_7, column_8,
column_9, column_10, column_11, column_12, column_13, column_14, column_15,
column_16, column_17, column_18, column_19, column_20, column_21, column_22,
column_23, column_24, column_25, column_26, column_27, column_28, column_29,
column_30, column_31, column_32, column_33, column_34, column_35, column_36,
column_37, column_38, column_39, column_40, column_41, column_42, column_43,
column_44, column_45, column_46, column_47, column_48, column_49, column_50,
column_51, column_52, column_53, column_54, column_55, column_56, column_57,
column_58, column_59, column_60, column_61, column_62, column_63, column_64,
column_65, column_66, column_67, column_68, column_69, column_70, column_71,
column_72, column_73, column_74, column_75, column_76, column_77, column_78,
column_79, column_80, column_81, column_82, column_83, column_84, column_85,
column_86, column_87, column_88, column_89, column_90, column_91, column_92,
column_93, column_94, column_95, column_96, column_97, column_98, column_99,
column_100, column_101, column_102, column_103, column_104, column_105,
column_106, column_107, column_108, column_109, column_110, column_111,
column_112, column_113, column_114, column_115, column_116, column_117,
column_118, column_119, column_120, column_121, column_122, column_123,
column_124, column_125, column_126, column_127, column_128, column_129,
column_130, column_131, column_132, column_133, column_134, column_135,
column_136, column_137, column_138, column_139, column_140, column_141,
column_142, column_143, column_144, column_145, column_146, column_147,
column_148, column_149, column_150, column_151, column_152, column_153,
column_154, column_155, column_156, column_157, column_158, column_159,
column_160, column_161, column_162, column_163, column_164, column_165,
column_166, column_167, column_168, column_169, column_170, column_171,
column_172, column_173, column_174, column_175, column_176, column_177,
column_178, column_179, column_180, column_181, column_182, column_183,
column_184, column_185, column_186, column_187, column_188, column_189,
column_190, column_191, column_192, column_193, column_194, column_195,
column_196, column_197, column_198, column_199) values (?, ?, ?, ?, ?, ?, ?, ?,
?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?,
?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?,
?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?,
?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?,
?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?,
?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?,
?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?,
?, ?, ?, ?, ?, ?, ?, ?, ?, ?)]
org.apache.ignite.internal.tx.impl.PrimaryReplicaExpiredException: IGN-TX-13
TraceId:98224b48-892e-4831-b5de-4d4fb09e55b5 Primary replica has expired,
transaction will be rolled back: [groupId = 1850_part_21, expected enlistment
consistency token = 112069202113202526, commit timestamp = HybridTimestamp
[physical=2024-03-10 03:13:16:057 +0000, logical=396,
composite=112069207395991948], current primary replica = null]
at
org.apache.ignite.internal.tx.impl.TxManagerImpl.lambda$verifyCommitTimestamp$23(TxManagerImpl.java:917)
at
java.base/java.util.concurrent.CompletableFuture$UniAccept.tryFire(CompletableFuture.java:714)
at
java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
at
java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2073)
at
org.apache.ignite.internal.util.PendingComparableValuesTracker.lambda$completeWaitersOnUpdate$0(PendingComparableValuesTracker.java:169)
at
java.base/java.util.concurrent.ConcurrentMap.forEach(ConcurrentMap.java:122)
at
org.apache.ignite.internal.util.PendingComparableValuesTracker.completeWaitersOnUpdate(PendingComparableValuesTracker.java:169)
at
org.apache.ignite.internal.util.PendingComparableValuesTracker.update(PendingComparableValuesTracker.java:103)
at
org.apache.ignite.internal.metastorage.server.time.ClusterTimeImpl.updateSafeTime(ClusterTimeImpl.java:146)
at
org.apache.ignite.internal.metastorage.impl.MetaStorageManagerImpl.onSafeTimeAdvanced(MetaStorageManagerImpl.java:823)
at
org.apache.ignite.internal.metastorage.impl.MetaStorageManagerImpl$1.onSafeTimeAdvanced(MetaStorageManagerImpl.java:430)
at
org.apache.ignite.internal.metastorage.server.WatchProcessor.lambda$advanceSafeTime$8(WatchProcessor.java:314)
at
java.base/java.util.concurrent.CompletableFuture$UniRun.tryFire(CompletableFuture.java:783)
at
java.base/java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:478)
at
java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at
java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:834)
2024-03-10 03:13:24:569 +0000
[INFO][TablesAmountCapacityTest_cluster_0-srv-worker-1][ClientInboundMessageHandler]
Partition primary replica changed, notifying client [connectionId=1,
remoteAddress=/127.0.0.1:33690]
{code}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
