5

Performance difference in prepared statements compared to jTDS due to differing...

 1 year ago
source link: https://github.com/microsoft/mssql-jdbc/issues/1196
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.

Performance difference in prepared statements compared to jTDS due to differing execution plan #1196

Closed

Chrriis opened this issue on Nov 28, 2019 · 90 comments

· Fixed by #1719

Comments

Driver version

7.4.1.jre12

SQL Server version

Microsoft SQL Server 2017 (RTM-GDR) (KB4505224) - 14.0.2027.2 (X64) Jun 15 2019 00:26:19 Copyright (C) 2017 Microsoft Corporation Enterprise Edition (64-bit) on Windows 10 Enterprise 10.0 (Build 18362: )

Client Operating System

Windows 10 Pro (1909)

JAVA/JVM version

OpenJDK 12.0.2+10

Table schema

A simple table with a few columns and one index

Problem description

We would like to switch from JTDS to MS SQL JDBC driver. The problem is that during long data crunching, the MS SQL driver is much slower. Our data crunching, which includes various other things, takes 77 minutes with JTDS and 104 minutes with MS SQL.

  1. Expected behaviour: comparable or better performance than JTDS for similar statements.
  2. Actual behaviour: some statements in MS SQL JDBC driver are much slower. Our simple test case shows 3x-4x slower.
  3. Any other details that can be helpful: micro benchmarks do not work. It is the state of the database as it evolves during the data crunching that exhibits this behavior. Make any change to the database (drop a table, change an index, remove and re-add a constraint, etc.) and the test case disappears. It may have to do with the computed statistics that JTDS is able to use and not MS SQL. Of course, it may also be a misuse or misconfiguration of the MS SQL JDBC driver...

Reproduction code

I narrowed down the test case to a relatively small backup (14MB, 170MB unzipped) and a Java class.

MSvsJTDS_bak.zip
SqlServerJdbcDriverSlowdownTest.zip

  • Load the backup to a SQL Server 2017 instance.
  • Set the credentials and server information at the top of the Java file, add JTDS JAR file and MS SQL JDBC JAR file to classpath, and run it.

We got these results:
1st Try:
Total time (ms): 2879 (MS)
Total time (ms): 929 (JTDS)

2nd Try:
Total time (ms): 2885 (MS)
Total time (ms): 888 (JTDS)

3rd Try:
Total time (ms): 2798 (MS)
Total time (ms): 993 (JTDS)

4th Try:
Total time (ms): 3057 (MS)
Total time (ms): 947 (JTDS)

On a different client and host machine, we got:
Total time (ms): 5681 (MS)
Total time (ms): 1516 (JTDS)

lukaseder, ArturSch, otbutz, petersedlacek, toby-murray-snow-software, and mikekuzak reacted with thumbs up emoji All reactions

Contributor

ulvii commented on Nov 29, 2019

Hi @Chrriis,
Thanks for creating the issue. We will investigate and get back to you.

Contributor

ulvii commented on Nov 30, 2019

Hi @Chrriis,
I wanted to share a few details in case they are helpful for your investigations. My initial testing shows that the behavior is query specific. I ran the exact same test with a simpler update query on numeric columns (update numerictable set column2=? where column1 = ?) and both drivers took almost exactly same amount of time to execute.

I also modified your test code a bit and seeing some strange behavior. When I hardcode the ID in the query

UPDATE T_DbPerfTest SET Col29 = x.Col29 FROM (   SELECT Col1, LEAD(Col28) OVER (PARTITION BY Col5, Col2, Col4, Col3 ORDER BY Col28, Col1) AS Col29   FROM T_DbPerfTest   WHERE Col29 IS NULL   AND (Col27 = 1 OR Col28 = ?)   AND Col2 = 240254 ) x WHERE T_DbPerfTest.Col1 = x.Col1 AND T_DbPerfTest.Col29 IS NULL AND x.Col29 = ? AND T_DbPerfTest.Col27 = 1

and update the JAVA code accordingly

    public static void executePreparedStatements(Connection connection, PreparedStatement preparedStatement) throws Exception {
        long[] ids = {
                240254,
                684796,
                684786,
                240102,
                240274,
                240303,
                240332,
                240244,
                685302,
                685331,
                685196,
                685389,
                685228,
                685360,
        };
        for(long id: ids) {
            preparedStatement.setLong(1, 27586214);
            preparedStatement.setLong(2, 27586214);
            preparedStatement.addBatch();
        }
        preparedStatement.executeBatch();
    }

