Re: Database related performance degradation after upgrading from Tomcat 9.0.33 to Tomcat 9.0.69

[Christopher Schultz]

Artur,

On 2/23/23 15:55, Artur Tomusiak - Hannon Hill wrote:

Thanks everyone for the information and advice. Thanks to you we were able
to track this down to a specific version of Tomcat and DBCP. Simply copying
tomcat-dbcp.jar file from Tomcat 9.0.38 to Tomcat 9.0.33 and running Tomcat
9.0.33 results in the slowness. This means that the issue was introduced in
DBCP 2.8.0-SNAPSHOT 6d232e5. Using the tomcat-dbcp.jar file from Tomcat
9.0.72 results in the same slowness as Tomcat 9.0.38, so that means that
the newest version of DBCP 2.10.0-SNAPSHOT f131286 has not fixed the
problem.

It does sound like https://issues.apache.org/jira/browse/DBCP-558 has
introduced the problem with latency. Based on the linked Pull Request
 and implementation of
com.mysql.jdbc.ConnectionImpl it looks like calling
`connection.isReadOnly()` results in an extra trip to the database. Based
on implementation of com.mysql.jdbc.ConnectionImpl, providing an extra
parameter in connection URL: `useLocalSessionState=true` fixes the
performance problem in Tomcat 9.0.69.

Without providing the extra `useLocalSessionState=true` parameter in
connection URL, copying tomcat-dbcp.jar file from Tomcat 9.0.33 to Tomcat
9.0.69 also fixes the database performance in Tomcat 9.0.69 and it does not
seem to be causing any problems at first sight, so we have found the
culprit and we have 2 potential workarounds:

- Use tomcat-dbcp.jar file from Tomcat 9.0.33 in Tomcat 9.0.69, or
- Append `useLocalSessionState=true` param to connection URL

A few follow up questions:

- Which of the two workarounds would be more recommended? Would there be
any problems with mismatching tomcat-dbcp.jar version or with using the
useLocalSessionState parameter?


I would strongly recommend using the request-parameter configuration. If 
you try to stick with that version of tomcat-dbcp forever just to get 
performance improvements, you may miss fixed bugs (including security 
bugs) in the future. You also have to remember to re-downgrade Tomcat 
every single time you upgrade it.



- Since the solution in the Pull Request seems to result in a
considerable performance hit, would that be considered an issue or
necessary evil? Should we expect such an issue to be fixed in the future or
do we just need to adjust and live with it?


You'd have to have this conversation with the commons-dbcp team, but I 
suspect they would say it is a "necessary evil".



- Out of curiosity, has anyone else here noticed such database
connection performance degradation between these versions of Tomcat
(essentially between 9.0.37 or earlier, and 9.0.38 or later)? Since DBCP
2.8.0 was released in 2020-09-21 and Tomcat 9.0.38 was released
in 2020-08-11, it's a bit strange that this issue was not reported
previously by anyone.


I use Tomcat 8.5 which likely had a similar evolution. But we typically 
do a of of work per connection-checkout and are not trying to perform 
37k checkouts in a short amount of time. So we haven't noticed any 
noticeable performance drop. Maybe our database has less latency than 
yours (we also run MariaDB at $work).


-chris


On Wed, Feb 22, 2023 at 12:43 PM Mark Thomas  wrote:


On 22/02/2023 04:58, Konstantin Kolinko wrote:

ср, 22 февр. 2023 г. в 01:31, Artur Tomusiak - Hannon Hill
:


After upgrading from Tomcat 9.0.33 to Tomcat 9.0.69,


Note that using a binary search (bisection) one could limit the version

range.

Relevant version information is:

9.0.71 - DBCP f131286  2.10.0-SNAPSHOT  2022-12-30
9.0.53 - DBCP 2abdb49  2.9.02021-08-03
9.0.42 - DBCP e24196a  2.9.0-SNAPSHOT   2021-01-15
9.0.38 - DBCP 6d232e5  2.8.0-SNAPSHOT   2020-08-11
9.0.30 - DBCP a363906  2.8.0-SNAPSHOT   2019-12-06



