[IGNITE-19275] Creation of big amount of tables throws exception

• Type: Bug
• Status: Resolved
• Priority: Critical
• Resolution: Cannot Reproduce
• Affects Version/s: 3.0
• Component/s: general
• Labels: ignite-3
• Ignite Flags: Docs Required, Release Notes Required
• Assignee: Unassigned
• Reporter: Igor
• Created: 11/Apr/23 14:35
• Updated: 16/Jul/24 08:50
• Resolved: 16/Jul/24 08:50

Description

Steps:

1. Sart 2 nodes
2. Init cluster
3. Connect to cluster via jdbc
4. Create table with 5 columns.
5. Wait 30 ms.
6. Repeat points 4-5 1000 times.

Expected behavior:

1. Creation time is constant.
2. Tables are created.

Actual behavior:

1. Creation time is increasing
2. The exception is thrown| after 200+ tables are created

Details:

Creation time graph:

Exceptions:

1. From client:

Exception in thread "main" java.sql.SQLException: Exception while executing query [query=CREATE TABLE table_239(id INT PRIMARY KEY, column_1 VARCHAR, column_2 VARCHAR, column_3 VARCHAR, column_4 VARCHAR)]. Error message:IGN-CMN-65535 TraceId:7299edda-2a88-4448-ba6d-366fca88cfd4
        at org.apache.ignite.internal.jdbc.proto.IgniteQueryErrorCode.createJdbcSqlException(IgniteQueryErrorCode.java:57)
        at org.apache.ignite.internal.jdbc.JdbcStatement.execute0(JdbcStatement.java:148)
        at org.apache.ignite.internal.jdbc.JdbcStatement.executeUpdate(JdbcStatement.java:177)
        at lunigorn.ignite3test.Test.main(Test.java:18) 

    2. From server logs:

2023-04-11 15:13:49:881 +0200 [WARNING][%node_1%Raft-Group-Client-5][SchemaManager] Error when processing CREATE event
java.util.concurrent.CompletionException: org.apache.ignite.lang.IgniteInternalException: IGN-SQL-32 TraceId:d3484efb-2ca6-4098-8c17-30a878c0801e Couldn't evaluate sql schemas for causality token: 722
    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$UniApply.tryFire(CompletableFuture.java:632)
    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.causality.BaseVersionedValue.lambda$copyState$6(BaseVersionedValue.java:305)
    at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859)
    at java.base/java.util.concurrent.CompletableFuture.uniWhenCompleteStage(CompletableFuture.java:883)
    at java.base/java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:2251)
    at org.apache.ignite.internal.causality.BaseVersionedValue.copyState(BaseVersionedValue.java:303)
    at org.apache.ignite.internal.causality.BaseVersionedValue.complete(BaseVersionedValue.java:189)
    at org.apache.ignite.internal.causality.CompletableVersionedValue.completeExceptionally(CompletableVersionedValue.java:101)
    at org.apache.ignite.internal.sql.engine.schema.SqlSchemaManagerImpl.lambda$new$1(SqlSchemaManagerImpl.java:131)
    at org.apache.ignite.internal.causality.BaseVersionedValue.lambda$notifyCompletionListeners$7(BaseVersionedValue.java:331)
    at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859)
    at java.base/java.util.concurrent.CompletableFuture.uniWhenCompleteStage(CompletableFuture.java:883)
    at java.base/java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:2251)
    at org.apache.ignite.internal.causality.BaseVersionedValue.notifyCompletionListeners(BaseVersionedValue.java:326)
    at org.apache.ignite.internal.causality.BaseVersionedValue.complete(BaseVersionedValue.java:198)
    at org.apache.ignite.internal.causality.IncrementalVersionedValue.lambda$completeInternal$1(IncrementalVersionedValue.java:236)
    at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859)
    at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:837)
    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.causality.BaseVersionedValue.lambda$copyState$6(BaseVersionedValue.java:305)
    at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859)
    at java.base/java.util.concurrent.CompletableFuture.uniWhenCompleteStage(CompletableFuture.java:883)
    at java.base/java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:2251)
    at org.apache.ignite.internal.causality.BaseVersionedValue.copyState(BaseVersionedValue.java:303)
    at org.apache.ignite.internal.causality.BaseVersionedValue.complete(BaseVersionedValue.java:189)
    at org.apache.ignite.internal.causality.IncrementalVersionedValue.lambda$completeInternal$1(IncrementalVersionedValue.java:236)
    at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859)
    at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:837)
    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.causality.BaseVersionedValue.lambda$copyState$6(BaseVersionedValue.java:305)
    at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859)
    at java.base/java.util.concurrent.CompletableFuture.uniWhenCompleteStage(CompletableFuture.java:883)
    at java.base/java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:2251)
    at org.apache.ignite.internal.causality.BaseVersionedValue.copyState(BaseVersionedValue.java:303)
    at org.apache.ignite.internal.causality.BaseVersionedValue.complete(BaseVersionedValue.java:189)
    at org.apache.ignite.internal.causality.IncrementalVersionedValue.lambda$completeInternal$1(IncrementalVersionedValue.java:236)
    at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:859)
    at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:837)
    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.raft.RaftGroupServiceImpl.sendWithRetry(RaftGroupServiceImpl.java:511)
    at org.apache.ignite.internal.raft.RaftGroupServiceImpl.lambda$handleThrowable$40(RaftGroupServiceImpl.java:560)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
    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:829)
Caused by: org.apache.ignite.lang.IgniteInternalException: IGN-SQL-32 TraceId:d3484efb-2ca6-4098-8c17-30a878c0801e Couldn't evaluate sql schemas for causality token: 722
    ... 42 more
Caused by: java.util.concurrent.TimeoutException
    ... 8 more

The nodes logs are in attachment.

 

The code to reproduce (or use gradle project):

package lunigorn.ignite3test;

import java.sql.*;

public class Test {
    private static final String DB_URL = "jdbc:ignite:thin://127.0.1.1:10800";
    private static final int COLUMNS_COUNT = 5;
    private static final int TABLES_COUNT = 1000;
    private static final int SLEEP = 30;

    public static void main(String[] args) throws SQLException {
        System.out.println("Test started");
        try (Connection connection = DriverManager.getConnection(DB_URL); Statement statement = connection.createStatement()){
            System.out.println("Connection created");
            for (int i = 0; i < TABLES_COUNT; i++) {
                String createTableQuery = createTableQuery("table_" + i, COLUMNS_COUNT);
                long timestampBefore = System.currentTimeMillis();
                statement.executeUpdate(createTableQuery);
                long timestampAfter = System.currentTimeMillis();
                System.out.println("Create table " + i + " took " + (timestampAfter - timestampBefore) + " ms");
                if (i % 50 == 0){
                    int tablesCount = findTablesCount(connection);
                    if (tablesCount != i+1){
                        throw new IllegalStateException("Expected " + (i+1) + " tables in cluster, but was " + tablesCount);
                    }
                    System.out.println("Tables count in cluster: " + tablesCount);
                }
                sleep();
            }
        }
    }


    public static String createTableQuery(String tableName, int columnsAmount){
        StringBuilder sb = new StringBuilder();
        sb.append("CREATE TABLE ").append(tableName).append("(");
        for (int i = 0; i < columnsAmount; i++) {
            if (i == 0){
                sb.append("id INT PRIMARY KEY");
            } else {
                sb.append("column_").append(i).append(" VARCHAR");
            }

            if (i != columnsAmount - 1){
                sb.append(", ");
            }
        }
        sb.append(")");
        return sb.toString();
    }

    public static int findTablesCount(Connection connection) throws SQLException {
        DatabaseMetaData md = connection.getMetaData();
        String catalog = connection.getCatalog();
        ResultSet table_rs = md.getTables(catalog, null, null, new String[]{"TABLE"});
        int count = 0;
        while (table_rs.next()){
            count++;
        }
        return count;
    }

    public static void sleep(){
        try {
            Thread.sleep(SLEEP);
        } catch (InterruptedException ignored) {
        }
    }

}

 

Issue Links

• is related to: IGNITE-19419 Internal queue overload under intensive SQL load
• is related to: IGNITE-19477 Custom operation timeout for sendWithRetry
• is related to: IGNITE-19478 Possible excess size of table entities written into meta storage
• is related to: IGNITE-19563 Deadlock on indexes creation with multiple tables creation
• is related to: IGNITE-19591 Possible bottleneck with RocksDB on multiple table creation, with RocksDB as table storage
• is related to: IGNITE-19530 Reduce size of configuration keys