jTDS driver becomes slower too, both drivers perform the same. So parametrizing IDs makes jTDS faster and I am currently not sure why. The only difference between drivers is jTDS calls sp_prepare whereas Microsoft JDBC driver calls sp_prepexec for PreparedStatemets. I will try to analyze this behavior sometime next week, please share your findings too.

Author

Chrriis commented on Dec 1, 2019

Thank you very much for the update!

Maybe I should tell more about this schema. This schema contains a primary key (Col1), a conceptual key (Col2, Col3, Col4, Col5) with a versioning column (Col28). A version can contain many rows of different conceptual keys.
Primary keys are (generally) an increasing number, and version column is an increasing number. Rows were added in the order of the versioning column, using statements that declare the keys in the same order.
The purpose of the test statement is to set the value of Col29 to the value of Col28 of the next version (per its conceptual key).

I am not a specialist in statistics computing in databases, but it is possible that the layout after insertion helps running the update statement (only the most recent versions are of interest, so last inserted rows per conceptual keys / PK) as done by JTDS.

You say that the only difference is in using sp_prepexec instead of sp_prepare. But in the test case, we clearly prepare the statement before executing it multiple times. Do you mean that sp_prepexec is invoked at the first batch execution (and sp_execute after that) or used at each batch execution (what would it mean to have a prepare step everytime)? Have you tried modifying the MS code to use sp_prepare like JTDS to see if you get the same result than JTDS (so we are sure there is nothing else at play here, like a subtle difference in the use of the TDS protocol, data types, etc.)?

I will do a few experiments tomorrow, I will let you know if I find anything of interest.

Author

Chrriis commented on Dec 2, 2019

I tried another variation of the statement which is less performant but more basic SQL (no window function).
UPDATE T_DbPerfTest SET Col29 = ? WHERE Col2 = ? AND Col27 = 1 AND Col29 IS NULL AND EXISTS ( SELECT 1 FROM T_DbPerfTest b WHERE T_DbPerfTest.Col5 = b.Col5 AND T_DbPerfTest.Col2 = b.Col2 AND T_DbPerfTest.Col4 = b.Col4 AND T_DbPerfTest.Col3 = b.Col3 AND ( T_DbPerfTest.Col28 < b.Col28 OR T_DbPerfTest.Col28 = b.Col28 AND T_DbPerfTest.Col1 < b.Col1 ))
You can try it yourself, just replace the statement in the test case, and comment the "setLong(3, xxx)" line.
Instead of times like "6020 (MS) vs 1512 (JTDS)", I get "14013 (MS) vs 5667 (JTDS)". Indeed a slower statement, but still similar slowdown ratio between MS and JTDS.

Author

Chrriis commented on Dec 2, 2019

I tried changing various settings in the connection string of SQL Server, but no improvement:

responseBuffering=full
enablePrepareOnFirstPreparedStatementCall=true
sendTimeAsDatetime=false
disableStatementPooling=false
statementPoolingCacheSize=10
serverPreparedStatementDiscardThreshold=0

I also tried to change JTDS parameters to see how the driver behaves. Still fast when changing:

TDS=7.0
maxStatements=0

JTDS became as slow as the MS driver when changing:
prepareSQL=2

I was not surprised by that last change result. The JTDS documentation says:

2: sp_executesql is used (fast)
3: sp_prepare and sp_cursorprepare are used in conjunction with sp_execute and sp_cursorexecute (faster, SQL Server only)

Author

Chrriis commented on Dec 2, 2019

The test case uses a batch but I found this is irrelevant. If you replace preparedStatement.addBatch(); with preparedStatement.execute(); and comment preparedStatement.executeBatch(); you get the same speed problem.

Author

Chrriis commented on Dec 2, 2019

So parametrizing IDs makes jTDS faster and I am currently not sure why.

The funny thing is that if you hardcode the 1st and 3rd parameters in the query (only leaving the ID parameterized), then the query is still fast for JTDS and slow for MS.

Contributor

ulvii commented on Dec 4, 2019

Hi @Chrriis ,

Do you mean that sp_prepexec is invoked at the first batch execution (and sp_execute after that) or used at each batch execution.

sp_prepexe is executed only once when statementPoolingCacheSize=10;disableStatementPooling=false;enablePrepareOnFirstPreparedStatementCall=true;. See SQL Profiler outputs below(I am hardcoding 1st and 3rd parameters):

