Driver version
Provide the JDBC driver version (e.g. 10.2.0).
10.2.
Problem description
In trying to figure out why an upgrade from 6.2.2 driver to 10.2.0 was preforming very much worse on a high latency network connection, I noticed strange TDS Command logging. Some TDS Commands, such as commit and setAutoCommit, are being executed twice!
I debugged locally to find the problem, then looked into the git history. This is the commit which introduced the problem. The diff is large for the SQLServerConnection class, you will need to manually expand it.
Notice two calls to executeCommand(new ConnectionCommand(sql, logContext));. On lines 3777 and 3782 in the diff.
On current main branch you can see the issue here on lines 3908 and 3913.
JDBC trace logs
An example of a double call for setAutoCommit:
16-Feb-2022 17:26:00.470 FINER [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.SQLServerConnection:17.setAutoCommit ENTRY true
16-Feb-2022 17:37:08.322 FINEST [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.TDSCommand.startRequest TDSCommand@5f8ccf71 (setAutoCommit): starting request...
16-Feb-2022 17:37:08.351 FINEST [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.TDSCommand.startResponse TDSCommand@5f8ccf71 (setAutoCommit): finishing request
16-Feb-2022 17:37:08.358 FINEST [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.TDSCommand.onRequestComplete TDSCommand@5f8ccf71 (setAutoCommit): request complete
16-Feb-2022 17:37:08.359 FINEST [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.TDSCommand.startResponse TDSCommand@5f8ccf71 (setAutoCommit): Reading response...
16-Feb-2022 17:37:08.431 FINEST [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.TDSCommand.onResponseEOM TDSCommand@5f8ccf71 (setAutoCommit): disabling interrupts
16-Feb-2022 17:37:15.880 FINEST [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.TDSCommand.startRequest TDSCommand@7bd470e6 (setAutoCommit): starting request...
16-Feb-2022 17:37:15.881 FINEST [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.TDSCommand.startResponse TDSCommand@7bd470e6 (setAutoCommit): finishing request
16-Feb-2022 17:37:15.882 FINEST [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.TDSCommand.onRequestComplete TDSCommand@7bd470e6 (setAutoCommit): request complete
16-Feb-2022 17:37:15.883 FINEST [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.TDSCommand.startResponse TDSCommand@7bd470e6 (setAutoCommit): Reading response...
16-Feb-2022 17:37:15.956 FINEST [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.TDSCommand.onResponseEOM TDSCommand@7bd470e6 (setAutoCommit): disabling interrupts
16-Feb-2022 17:42:04.369 FINER [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.SQLServerConnection:17.setAutoCommit RETURN
Another for commit:
16-Feb-2022 17:26:00.317 FINER [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.SQLServerConnection:17.commit ENTRY
16-Feb-2022 17:26:00.318 FINEST [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.TDSCommand.detach TDSCommand@3bf967dc (SQLServerPreparedStatement:69 executeXXX): detaching...
16-Feb-2022 17:26:00.318 FINEST [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.TDSCommand.startRequest TDSCommand@49bda83e (Connection.commit): starting request...
16-Feb-2022 17:26:00.318 FINEST [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.TDSCommand.startResponse TDSCommand@49bda83e (Connection.commit): finishing request
16-Feb-2022 17:26:00.318 FINEST [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.TDSCommand.onRequestComplete TDSCommand@49bda83e (Connection.commit): request complete
16-Feb-2022 17:26:00.318 FINEST [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.TDSCommand.startResponse TDSCommand@49bda83e (Connection.commit): Reading response...
16-Feb-2022 17:26:00.402 FINEST [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.TDSCommand.onResponseEOM TDSCommand@49bda83e (Connection.commit): disabling interrupts
16-Feb-2022 17:26:00.402 FINEST [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.TDSCommand.startRequest TDSCommand@40d12708 (Connection.commit): starting request...
16-Feb-2022 17:26:00.402 FINEST [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.TDSCommand.startResponse TDSCommand@40d12708 (Connection.commit): finishing request
16-Feb-2022 17:26:00.402 FINEST [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.TDSCommand.onRequestComplete TDSCommand@40d12708 (Connection.commit): request complete
16-Feb-2022 17:26:00.402 FINEST [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.TDSCommand.startResponse TDSCommand@40d12708 (Connection.commit): Reading response...
16-Feb-2022 17:26:00.470 FINEST [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.TDSCommand.onResponseEOM TDSCommand@40d12708 (Connection.commit): disabling interrupts
16-Feb-2022 17:26:00.470 FINER [http-nio-8080-exec-7] com.microsoft.sqlserver.jdbc.SQLServerConnection:17.commit RETURN
Driver version
Provide the JDBC driver version (e.g. 10.2.0).
10.2.
Problem description
In trying to figure out why an upgrade from 6.2.2 driver to 10.2.0 was preforming very much worse on a high latency network connection, I noticed strange TDS Command logging. Some TDS Commands, such as
commitandsetAutoCommit, are being executed twice!I debugged locally to find the problem, then looked into the git history. This is the commit which introduced the problem. The diff is large for the SQLServerConnection class, you will need to manually expand it.
Notice two calls to
executeCommand(new ConnectionCommand(sql, logContext));. On lines 3777 and 3782 in the diff.On current main branch you can see the issue here on lines 3908 and 3913.
JDBC trace logs
An example of a double call for
setAutoCommit:Another for
commit: