Skip to content

Infinite loop in SQLServerConnection.login, spawning thousands of threads, causes high CPU and threads consumption #1831

@haimadrian

Description

@haimadrian

Hello,
I'm having an issue with mssql-jdbc driver in multi-threaded environment.

Driver version

10.2.0.jre8

SQL Server version

Microsoft SQL Server 2019 (RTM-GDR) (KB4583458) - 15.0.2080.9 (X64) Nov 6 2020 16:50:01 Copyright (C) 2019 Microsoft Corporation Developer Edition (64-bit) on Windows 10 Enterprise 10.0 (Build 19044: )

Client Operating System

Windows 10 Enterprise 21H2 19044.1706
Processor: Intel(R) Core(TM) i7-8850H CPU @ 2.60GHz 2.59 GHz (6 cores, 12 logical)
RAM: 32GB

JAVA/JVM version

openjdk version "1.8.0_222"
OpenJDK Runtime Environment (Zulu 8.40.0.25-CA-win64) (build 1.8.0_222-b10)
OpenJDK 64-Bit Server VM (Zulu 8.40.0.25-CA-win64) (build 25.222-b10, mixed mode)

Table schema

N/A

Problem description

The issue is that the thread pool of com.microsoft.sqlserver.jdbc.SocketFinder is not limited, and it creates thousands of threads, causing the JVM to consume all available CPU of a machine.
The issue is reproducible when two threads are trying to connect to a stopped instance, and the first thread receives a TimeOut exception, and interrupt the second thread while it is waiting for its time-out to occur.
I have prepared a short demonstration to reproduce the issue. You do not really have to connect to a real instance.
I could overcome this by synchronizing the access to DriverManager.getConnection(...), and some sleep (250 milliseconds). Without the sleep the issue is still reproducible.
I would like to avoid synchronizing the access to DriverManager, to let multiple threads work concurrently.
The issue is also reproducible when using commons-dbcp, and this time synchronizing the access to basicDataSource.getConnection() does not help to overcome the issue.

Expected behavior

  • Limit SocketFinder's thread pool to make sure it will not pass X threads. And if X is configurable, that will be perfect.
  • When a connection is unreachable (ConnectException), bubble it to the caller immediately, or after Y attempts, rather than looping in a busy-waiting implementation that causes thousands of calls to SocketFinder.findSocketUsingThreading.
  • Let multiple threads to acquire connection to MSSQL.

Actual behavior

7K threads and ~80% CPU usage.
Output from my demo: (Notice the ~7K threads)

2022-05-11 19:00:55.528 {main}: Connecting to SQL Server...
2022-05-11 19:00:55.530 {ThreadMXBean}: Amount of threads: 8
2022-05-11 19:00:55.531 {DemoThread}: Going to sleep for 5 SECONDS
2022-05-11 19:00:57.528 {ThreadMXBean}: Amount of threads: 10
2022-05-11 19:00:59.524 {ThreadMXBean}: Amount of threads: 10
2022-05-11 19:01:00.546 {DemoThread}: Connecting to SQL Server...
2022-05-11 19:01:01.523 {ThreadMXBean}: Amount of threads: 12
2022-05-11 19:01:03.530 {ThreadMXBean}: Amount of threads: 12
2022-05-11 19:01:05.527 {ThreadMXBean}: Amount of threads: 12
2022-05-11 19:01:05.703 {main}: Error has occurred: com.microsoft.sqlserver.jdbc.SQLServerException: The TCP/IP connection to the host localhost, port 1433 has failed. Error: "connect timed out. Verify the connection properties. Make sure that an instance of SQL Server is running on the host and accepting TCP/IP connections at the port. Make sure that TCP connections to the port are not blocked by a firewall.".
com.microsoft.sqlserver.jdbc.SQLServerException: The TCP/IP connection to the host localhost, port 1433 has failed. Error: "connect timed out. Verify the connection properties. Make sure that an instance of SQL Server is running on the host and accepting TCP/IP connections at the port. Make sure that TCP connections to the port are not blocked by a firewall.".
	at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDriverError(SQLServerException.java:237)
	at com.microsoft.sqlserver.jdbc.SQLServerException.ConvertConnectExceptionToSQLServerException(SQLServerException.java:288)
	at com.microsoft.sqlserver.jdbc.SocketFinder.findSocket(IOBuffer.java:2720)
	at com.microsoft.sqlserver.jdbc.TDSChannel.open(IOBuffer.java:761)
	at com.microsoft.sqlserver.jdbc.SQLServerConnection.connectHelper(SQLServerConnection.java:3180)
	at com.microsoft.sqlserver.jdbc.SQLServerConnection.login(SQLServerConnection.java:2833)
	at com.microsoft.sqlserver.jdbc.SQLServerConnection.connectInternal(SQLServerConnection.java:2671)
	at com.microsoft.sqlserver.jdbc.SQLServerConnection.connect(SQLServerConnection.java:1640)
	at com.microsoft.sqlserver.jdbc.SQLServerDriver.connect(SQLServerDriver.java:936)
	at java.sql.DriverManager.getConnection(DriverManager.java:664)
	at java.sql.DriverManager.getConnection(DriverManager.java:208)
	at org.example.MSSQLJdbcTest$SqlServerConnection.connect(MSSQLJdbcTest.java:145)
	at org.example.MSSQLJdbcTest.main(MSSQLJdbcTest.java:57)