MS JDBC

declare @p1 int
set @p1=1
exec sp_prepexec @p1 output,N'@P0 bigint',N'UPDATE T_DbPerfTest SET Col29 = x.Col29 FROM (   SELECT Col1, LEAD(Col28) OVER (PARTITION BY Col5, Col2, Col4, Col3 ORDER BY Col28, Col1) AS Col29   FROM T_DbPerfTest   WHERE Col29 IS NULL   AND (Col27 = 1 OR Col28 = 27586214)   AND Col2 = @P0 ) x WHERE T_DbPerfTest.Col1 = x.Col1 AND T_DbPerfTest.Col29 IS NULL AND x.Col29 = 27586214 AND T_DbPerfTest.Col27 = 1        ',240254
select @p1

exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360
exec sp_execute 1,240254
exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360
exec sp_execute 1,240254
exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360
exec sp_execute 1,240254
exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360
exec sp_execute 1,240254
exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360
exec sp_execute 1,240254
exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360
exec sp_execute 1,240254
exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360
exec sp_execute 1,240254
exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360
exec sp_execute 1,240254
exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360
exec sp_execute 1,240254
exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360
exec sp_execute 1,240254
exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360
declare @p1 int
set @p1=1
exec sp_prepare @p1 output,N'@P0 bigint',N'UPDATE T_DbPerfTest SET Col29 = x.Col29 FROM (   SELECT Col1, LEAD(Col28) OVER (PARTITION BY Col5, Col2, Col4, Col3 ORDER BY Col28, Col1) AS Col29   FROM T_DbPerfTest   WHERE Col29 IS NULL   AND (Col27 = 1 OR Col28 = 27586214)   AND Col2 =  @P0  ) x WHERE T_DbPerfTest.Col1 = x.Col1 AND T_DbPerfTest.Col29 IS NULL AND x.Col29 = 27586214 AND T_DbPerfTest.Col27 = 1',1
select @p1

exec sp_execute 1,240254
exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360
exec sp_execute 1,240254
exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360
exec sp_execute 1,240254
exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360
exec sp_execute 1,240254
exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360
exec sp_execute 1,240254
exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360
exec sp_execute 1,240254
exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360
exec sp_execute 1,240254
exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360
exec sp_execute 1,240254
exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360
exec sp_execute 1,240254
exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360
exec sp_execute 1,240254
exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360
exec sp_execute 1,240254
exec sp_execute 1,684796
exec sp_execute 1,684786
exec sp_execute 1,240102
exec sp_execute 1,240274
exec sp_execute 1,240303
exec sp_execute 1,240332
exec sp_execute 1,240244
exec sp_execute 1,685302
exec sp_execute 1,685331
exec sp_execute 1,685196
exec sp_execute 1,685389
exec sp_execute 1,685228
exec sp_execute 1,685360

Author

Chrriis commented on Dec 4, 2019

edited

@ulvii I looked at the code and figured that out :)

That being said, I disagree when you say that it is the only thing that differs. I simplified the test case and added logs of the bytes that are sent for a given execution of the statement. I see less bytes sent with JTDS although we should be under the same conditions in both cases: statement was prepared long time ago, there were the same number of executions, etc.

Of course it is possible that I made a mistake in my test case, so please do cross-check my findings!

The zip
MSvsJTDS2.zip
contains:

  • An Excel file showing the differences at the byte level for one statement execution (about 58 bytes vs 36 bytes).
  • The simplified test case. Note the system prints showing my section where I logged the bytes.
  • My modified MS IOBuffer class with system prints to log the bytes.
  • My modified JTDS SharedSocket class with system prints to log the bytes.

It seems that the JTDS prepared statement executions do not have the header (size 22). Maybe only the preparation packet needs it and adding it to executions creates problems?

Thanks a lot for your help!

Author

Chrriis commented on Dec 4, 2019

I think I succeeded modifying the code so that the sp_prepexec call is just a sp_prepare instead. That way we can compare the same scenario between MS and JTDS. Well, unless I made a mistake, total time has not changed: MS is still 3x slower...
So, if the above is correct (please confirm!), then it means the bad performance could be due to the way the connection is established (maybe a different setting?) or the version of the protocol. @ulvii What is your take?

I've done some profiling that may or may not be interesting for this case (I'm attaching it.)