Alternatively, it is possible to reconfigure the pool to use Apache
Commons DBCP 2 and Apache Commons Pool 2 directly (instead of
package-renamed version used by Tomcat), and bisect their version
ranges.


Given Tomcat's tendency to update to specific commits rather than
releases, bisecting Tomcat versions is probably easier.

Does your database provide any form of debug logging? The additional
commands should be easy to spot in such a log.

Changes to autoCommit and readOnly handling in 9.0.38 could result in
additional database calls. See
https://issues.apache.org/jira/browse/DBCP-558

I don't see anything else obvious in the change history but a debug log
for the connection is likely to be the quickest way to see what is going
on.

Mark

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org






-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: Database related performance degradation after upgrading from Tomcat 9.0.33 to Tomcat 9.0.69

[Mark Thomas]

On 23/02/2023 20:55, Artur Tomusiak - Hannon Hill wrote:


A few follow up questions:

- Which of the two workarounds would be more recommended? Would there be
any problems with mismatching tomcat-dbcp.jar version or with using the
useLocalSessionState parameter?


It depends.

Given the nature of the tomcat-dbcp.jar, I don't foresee any 
compatibility issues using tomcat-dbcp.jar from any version of Tomcat 
9.0.x with any other version of Tomcat 9.0.x.


There is a maintenance issue in that updating Tomcat becomes a little 
more complicated.


You also need to be sure that the problem described in DBCP-558 isn't 
going to affect your application.


useLocalSessionState looks to be the simpler solution but you should be 
aware of the caveats described here:

https://forums.mysql.com/read.php?39,626495,626511

A third option is to use a different database connection pool. Although 
that carries the risks of the unknown. You are probably better off with 
a minimal change to fix the issue you see.



- Since the solution in the Pull Request seems to result in a
considerable performance hit, would that be considered an issue or
necessary evil? Should we expect such an issue to be fixed in the future or
do we just need to adjust and live with it?


I think the general expectation is that application servers are normally 
located close to the database they use and round-trip latency should be 
negligible compared to the time taken for the actual DB operations.


An enhancement/PR might be accepted to make the fix in DBCP-558 optional 
but that would be a decision for the Commons DBCP project.



- Out of curiosity, has anyone else here noticed such database
connection performance degradation between these versions of Tomcat
(essentially between 9.0.37 or earlier, and 9.0.38 or later)? Since DBCP
2.8.0 was released in 2020-09-21 and Tomcat 9.0.38 was released
in 2020-08-11, it's a bit strange that this issue was not reported
previously by anyone.


I don't recall seeing any such reports - either here or with DBCP.

Mark



Thank you,
Artur Tomusiak

On Wed, Feb 22, 2023 at 12:43 PM Mark Thomas  wrote:


On 22/02/2023 04:58, Konstantin Kolinko wrote:

ср, 22 февр. 2023 г. в 01:31, Artur Tomusiak - Hannon Hill
:


After upgrading from Tomcat 9.0.33 to Tomcat 9.0.69,


Note that using a binary search (bisection) one could limit the version

range.

Relevant version information is:

9.0.71 - DBCP f131286  2.10.0-SNAPSHOT  2022-12-30
9.0.53 - DBCP 2abdb49  2.9.02021-08-03
9.0.42 - DBCP e24196a  2.9.0-SNAPSHOT   2021-01-15
9.0.38 - DBCP 6d232e5  2.8.0-SNAPSHOT   2020-08-11
9.0.30 - DBCP a363906  2.8.0-SNAPSHOT   2019-12-06



Alternatively, it is possible to reconfigure the pool to use Apache
Commons DBCP 2 and Apache Commons Pool 2 directly (instead of
package-renamed version used by Tomcat), and bisect their version
ranges.


Given Tomcat's tendency to update to specific commits rather than
releases, bisecting Tomcat versions is probably easier.

Does your database provide any form of debug logging? The additional
commands should be easy to spot in such a log.

Changes to autoCommit and readOnly handling in 9.0.38 could result in
additional database calls. See
https://issues.apache.org/jira/browse/DBCP-558

I don't see anything else obvious in the change history but a debug log
for the connection is likely to be the quickest way to see what is going
on.

Mark

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org






-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: Database related performance degradation after upgrading from Tomcat 9.0.33 to Tomcat 9.0.69

[Artur Tomusiak - Hannon Hill]

Thanks everyone for the information and advice. Thanks to you we were able
to track this down to a specific version of Tomcat and DBCP. Simply copying
tomcat-dbcp.jar file from Tomcat 9.0.38 to Tomcat 9.0.33 and running Tomcat
9.0.33 results in the slowness. This means that the issue was introduced in
DBCP 2.8.0-SNAPSHOT 6d232e5. Using the tomcat-dbcp.jar file from Tomcat
9.0.72 results in the same slowness as Tomcat 9.0.38, so that means that
the newest version of DBCP 2.10.0-SNAPSHOT f131286 has not fixed the
problem.

It does sound like https://issues.apache.org/jira/browse/DBCP-558 has
introduced the problem with latency. Based on the linked Pull Request
 and implementation of
com.mysql.jdbc.ConnectionImpl it looks like calling
`connection.isReadOnly()` results in an extra trip to the database. Based
on implementation of com.mysql.jdbc.ConnectionImpl, providing an extra
parameter in connection URL: `useLocalSessionState=true` fixes the
performance problem in Tomcat 9.0.69.

Without providing the extra `useLocalSessionState=true` parameter in
connection URL, copying tomcat-dbcp.jar file from Tomcat 9.0.33 to Tomcat
9.0.69 also fixes the database performance in Tomcat 9.0.69 and it does not
seem to be causing any problems at first sight, so we have found the
culprit and we have 2 potential workarounds:

   - Use tomcat-dbcp.jar file from Tomcat 9.0.33 in Tomcat 9.0.69, or
   - Append `useLocalSessionState=true` param to connection URL

A few follow up questions:

   - Which of the two workarounds would be more recommended? Would there be
   any problems with mismatching tomcat-dbcp.jar version or with using the
   useLocalSessionState parameter?
   - Since the solution in the Pull Request seems to result in a
   considerable performance hit, would that be considered an issue or
   necessary evil? Should we expect such an issue to be fixed in the future or
   do we just need to adjust and live with it?
   - Out of curiosity, has anyone else here noticed such database
   connection performance degradation between these versions of Tomcat
   (essentially between 9.0.37 or earlier, and 9.0.38 or later)? Since DBCP
   2.8.0 was released in 2020-09-21 and Tomcat 9.0.38 was released
   in 2020-08-11, it's a bit strange that this issue was not reported
   previously by anyone.

Thank you,
Artur Tomusiak

On Wed, Feb 22, 2023 at 12:43 PM Mark Thomas  wrote:

> On 22/02/2023 04:58, Konstantin Kolinko wrote:
> > ср, 22 февр. 2023 г. в 01:31, Artur Tomusiak - Hannon Hill
> > :
> >>
> >> After upgrading from Tomcat 9.0.33 to Tomcat 9.0.69,
> >
> > Note that using a binary search (bisection) one could limit the version
> range.
>
> Relevant version information is:
>
> 9.0.71 - DBCP f131286  2.10.0-SNAPSHOT  2022-12-30
> 9.0.53 - DBCP 2abdb49  2.9.02021-08-03
> 9.0.42 - DBCP e24196a  2.9.0-SNAPSHOT   2021-01-15
> 9.0.38 - DBCP 6d232e5  2.8.0-SNAPSHOT   2020-08-11
> 9.0.30 - DBCP a363906  2.8.0-SNAPSHOT   2019-12-06
>
>
> > Alternatively, it is possible to reconfigure the pool to use Apache
> > Commons DBCP 2 and Apache Commons Pool 2 directly (instead of
> > package-renamed version used by Tomcat), and bisect their version
> > ranges.
>
> Given Tomcat's tendency to update to specific commits rather than
> releases, bisecting Tomcat versions is probably easier.
>
> Does your database provide any form of debug logging? The additional
> commands should be easy to spot in such a log.
>
> Changes to autoCommit and readOnly handling in 9.0.38 could result in
> additional database calls. See
> https://issues.apache.org/jira/browse/DBCP-558
>
> I don't see anything else obvious in the change history but a debug log
> for the connection is likely to be the quickest way to see what is going
> on.
>
> Mark
>
> -
> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
> For additional commands, e-mail: users-h...@tomcat.apache.org
>
>

Re: Database related performance degradation after upgrading from Tomcat 9.0.33 to Tomcat 9.0.69

[Mark Thomas]

On 22/02/2023 04:58, Konstantin Kolinko wrote:

ср, 22 февр. 2023 г. в 01:31, Artur Tomusiak - Hannon Hill
:


After upgrading from Tomcat 9.0.33 to Tomcat 9.0.69,


Note that using a binary search (bisection) one could limit the version range.


Relevant version information is:

9.0.71 - DBCP f131286  2.10.0-SNAPSHOT  2022-12-30
9.0.53 - DBCP 2abdb49  2.9.02021-08-03
9.0.42 - DBCP e24196a  2.9.0-SNAPSHOT   2021-01-15
9.0.38 - DBCP 6d232e5  2.8.0-SNAPSHOT   2020-08-11
9.0.30 - DBCP a363906  2.8.0-SNAPSHOT   2019-12-06



Alternatively, it is possible to reconfigure the pool to use Apache
Commons DBCP 2 and Apache Commons Pool 2 directly (instead of
package-renamed version used by Tomcat), and bisect their version
ranges.


Given Tomcat's tendency to update to specific commits rather than 
releases, bisecting Tomcat versions is probably easier.


Does your database provide any form of debug logging? The additional 
commands should be easy to spot in such a log.


Changes to autoCommit and readOnly handling in 9.0.38 could result in 
additional database calls. See 
https://issues.apache.org/jira/browse/DBCP-558


I don't see anything else obvious in the change history but a debug log 
for the connection is likely to be the quickest way to see what is going on.


Mark

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: Database related performance degradation after upgrading from Tomcat 9.0.33 to Tomcat 9.0.69

[Terence M. Bandoian]

On 2/21/2023 10:58 PM, Konstantin Kolinko wrote:

ср, 22 февр. 2023 г. в 01:31, Artur Tomusiak - Hannon Hill
:

After upgrading from Tomcat 9.0.33 to Tomcat 9.0.69,

Note that using a binary search (bisection) one could limit the version range.



If I understand the point you're making:

If testing for this problem was conducted with versions between 9.0.33 
and 9.0.69, the number of versions that could have caused the problem 
would be more limited which would simplify finding the cause.


-Terence Bandoian

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: Database related performance degradation after upgrading from Tomcat 9.0.33 to Tomcat 9.0.69

[Konstantin Kolinko]

ср, 22 февр. 2023 г. в 01:31, Artur Tomusiak - Hannon Hill
:
>
> After upgrading from Tomcat 9.0.33 to Tomcat 9.0.69,

Note that using a binary search (bisection) one could limit the version range.

Alternatively, it is possible to reconfigure the pool to use Apache
Commons DBCP 2 and Apache Commons Pool 2 directly (instead of
package-renamed version used by Tomcat), and bisect their version
ranges.

> [...]
>
> Here is our database connection configuration in context.xml file:
>
>name="jdbc/CascadeDS"
> auth="Container"
> type="javax.sql.DataSource"
> username="@{dbusername}"
> password="@{dbpassword}"
> driverClassName="com.mysql.jdbc.Driver"
>
> url="jdbc:mysql://@{dbhostport}/@{dbname}?useUnicode=truecharacterEncoding=UTF-8useSSL=false"
> maxTotal="250"
> maxIdle="10"

Only 10 idle connections are allowed?

So if you have 250 active connections, only 10 of them can be returned
to the pool, and the other 240 of them have to be closed and reopened.

How many active connections do you usually have? Are those numbers adequate?

> maxWaitMillis="3000"
> removeAbandonedOnBorrow="true"
> removeAbandonedOnMaintenance="true"
> removeAbandonedTimeout="300"
> logAbandoned="true"
> testOnBorrow="true"
> testOnCreate="true"

I do not see a "validationQuery", so you are relying on
connection.isValid() for those tests...

Why do you need a "testOnCreate" ?

>   />

Best regards,
Konstantin Kolinko

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

RE: Database related performance degradation after upgrading from Tomcat 9.0.33 to Tomcat 9.0.69

[John.E.Gregg]

Artur,

> -Original Message-
> From: Artur Tomusiak - Hannon Hill 
> Sent: Tuesday, February 21, 2023 4:31 PM
> To: users@tomcat.apache.org
> Subject: Database related performance degradation after upgrading from
> Tomcat 9.0.33 to Tomcat 9.0.69
> 
> After upgrading from Tomcat 9.0.33 to Tomcat 9.0.69, jobs in our application
> that execute lots of quick database queries end up being visibly slower - 16%
> slower on average in a typical setup where a database is on a local area
> network. Here is additional information we have
> confirmed:
> 
>- This is not specific to operating system (tested on Linux and MacOS)
>- This is not related to database vendors (tested on MySQL and Oracle)
>- This is not related to our software (identical code runs on different
>versions of Tomcat)
>- This is related to database connection latency as opposed to the speed
>of the database or the app - the longer the database latency, the more
>significant the slowdown is. When testing with a local database on the same
>machine, there is no performance hit between the two versions of Tomcat.
>When testing with a database on another network across the Internet (very
>high latency), the job running on Tomcat 9.0.69 is about 50% slower than
>Tomcat 9.0.33.
>- This might be coincidental, but based on the number of queries the job
>executes and the database connection latency, it appears as if each
>database query required 2 additional network trips to the database on
>Tomcat 9.0.69 as compared to Tomcat 9.0.33.
>   - For example, if a job executes about 37,000 queries, and the
>   database connection latency is about 0.15 ms, the job ends up being
> about
>   11 seconds slower on Tomcat 9.0.69 than Tomcat 9.0.33 based on our
> tests.
>   This seems to add up to 2 extra network trips per query because 37,000
>   queries * 0.15 ms/trip * 2 extra trips/query = 11,100 ms = 11.1 s.
>   - Another example is when testing with a db connection over the
>   Internet (25 ms latency) and a job that executes 1,231 queries, that 
> job is
>   more or less 60 seconds slower on Tomcat 9.0.69 than Tomcat
> 9.0.33 based on
>   our tests. Again, if we assumed that there are extra 2 trips to the
>   database per query, this adds up: 1,231 queries * 25 ms/trip * 2 extra
>   trips/query = 61,550 ms = 61.55 s.
> 
> We are suspecting that the slowness comes from around getting a database
> connection from the connection pool, though we spotted an occasional
> slowness around transaction committing as well.
> 
> Here is our database connection configuration in context.xml file:
> 
>name="jdbc/CascadeDS"
> auth="Container"
> type="javax.sql.DataSource"
> username="@{dbusername}"
> password="@{dbpassword}"
> driverClassName="com.mysql.jdbc.Driver"
> 
> url="jdbc:mysql://@{dbhostport}/@{dbname}?useUnicode=truechar
> acterEncoding=UTF-8useSSL=false"
> maxTotal="250"
> maxIdle="10"
> maxWaitMillis="3000"
> removeAbandonedOnBorrow="true"
> removeAbandonedOnMaintenance="true"
> removeAbandonedTimeout="300"
> logAbandoned="true"
> testOnBorrow="true"
> testOnCreate="true"
>   />
> 
> Is this a known issue? If not, is there any additional information I could
> provide to help troubleshoot or replicate the problem?
> 
> Thank you,
> Artur Tomusiak

