Debugging connection pool issues

[ViliusS]

I'm trying to debug an issue with our Java application that sometimes, for some not so apparent reason, the application cannot connect to SQL Server. I suspect that this issue has something to do with the connection pool size. I'm trying to setup SQL logging as described in https://learn.microsoft.com/en-us/sql/connect/jdbc/tracing-driver-operation?view=sql-server-ver16 so that I could clearly see how many connections are used and how many pool connection are still free/idle. I have configured it the following way:

handlers=java.util.logging.FileHandler
.level=OFF
java.util.logging.FileHandler.pattern = log/sqlwire.log
java.util.logging.FileHandler.limit = 10240000
java.util.logging.FileHandler.count = 10
java.util.logging.FileHandler.formatter = java.util.logging.SimpleFormatter
java.util.logging.FileHandler.level = FINEST

com.microsoft.sqlserver.jdbc.internals.SQLServerDataSource.level=FINER
com.microsoft.sqlserver.jdbc.internals.SQLServerException.level=FINE

This produces the output like this:

FINER: SQLServerPooledConnection:10 user:(default).
Jun 26, 2025 8:44:29 AM com.microsoft.sqlserver.jdbc.SQLServerPooledConnection getConnection
FINE: SQLServerPooledConnection:10 Physical connection, ConnectionID:10 ClientConnectionId: f56b71c0-5620-403c-93a3-7e295d351da0
Jun 26, 2025 8:44:29 AM com.microsoft.sqlserver.jdbc.SQLServerPooledConnection getConnection
FINE: SQLServerPooledConnection:10 proxy  ProxyConnectionID:8388666 is returned.
Jun 26, 2025 8:44:29 AM com.microsoft.sqlserver.jdbc.SQLServerPooledConnection notifyEvent
FINER: SQLServerPooledConnection:10 Exception:nullConnectionID:10 ClientConnectionId: f56b71c0-5620-403c-93a3-7e295d351da0
Jun 26, 2025 8:44:29 AM com.microsoft.sqlserver.jdbc.SQLServerPooledConnection notifyEvent
FINER: SQLServerPooledConnection:10 notifyEvent:connectionClosed ConnectionID:10 ClientConnectionId: f56b71c0-5620-403c-93a3-7e295d351da0
Jun 26, 2025 8:44:29 AM com.microsoft.sqlserver.jdbc.SQLServerPooledConnection getConnection
FINER: SQLServerPooledConnection:11 user:(default).
Jun 26, 2025 8:44:29 AM com.microsoft.sqlserver.jdbc.SQLServerPooledConnection getConnection
FINE: SQLServerPooledConnection:11 Physical connection, ConnectionID:11 ClientConnectionId: 4db13a4e-7e90-44fc-992a-4d239c040efb
Jun 26, 2025 8:44:29 AM com.microsoft.sqlserver.jdbc.SQLServerPooledConnection getConnection
FINE: SQLServerPooledConnection:11 proxy  ProxyConnectionID:8388667 is returned.
Jun 26, 2025 8:44:29 AM com.microsoft.sqlserver.jdbc.SQLServerPooledConnection notifyEvent
FINER: SQLServerPooledConnection:11 Exception:nullConnectionID:11 ClientConnectionId: 4db13a4e-7e90-44fc-992a-4d239c040efb
Jun 26, 2025 8:44:29 AM com.microsoft.sqlserver.jdbc.SQLServerPooledConnection notifyEvent
FINER: SQLServerPooledConnection:11 notifyEvent:connectionClosed ConnectionID:11 ClientConnectionId: 4db13a4e-7e90-44fc-992a-4d239c040efb
Jun 26, 2025 8:44:29 AM com.microsoft.sqlserver.jdbc.SQLServerPooledConnection getConnection
FINER: SQLServerPooledConnection:11 user:(default).
Jun 26, 2025 8:44:29 AM com.microsoft.sqlserver.jdbc.SQLServerPooledConnection getConnection
FINE: SQLServerPooledConnection:11 Physical connection, ConnectionID:11 ClientConnectionId: 4db13a4e-7e90-44fc-992a-4d239c040efb
Jun 26, 2025 8:44:29 AM com.microsoft.sqlserver.jdbc.SQLServerPooledConnection getConnection
....

I'm still puzzled though by this output as it doesn't tell me anything about the state of the pool itself. Numbers in SQLServerPooledConnection:**11** ir SQLServerPooledConnection:**10** sometimes increases, sometimes decreases, but it is unclear if these IDs actually mean that I have used up all 10 or 11 pooled connections in total or if it just internal ID which could be any number?
I tried various other combinations of internal and public classes with FINER and FINE logging levels, but cannot get anything concrete in the logs.

Am I missing something or logging pool's state is currently not implemented? Also, how to interpret those SQLServerPooledConnection:**X** numbers?
Any pointers would be much appreciated.

P.S. I cannot debug this issue on the server side because the issue happens to only to one client and only at times. I don't have direct access to the SQL server.

[David-Engel]

The mssql-jdbc library doesn't implement pooling itself. The SQLServerPooledConnection class is leveraged by 3rd party pooling libraries and won't have statistics about their pool sizes/use other than that the pool has requested a new connection (or reused a connection) from the driver, which you are seeing in the logs. You'll need to see what logging needs to be enabled in your pooling library to gather more info about the pool state.

[ViliusS]

OK. So what are those numbers after SQLServerPooledConnection ? Looking at the code

mssql-jdbc/src/main/java/com/microsoft/sqlserver/jdbc/SQLServerPooledConnection.java

Line 65 in 558f420

traceID = getClass().getSimpleName() + ':' + nextPooledConnectionID();

it's some kind ID, but can these IDs be used as indirect indication of how many connections are actually used at the moment?

[ranjeetkumar274]

you’re not missing a logging flag the Microsoft JDBC driver just doesn’t log pool state. The numbers you see (SQLServerPooledConnection:X) are just internal IDs for physical connections. If you need pool statistics, you’ll have to rely on your pooling library (e.g., HikariCP) instead of the driver itself.

[ViliusS]

@ranjeetkumar274 , are these internal IDs coming from SQL Server, or is there a logic in how they are set, for example why they sometimes start from ID 7 on completely new pool?

[ranjeetkumar274]

ok bro, so those IDs are not from SQL Server they’re just made by the JDBC driver every new connection gets the next number the counter won’t reset till you restart JVM.

[ranjeetkumar274]

Sometimes they starts from 7 or 20 because earlier you got some misbehaved connections or existing ones , as they will only go to zero when you will restart your JVM as told you

[ViliusS]

The reason why I'm asking is because they definitely don't go to zero or even doesn't start at 1 on clean JVM restart. Sometimes the first ID when I start my Java application is 3, sometimes it's 7, sometimes 10.