Here's what I see.

It looks like the number of requests are roughly the same between the two drivers, yet the MS driver requests appear to take a much longer time.

The MS driver is spending all of it's time here

void SqlServerJdbcDriverSlowdownTest.main(String[]):52	1
void SqlServerJdbcDriverSlowdownTest.executePreparedStatements(Connection, PreparedStatement):102	1
int[] com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.executeBatch():2076	1
void com.microsoft.sqlserver.jdbc.SQLServerStatement.executeStatement(TDSCommand):223	1
void com.microsoft.sqlserver.jdbc.SQLServerStatement.executeCommand(TDSCommand):248	1
boolean com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(TDSCommand):2979	1
boolean com.microsoft.sqlserver.jdbc.TDSCommand.execute(TDSWriter, TDSReader):7194	1
boolean com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$PrepStmtBatchExecCmd.doExecute():2675	1
void com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.doExecutePreparedStatementBatch(SQLServerPreparedStatement$PrepStmtBatchExecCmd):2786	1
TDSReader com.microsoft.sqlserver.jdbc.TDSCommand.startResponse(boolean):7579	1
boolean com.microsoft.sqlserver.jdbc.TDSReader.readPacket():6418	1
int com.microsoft.sqlserver.jdbc.TDSChannel.read(byte[], int, int):2023	1
int java.net.Socket$SocketInputStream.read(byte[], int, int):68	1

On the flip side, the Jtds path looks as follows for where most of it's time is spent

void SqlServerJdbcDriverSlowdownTest.main(String[]):68	8
void SqlServerJdbcDriverSlowdownTest.executePreparedStatements(Connection, PreparedStatement):102	8
int[] net.sourceforge.jtds.jdbc.JtdsStatement.executeBatch():1051	8
SQLException net.sourceforge.jtds.jdbc.JtdsPreparedStatement.executeMSBatch(int, int, ArrayList):463	8
void net.sourceforge.jtds.jdbc.TdsCore.executeSQL(String, String, ParamInfo[], boolean, int, int, int, boolean):1086	8
void net.sourceforge.jtds.jdbc.TdsCore.wait(int):4127	8
int net.sourceforge.jtds.jdbc.ResponseStream.peek():99	8
int net.sourceforge.jtds.jdbc.ResponseStream.read():114	8
void net.sourceforge.jtds.jdbc.ResponseStream.getPacket():477	8
byte[] net.sourceforge.jtds.jdbc.SharedSocket.getNetPacket(SharedSocket$VirtualSocket, byte[]):731	8
byte[] net.sourceforge.jtds.jdbc.SharedSocket.readPacket(byte[]):850	8
void java.io.DataInputStream.readFully(byte[]):170	8
void java.io.DataInputStream.readFully(byte[], int, int):200	8
int java.net.Socket$SocketInputStream.read(byte[], int, int):68	8

This was using JTDs 1.3.1 and MS 7.4.1

I ran sql server locally in a docker container.

As far as I can tell, it looks like both are doing essentially the same thing. Some protocol or connection setting seems to be the likely culprit here, IMO.

Interestingly enough, in both profiling sessions I did (One with jtds first, one with it second, to make sure that DB caching wasn't messing with things), it looks like the first 2 batches for the MS driver ran faster than JTDs (~80ms). It was the subsequent requests that ended up taking ~1 second.

JTDS consistently spent around 160ms per request.

Is there some "expected batch size" or "look ahead" parameter going on that the MS driver isn't sending?
sql_server_performance.zip

@Chrriis
Given your request information and the TDS docs

https://docs.microsoft.com/en-us/openspecs/windows_protocols/ms-tds/b05b006b-3cbf-404b-bcaf-7ec584b54706

It looks to me (and I could be wrong) that the MS driver is setting the "SQLBatch" packet data section and JTDs is not.

Author

Chrriis commented on Dec 6, 2019

Thanks @cogman. I analyzed the bytes that were sent vs TDS spec and suspected they were the MARS section stuff, so thank you for the confirmation. I think JTDS uses an older version of the protocol that does not have those.

About profiling, I too found that time was spent reading, which is why I started analyzing the sent messages in the first place, but they seemed to be the same.

So I think you are right saying there is a protocol or connection setting, but I fail to find which could be causing this huge difference. Any help is welcome there! :)

ulvii

added this to Under Investigation in MSSQL JDBC

on Dec 6, 2019

Author

Chrriis commented on Dec 11, 2019