2022-05-11 19:01:05.706 {main}: Going to sleep for 10 SECONDS
2022-05-11 19:01:07.529 {ThreadMXBean}: Amount of threads: 4339
2022-05-11 19:01:09.526 {ThreadMXBean}: Amount of threads: 7531
2022-05-11 19:01:09.547 {DemoThread}: Error has occurred during second connect: com.microsoft.sqlserver.jdbc.SQLServerException: The TCP/IP connection to the host localhost, port 1433 has failed. Error: "null. Verify the connection properties. Make sure that an instance of SQL Server is running on the host and accepting TCP/IP connections at the port. Make sure that TCP connections to the port are not blocked by a firewall.".
com.microsoft.sqlserver.jdbc.SQLServerException: The TCP/IP connection to the host localhost, port 1433 has failed. Error: "null. Verify the connection properties. Make sure that an instance of SQL Server is running on the host and accepting TCP/IP connections at the port. Make sure that TCP connections to the port are not blocked by a firewall.".
	at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDriverError(SQLServerException.java:237)
	at com.microsoft.sqlserver.jdbc.SQLServerException.ConvertConnectExceptionToSQLServerException(SQLServerException.java:288)
	at com.microsoft.sqlserver.jdbc.SocketFinder.findSocket(IOBuffer.java:2708)
	at com.microsoft.sqlserver.jdbc.TDSChannel.open(IOBuffer.java:761)
	at com.microsoft.sqlserver.jdbc.SQLServerConnection.connectHelper(SQLServerConnection.java:3180)
	at com.microsoft.sqlserver.jdbc.SQLServerConnection.login(SQLServerConnection.java:2833)
	at com.microsoft.sqlserver.jdbc.SQLServerConnection.connectInternal(SQLServerConnection.java:2671)
	at com.microsoft.sqlserver.jdbc.SQLServerConnection.connect(SQLServerConnection.java:1640)
	at com.microsoft.sqlserver.jdbc.SQLServerDriver.connect(SQLServerDriver.java:936)
	at java.sql.DriverManager.getConnection(DriverManager.java:664)
	at java.sql.DriverManager.getConnection(DriverManager.java:208)
	at org.example.MSSQLJdbcTest$SqlServerConnection.connect(MSSQLJdbcTest.java:145)
	at org.example.MSSQLJdbcTest.lambda$main$3(MSSQLJdbcTest.java:50)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

2022-05-11 19:01:11.533 {ThreadMXBean}: Amount of threads: 7531
2022-05-11 19:01:13.529 {ThreadMXBean}: Amount of threads: 7531
2022-05-11 19:01:15.678 {ThreadMXBean}: Amount of threads: 7531
2022-05-11 19:01:15.762 {main}: Going to sleep for 10 SECONDS
2022-05-11 19:01:17.522 {ThreadMXBean}: Amount of threads: 7531
2022-05-11 19:01:19.527 {ThreadMXBean}: Amount of threads: 7531
2022-05-11 19:01:21.526 {ThreadMXBean}: Amount of threads: 7531
2022-05-11 19:01:23.521 {ThreadMXBean}: Amount of threads: 7531
2022-05-11 19:01:25.530 {ThreadMXBean}: Amount of threads: 7531
2022-05-11 19:01:25.763 {main}: All Tests Complete. Exiting.

Error message/stack trace

N/A

Any other details that can be helpful

You can run this code to reproduce the issue.

package org.example;

import java.io.PrintWriter;
import java.io.StringWriter;
import java.lang.management.ManagementFactory;
import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.SQLException;
import java.text.SimpleDateFormat;
import java.util.Date;
import java.util.Properties;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.ScheduledExecutorService;
import java.util.concurrent.TimeUnit;