I don't know anything about version differences between those versions of 
Tomcat, but I do know a thing or two about JDBC and network round trips.

Assuming the connections are open and in the pool, here are the possible round 
trips that I can think of:

1. Check the health of the connection upon checkout (testOnBorrow=true)
2. Disable autocommit
3. Prepare JDBC statement
4. Execute statement & read initial results
5. Read additional results
6. Commit/roll back transaction
7. Enable auto commit

Statement caching should help with #3.

4 and 5 are a little mushy.  I know with Oracle the first 10 rows by default 
come back in the response to the query.  If there are more results, they will 
require additional round trips unless you've increased the JDBC prefetch size.

7 might surprise you but typically pools store connections with autocommit 
enabled because that is the default state for a connection.  Some pools allow 
you to disable this functionality.  IOW, the autocommit state doesn't change 
unless you explicitly change it.

Also, you need to think about what's going on at the TCP level.  If there are 
enough packets in the response, the DB can't just send them all at once.  It 
might have to pause to wait for the ACKs from the client.  So even if the row 
count is low but the rows are wide, there might be extra pauses in there.  As 
long as the data was the same in your tests, I don't think this should be an 
issue, though.

Hope this helps.

Database related performance degradation after upgrading from Tomcat 9.0.33 to Tomcat 9.0.69

[Artur Tomusiak - Hannon Hill]

After upgrading from Tomcat 9.0.33 to Tomcat 9.0.69, jobs in our
application that execute lots of quick database queries end up being
visibly slower - 16% slower on average in a typical setup where a database
is on a local area network. Here is additional information we have
confirmed:

   - This is not specific to operating system (tested on Linux and MacOS)
   - This is not related to database vendors (tested on MySQL and Oracle)
   - This is not related to our software (identical code runs on different
   versions of Tomcat)
   - This is related to database connection latency as opposed to the speed
   of the database or the app - the longer the database latency, the more
   significant the slowdown is. When testing with a local database on the same
   machine, there is no performance hit between the two versions of Tomcat.
   When testing with a database on another network across the Internet (very
   high latency), the job running on Tomcat 9.0.69 is about 50% slower than
   Tomcat 9.0.33.
   - This might be coincidental, but based on the number of queries the job
   executes and the database connection latency, it appears as if each
   database query required 2 additional network trips to the database on
   Tomcat 9.0.69 as compared to Tomcat 9.0.33.
  - For example, if a job executes about 37,000 queries, and the
  database connection latency is about 0.15 ms, the job ends up being about
  11 seconds slower on Tomcat 9.0.69 than Tomcat 9.0.33 based on our tests.
  This seems to add up to 2 extra network trips per query because 37,000
  queries * 0.15 ms/trip * 2 extra trips/query = 11,100 ms = 11.1 s.
  - Another example is when testing with a db connection over the
  Internet (25 ms latency) and a job that executes 1,231 queries,
that job is
  more or less 60 seconds slower on Tomcat 9.0.69 than Tomcat
9.0.33 based on
  our tests. Again, if we assumed that there are extra 2 trips to the
  database per query, this adds up: 1,231 queries * 25 ms/trip * 2 extra
  trips/query = 61,550 ms = 61.55 s.

We are suspecting that the slowness comes from around getting a database
connection from the connection pool, though we spotted an occasional
slowness around transaction committing as well.

Here is our database connection configuration in context.xml file:

  

Is this a known issue? If not, is there any additional information I could
provide to help troubleshoot or replicate the problem?

Thank you,
Artur Tomusiak