@ulvii I found the issue! The root cause is that the statement that is passed to the server is slightly different between MS and JTDS: the MS driver adds spaces at the end of the statement when replacing the ? parameters with @Px ones. As a quick test, you can simply add .trim() at the end of the SQLServerConnection.replaceParameterMarkers(xxx) method and MS becomes as fast as JTDS using my test cases.

Of course, the fix must be more subtle than this: the statement that is passed to the driver should be left untouched when replacing the parameters. What I mean is that

  • if I pass: <space><space>UPDATE FOO SET x=? WHERE y=?<space>
  • then I should get: <space><space>UPDATE FOO SET x=@P0 WHERE y=@P1<space>
  • and not: <space><space>UPDATE FOO SET x=@P0 WHERE y=@P1<space><space><space><space><space><space><space>

With that fix, the MS driver would do as is told (passing command as is) and for us it would become as fast as JTDS (at least for this case).

Please let us know what you think! :)

Author

Chrriis commented on Dec 11, 2019

The fix in SQLServerConnection.replaceParameterMarkers(xxx) is simply to:

  • Remove the last while loop that adds the spaces.
  • return new String(sqlDst, 0, dstBegin);

That way, the statement is untouched, spaces that were part of the original statement are preserved and no new spaces are added.

cogman commented on Dec 11, 2019

edited

TBH, this method is a fair bit more complex than needs be. (Looks like a C->Java translation)

Make this into a string builder and use strings/Integer.toString and this will be both more idiomatic and readable. The performance hit will be negligible, potentially non-existent due to JVM optimizations.

For example, "makeParameterName" could be simplified to "@P" + nParam

Also, weird that spaces have that big of an impact on performance from the server. I'd never have guessed that.

Same method, more idiomatic

    static String replaceParamMarkers(String sqlSrc, Parameter[] params, boolean isReturnValueSyntax) {
        if (params == null || params.length == 0)
            return sqlSrc;
        char[] chars = sqlSrc.toCharArray();
        StringBuilder results = new StringBuilder(sqlSrc.length() + (6 * params.length));
        int param = 0;
        for (char c : chars) {
            if (c == '?') {
                results.append("@P").append(param);
                if (!isReturnValueSyntax && params[param].isOutput()) {
                    results.append(" OUT");
                }
                ++param;
            }
            else {
                results.append(c);
            }
        }

        return results.toString();
    }

Contributor

ulvii commented on Dec 13, 2019

edited

Hi @Chrriis , @cogman ,
I tried your suggestions, there is some performance improvement(2 seconds), but in my environment the performance of two drivers is still not comparable for this test case.
Total time (ms): 7328 (MS)
Total time (ms): 1105 (JTDS)
I will continue testing.

Author

Chrriis commented on Dec 13, 2019

edited

Hi @ulvii,

I am not sure what you did, because on our systems, the problem and the fix are consistent.

Here are our results:

  • Original statement (batch, 3 parameters)

    • Without fix:
      Total time (ms): 8277 (MS)
      Total time (ms): 2062 (JTDS)
    • With fix:
      Total time (ms): 2049 (MS)
      Total time (ms): 2029 (JTDS)
  • Original statement with inlined 1st and 3rd parameters (batch)

    • Without fix:
      Total time (ms): 7551 (MS)
      Total time (ms): 1987 (JTDS)
    • With fix:
      Total time (ms): 1990 (MS)
      Total time (ms): 1954 (JTDS)
  • More basic but slower statement (batch, 2 parameters)

    • Without fix:
      Total time (ms): 25450 (MS)
      Total time (ms): 6914 (JTDS)
    • With fix:
      Total time (ms): 6728 (MS)
      Total time (ms): 6931 (JTDS)
  • Simpler test case (no batch, 1 parameter)

    • Without fix:
      Total time (ms): 5762 (MS)
      Total time (ms): 1672 (JTDS)
    • With fix:
      Total time (ms): 1717 (MS)
      Total time (ms): 1692 (JTDS)

The only change between both is that:

        while (dstBegin < sqlDst.length) {
            sqlDst[dstBegin++] = ' ';
        }
        return new String(sqlDst);

is replaced with:

        return new String(sqlDst, 0, dstBegin);

Contributor

ulvii commented on Dec 13, 2019

I downloaded your test case and updated the driver with your suggestion. I am still willing to create a PR if it resolves the issue for you. Would you implement @cogman's change and let me know if you are still seeing the performance improvement?