public class MSSQLJdbcTest {
    private static final SimpleDateFormat dateFormat = new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS");

    public static void main(String[] args) {
        // Make sure the instance is stopped
        String connectionUrl = "jdbc:sqlserver://localhost" +
                ";databaseName=master" +
                ";applicationName=Naruto" +
                ";loginTimeout=10" +
                ";socketTimeout=10000" +
                ";encrypt=false" +
                ";trustServerCertificate=true" +
                //";integratedSecurity=true" +
                //";authenticationScheme=NativeAuthentication" +
                ";MultiSubnetFailover=false" +
                ";userName=Sasuke"
                ;

        SqlServerConnection connection = new SqlServerConnection(connectionUrl, "Uchiha");
        ExecutorService executor = null;
        ScheduledExecutorService scheduledExecutor = null;

        try {
            // A scheduler to print amount of threads created in this jvm
            scheduledExecutor = Executors.newSingleThreadScheduledExecutor(r -> new Thread(r, "ThreadMXBean"));
            scheduledExecutor.scheduleAtFixedRate(() -> log("Amount of threads: %d", ManagementFactory.getThreadMXBean().getTotalStartedThreadCount()), 0, 2, TimeUnit.SECONDS);

            // A second thread for the demo, to simulate multi-threaded environment
            executor = Executors.newSingleThreadExecutor(r -> new Thread(r, "DemoThread"));
            executor.submit(() -> {
                safeSleep(5, TimeUnit.SECONDS);
                try {
                    // Second connect
                    connection.connect();
                } catch (SQLException e) {
                    log("Error has occurred during second connect:", e);
                }
            });

            // First connect
            connection.connect();

            safeSleep(5, TimeUnit.SECONDS);
        } catch (Exception e) {
            log("Error has occurred:", e);
        } finally {
            if (executor != null) {
                // Shutdown executor and interrupt the thread.
                executor.shutdownNow();
            }

            try {
                safeSleep(10, TimeUnit.SECONDS);
                connection.disconnect();
            } catch (SQLException e) {
                log("Error has occurred while closing connection:", e);
            }

            safeSleep(10, TimeUnit.SECONDS);

            if (scheduledExecutor != null) {
                scheduledExecutor.shutdownNow();
            }
        }

        log("All Tests Complete. Exiting.");
    }

    private static void safeSleep(int duration, TimeUnit timeUnit) {
        log("Going to sleep for %d %s", duration, timeUnit.name());
        try { Thread.sleep(timeUnit.toMillis(duration)); } catch (InterruptedException ignore) {}
    }

    private static void log(String message, Object... args) {
        log(message, null, args);
    }

    private synchronized static void log(String message, Throwable thrown, Object... args) {
        String msg = message;

        if (args != null) {
            msg = String.format(msg, args);
        }

        if (thrown != null) {
            msg += " " + thrown;
        }

        System.out.printf("%s {%s}: %s%n", dateFormat.format(new Date()), Thread.currentThread().getName(), msg);

        if (thrown != null) {
            System.out.println(getStackTrace(thrown));
        }
    }

    private static String getStackTrace(Throwable thrown) {
        String result = null;
        try (StringWriter sw = new StringWriter(); PrintWriter pw = new PrintWriter(sw)) {
            thrown.printStackTrace(pw);
            result = sw.toString();
        } catch (Exception ignore) { }

        return result;
    }

    private static class SqlServerConnection {
        private final String connectionUrl;
        private final String pwd;
        private Connection connection;

        SqlServerConnection(String connectionUrl, String pwd) {
            this.connectionUrl = connectionUrl;
            this.pwd = pwd;
        }

        public void connect() throws SQLException {
            log("Connecting to SQL Server...");
            if (connection != null) {
                log("Connection is already existing. Disconnecting existing connection...");
                disconnect();
            }
            Properties props = new Properties();
            props.put("password", pwd);

            // Using this, along with synchronization over 'this' instance can overcome the issue,
            // but it will not allow two threads to connect simultaneously...
            //safeSleep(250, TimeUnit.MILLISECONDS);

            connection = DriverManager.getConnection(connectionUrl, props);
            log("Connected.");
        }

        public void disconnect() throws SQLException {
            if (connection != null) {
                log("Disconnecting from SQL Server...");
                connection.close();
                log("Disconnected.");
            }
        }
    }
}

JDBC trace logs

Modifying log level affects the issue:

  • FINEST: ~94 threads
  • FINE: ~794 threads
  • INFO: ~7292 threads

MSSQLJdbcDemo.log

Metadata

Metadata

Assignees

Labels

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions