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
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.SocketFinderis 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 tobasicDataSource.getConnection()does not help to overcome the issue.Expected behavior
SocketFinder's thread pool to make sure it will not pass X threads. And if X is configurable, that will be perfect.ConnectException), bubble it to the caller immediately, or after Y attempts, rather than looping in a busy-waiting implementation that causes thousands of calls toSocketFinder.findSocketUsingThreading.Actual behavior
7K threads and ~80% CPU usage.
Output from my demo: (Notice the ~7K threads)
Error message/stack trace
N/A
Any other details that can be helpful
You can run this code to reproduce the issue.
JDBC trace logs
Modifying log level affects the issue:
MSSQLJdbcDemo.log