Author

Chrriis commented on Dec 13, 2019

Thanks @ulvii, I would greatly appreciate it if you could updated the driver with the changes I suggested. It does make a huge difference!

Of course, what would be great for the future is if SQL Server itself were fixed to treat statements with and without trailing spaces in the same manner. If you know anyone at Microsoft who can do something in the server itself, you would make the world a better place :)
Here are some posts which might be related:
https://stackoverflow.com/questions/56334818/sql-server-performance-slow-when-query-text-has-a-particular-number-of-character
https://stackoverflow.com/questions/12019589/last-4-whitespaces-of-sql-would-hurt-sql-server-performance

About the changes @cogman proposed, I would have to try them when time allows. That being said, I think the immediate need is a fix that is the least intrusive, and I think improving the code as suggested deserves its own bug report / PR to better evaluate if it is equivalent and does not breaks anything (for example, I am not sure how makeParamName(xx) currently works in detail).

@ulvii, @cogman, thanks a lot for your help!

cogman commented on Dec 14, 2019

edited

@Chrriis I've ran the test a few times with a few permutations of the driver changes (mine, yours, part of yours, part of mine). I didn't see any driver differences even though the string output at the end was the same.

UPDATE T_DbPerfTest SET Col29 = x.Col29 FROM (   SELECT Col1, LEAD(Col28) OVER (PARTITION BY Col5, Col2, Col4, Col3 ORDER BY Col28, Col1) AS Col29   FROM T_DbPerfTest   WHERE Col29 IS NULL   AND (Col27 = 1 OR Col28 = @P0)   AND Col2 = @P1 ) x WHERE T_DbPerfTest.Col1 = x.Col1 AND T_DbPerfTest.Col29 IS NULL AND x.Col29 = @P2 AND T_DbPerfTest.Col27 = 1

I even tried running against sql server 2017 vs 2019 just to see if it was something about the database version. I threw in print statements into the driver to make sure I wasn't somehow getting an older version of the driver.

I ran this change with 8.1.1 built on my box.

Edit: Just for fun, I also added a bit of logic to strip out repeated whitespace in the query. No difference.

Testing Prepared Statements...
Total time (ms): 3828 (JTDS)
"UPDATE T_DbPerfTest SET Col29 = x.Col29 FROM ( SELECT Col1, LEAD(Col28) OVER (PARTITION BY Col5, Col2, Col4, Col3 ORDER BY Col28, Col1) AS Col29 FROM T_DbPerfTest WHERE Col29 IS NULL AND (Col27 = 1 OR Col28 = @P0) AND Col2 = @P1 ) x WHERE T_DbPerfTest.Col1 = x.Col1 AND T_DbPerfTest.Col29 IS NULL AND x.Col29 = @P2 AND T_DbPerfTest.Col27 = 1"
Total time (ms): 19405 (MS)

Author

Chrriis commented on Dec 16, 2019

edited

@ulvii I looked at @cogman's code. I changed a few things, e.g. to not allocate an array of chars just to get the length and to take into account the OUT parameter length. I truly think that rewriting this method should be a different issue/PR focused on improving the code and which could have its own dedicated thread of comments (let's not highjack this one which is about a bug in performance).

By-the-way, I did not have the bug today but I restored the database backup and could reproduce. I probably had background processes altering statistics. It is important to restore the backup before measuring again.

So, I would be grateful if you could fix the issue by replacing:

        while (dstBegin < sqlDst.length) {
            sqlDst[dstBegin++] = ' ';
        }
        return new String(sqlDst);

with:

        return new String(sqlDst, 0, dstBegin);

I hope this can make it soon in a release so we can continue our performance investigations between JTDS and MS drivers.

@Chrriis Did you miss where I ran your code and did not see performance improvements?

Specifically, the statement that got pushed out was UPDATE T_DbPerfTest SET Col29 = x.Col29 FROM ( SELECT Col1, LEAD(Col28) OVER (PARTITION BY Col5, Col2, Col4, Col3 ORDER BY Col28, Col1) AS Col29 FROM T_DbPerfTest WHERE Col29 IS NULL AND (Col27 = 1 OR Col28 = @P0) AND Col2 = @P1 ) x WHERE T_DbPerfTest.Col1 = x.Col1 AND T_DbPerfTest.Col29 IS NULL AND x.Col29 = @P2 AND T_DbPerfTest.Col27 = 1

