Dramatic SQL response time moving from jboss 3.0.6 to 3.2.5

[daffyduck]

Hi, (sorry for first posting this item in JBossWS forum!)

Moving a production application from jboss 3.0.6 to jboss 3.2.5, we found a critical issue; the SQL queries execution time were rising from about 160 ms to 1200 ms !

Database server is on a dif. machine and remains the same.
(MS-SLQ server 2000)

For this test we are using jboss's default server configuration for both versions.

We made à simple Benchmark application to test SQL request's performances. (not to be confused by diff. in application perf. prob.)


Here is the Datasource definition file used:

<?xml version="1.0" encoding="UTF-8"?>

<local-tx-datasource>
<jndi-name>jdbc/DATASOURCENAME</jndi-name> <connection-url>jdbc:microsoft:sqlserver://dbserver:####;ServerName=dbserver;PortNumber=####;DatabaseName=DBNAME;User=dbuser;Password=dbuserpwd;Selec
tMethod=cursor</connection-url> <driver-class>com.microsoft.jdbc.sqlserver.SQLServerDriver</driver-class>
<user-name>dbuser</user-name>
dbuserpwd
<prepared-statement-cache-size>50</prepared-statement-cache-size>
<min-pool-size>5</min-pool-size>
<max-pool-size>50</max-pool-size>
<idle-timeout-minutes>15</idle-timeout-minutes>
<track-statements>false</track-statements>
</local-tx-datasource>



Regards,

Damien.

[mbaptist]

Hi,
(I'm working with Damien, alias DaffyDuck)

I made some complementary tests.
Withe a simple ejb using a datasource on both JBoss 3.0.6 and 3.2.5, I found the following results (average time executing the same request 25 times)
jboss 3.0.6 ~70 ms
jboss 3.2.5 ~ 1000 ms !!!

I added some debug to my code and here are my results:
Executed CODE ms
JBOSS 3.0.6
BEGIN - PreparedStatement
END - PreparedStatement 0
BEGIN - executeQuery
END - executeQuery 0,031
BEGIN - WHILE (loop on resultset)
END - WHILE 0,037
BEGIN - RESULTSET.CLOSE
END - RESULTSET.CLOSE 0
BEGIN - PREPSTMT.CLOSE
END - PREPSTMT.CLOSE 0,001
BEGIN - RS.CLOSE
END - RS.CLOSE 0

JBOSS 3.2.5
BEGIN - PreparedStatement
END - PreparedStatement 0
BEGIN - executeQuery
END - executeQuery 0,307
BEGIN - WHILE (loop on resultset)
END - WHILE 0,722
BEGIN - RESULTSET.CLOSE
END - RESULTSET.CLOSE 0,033
BEGIN - PREPSTMT.CLOSE
END - PREPSTMT.CLOSE 0
BEGIN - RS.CLOSE
END - RS.CLOSE 0

As you can see, it's the executeQuery execution time that is x10 and the loop on the resultset (rs.next()) execution time that is x20.

Additional information: we do have the same kind of results with a different driver (jtds instead of M$).

Any sugestion or track to continue our investigations.

Br,

Marc.

[adrian.brock]

Get a profiler and show where it is spending the time.

1) The cpu used by each method
2) The "real time" for each method

The results will be different for each, (2) is more interesting,
it is closer to what your debug is showing.

JBoss doesn't do anything for rs.next() except pass it to the database.

For executeQuery(), the only thing it does is make sure the
reused connection has the correct configuration.
Unless you are playing with things like autocommit or readOnly it won't
do anything at this point either.

[mbaptist]

OK,

We are making the same tests using p6spy SQL Profiler v.0.3. By the way, is there any difference between v3.0.6 and 3.2.5 that could explain our problem?

REM: with both versions, I made the tests using the default config. and both are using the same database located on a remote server.


Br,

Marc

[mbaptist]

Hi,

We finally found the trick ;-)
It was due to a misconfiguration in the DataSource definition (pointing to a wrong server :-( ).

Sorry for that thread!!!

By the way, during our tests we discovered that the JTDS driver were 15 to 20 % faster that M$ one.

We do recomend the p5spy profiler. Easy to use and efficient.

Thanks Adrian for your help.

Best Regards,