I didn't just test my code change. Neither change on 8.1.1 resulted in a difference in performance.

I can cook up a test docker compose to demonstrate if you like.

Author

Chrriis commented on Dec 16, 2019

edited

@cogman This bug is related to SQL Server caches of query plans, parameter sniffing, statistics computing, etc. It is known that having trailing spaces, sometimes magical number of them, confuse SQL Server and make it not reuse an optimal plan.
I spent too much time on this already. I gave a test case, I gave links to posts of some people with the same problem, I showed that the driver was adding useless spaces which can lead to this problem, and I gave metrics with and without these spaces.

Do you mean that you are not able to reproduce the issue? If so, this kind of issue is like concurrency issues: it is not because you do not see it that it does not exist. In any case, the statement does have useless spaces and it is known to cause problems.

Author

Chrriis commented on Dec 17, 2019

edited

@ulvii, @cogman, I have very interesting findings. I ported the whole thing to SQL Server Express 2012 (our earlier investigations were on SQL Server 2017). And these are the times we get (without fix):
Total time (ms): 969 (JTDS)
Total time (ms): 10252 (MS)

So, on that server, the performance penalty is 10 times!

But that is not all. If I apply the fix I suggested, the performance penalty remains. This might explain what @cogman is experiencing. So, I applied another difference I found between JTDS and MS JDBC: spaces around parameters. Depending on the test case, it does or does not help.
Total time (ms): 969 (JTDS)
Total time (ms): 985 (MS)

I was wondering why JTDS was adding these spaces, but maybe they (sometimes?) help parameter sniffing and query plan reuse in older versions of SQL Server, who knows. I would not urge to add the spaces around parameters like JTDS does though, this needs much more analysis.

So: the trailing spaces at the end of the statement are definitely a problem and this fix should be applied. But, removing them does not fix all of the performance penalties of MS driver compared to JTDS.

Here is the backup for SQL Express 2012:
MSvsJTDS_SQLExpress2012.zip

Author

Chrriis commented on Dec 17, 2019

edited

I found how to fix the remaining performance penaly found on SQL Server 2012: I changed the MS driver code (temporary hack) to do a prepare instead of a prepExec. Then it becomes as fast...

So, we can infer that:

  • Trailing spaces confuse query optimisation and should not be added by the MS driver.
  • Preparing the statement separately instead of calling prepexec yields better performance on some versions of SQL Server.

(of course, do check on your side if you come to the same conclusions).

Contributor

ulvii commented on Dec 19, 2019

Hi @Chrriis , @cogman ,
Thanks for the investigations, interesting results.
I created a #1215 for now, since we all agree that trailing spaces should be removed. I will get back to your investigations when time permits and perhaps get SQL Server team involved to figure out the root cause of the performance penalty.

Author

Chrriis commented on Dec 20, 2019

Thanks @ulvii, I will try the next official release that contains this first fix. Unfortunately, we need to support SQL Server 2012 so we will stick to JTDS in production for the time being.
That being said, if you need help with testing code changes or carry some analyses, do contact me.

About the PrepExec vs Prepare + Execute, JTDS has the notion of modes using the prepareSQL connection property. Here is its documentation:

prepareSQL (default - 3 for SQL Server, 1 for Sybase)
This parameter specifies the mechanism used for Prepared Statements.

Value Description
0 SQL is sent to the server each time without any preparation, literals are inserted in the SQL (slower)
1 Temporary stored procedures are created for each unique SQL statement and parameter combination (faster)
2 sp_executesql is used (fast)
3 sp_prepare and sp_cursorprepare are used in conjunction with sp_execute and sp_cursorexecute (faster, SQL Server only)

While I don't think the MS driver should have these modes, maybe you could add some modes at least to switch between PrepExec and Prepare + Execute.

Contributor

ulvii commented on Oct 6, 2020

edited

Hi @otbutz ,
Unfortunately, this improvement did not make it to the current semester, we will consider it in next semester.

Edit: we look into getting this done in the next production release before January 31st, will update you on progress.

Is this going to be released in 9.2.0 ?

Highly doubt it. The issue is open since Nov 2019 with a very clear diagnosis done by @Chrriis who posted unpatched vs patched benchmark results. And yet a slowdown of factor 3-4 compared to jtds doesn't seem to justify prioritizing this issue.

mikekuzak, ArturSch, kurtjmeyoung, vramirez122000, xafarr, and petersedlacek reacted with confused emoji All reactions

Contributor

peterbae commented on Jan 19, 2021

The issue is still pending prioritization, we will let you know if we have any progress on this issue in the future.

@lukaseder maybe a tweet to draw attention to this issue?

Sure, that'll be 250 EUR per tweet grin

That's actually cheaper than i thought smile

Anyone want to take a stab at a pull request that adds a mode in the driver configuration (and elsewhere) so that it will switch to prepare+exec instead of prepexec like the JTDS driver does?

Alternative for our use case is I guess to clone and build our own with Chrriis's hack

#1196 (comment)

Author

Chrriis commented on May 18, 2021

Anyone want to take a stab at a pull request that adds a mode in the driver configuration (and elsewhere) so that it will switch to prepare+exec instead of prepexec like the JTDS driver does?

It is not straightforward to implement, which is why I had hopes that the original developers would take a look at it.
Considering how serious this bug is and that there is no activity after a year and a half ago, my guess is that this driver is in maintenance mode. Perhaps the original developers have left.

Alternative for our use case is I guess to clone and build our own with Chrriis's hack

The hack is coupled with the test so that there is always a dummy call first. It cannot be turned into a proper feature.
Personally, we have decided to stick to jTDS and we also implemented a Postgres alternative.

we have decided to stick to jTDS and we also implemented a Postgres alternative.

Dito.

We can only hope that MS changes its prioritization strategy and finally pays more attention to the fundamental problems of its driver. But backlogged issues like this one and #1538 are red flags that we'll have to stick to jTDS for the foreseeable future.

lilgreenbird

moved this from Under Investigation to Backlog in MSSQL JDBC

on May 21, 2021

Amazing work @Chrriis. We are facing the exact same performance drop switching from jTDS to ms driver.
Unbelievable this still isn't fixed. Test cases proof enough I should say.

Subscribed to this issue just in case Microsoft wakes up.

Hi all,

This issue, along with others were considered when we do planning for the semester but it didn't make the cut. We will review the list again when we do planning for the next semester but please note we have very limited resources so can only work on those features/issues that are highest priority.

Since this project is open source, you are welcome to contribute and create a PR if you have a fix, that would help expedite the process.

Contributor

marschall commented on Jun 23, 2021

edited

Hi all,

This issue, along with others were considered when we do planning for the semester but it didn't make the cut. We will review the list again when we do planning for the next semester but please note we have very limited resources so can only work on those features/issues that are highest priority.

Since this project is open source, you are welcome to contribute and create a PR if you have a fix, that would help expedite the process.

Here I thought that SQL Server was a commercial product offered by Microsoft, a company worth more than 2,000,000,000,000 $, my bad. The next time somebody brings up whether we should chose SQL Server or an alternative I'll bring up that the JDBC driver is just an open source project with very limited resources.

Any updates? We are approaching the second birthday of this issue.

mikekuzak reacted with thumbs up emoji All reactions

David-Engel

changed the title Big performance penalty in prepared statements compared to JTDS

Performance difference in prepared statements compared to jTDS due to differing execution plan

on Oct 27, 2021

dospencer commented on Jan 22

I just encountered another performance issue with the MS JDBC driver. It takes about 39 minutes to insert 85K records into a MS SQL Server table using the MS SQL Server driver. If I use the Open Source JTDS driver then it takes only 39 seconds. The issue is only occurring when I have fields defined as BigDecimal in the application and that generates setBigDecimal for the prepared statement. If I change the data type from BigDecimal to Int, Float or Double, I do not get that performance issue.

Is setBigDecimal inherently slow performing and should be avoided with MS SQL Server driver? Why do I not experience the same issue with the Open source JTDS driver?

Member

tkyc commented on Jan 24

Hi @dospencer, we are currently in progress of investigating performance related problems in regards to this issue. However, we are preparing for an upcoming release and will try to address this issue after.

dospencer commented on Jan 24

Thank you @tkyc . Do you have a time for the upcoming release?

Member

tkyc commented on Jan 24

@dospencer We expect to have our release out sometime late January or early February

Member

tkyc commented on Feb 1

Hi @dospencer, can you create a separate github issue for your problem? Thanks

dospencer commented on Feb 3

@tkyc I created a separate issue as requested. #1749

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Assignees

No one assigned

Labels
None yet
Projects

MSSQL JDBC

Closed Issues
Milestone

11.1.0

13 participants

About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK