Skip to main content

1300ms to 160ms, tune Spring/Hibernate on slow MySQL

I write this article to remember the different behaviour various JDBC connection pool displays when they work with slow JDBC connection(to MySQL database, in this case). It starts with a typical Java application on Spring, Hibernate, Jetty, ApacheCXF and MySQL like following code.

Version 1: without correct pooling

//... service code
@Transactional(isolation=Isolation.READ_COMMITTED)
public void foo() {
//... do something with database
}

//... connection pool configuration
...
class = "com.mysql.jdbc.jdbc2.optional.MysqlConnectionPoolDataSource";
url = "jdbc:mysql://mysql.far-far-away.com/mysystem";
user = ...

//... transaction management configuration in spring
...
<tx:annotation-driven transaction-manager="transactionManager"
order="100" />
<bean id="transactionManager"
class="org.springframework.orm.hibernate3.HibernateTransactionManager">
<property name="sessionFactory" ref="mySessionFactory" />
</bean>
<bean id="mySessionFactory"
class="org.springframework.orm.hibernate3.annotation.AnnotationSessionFactoryBean">
<property name="hibernateProperties">
   <props>
       <prop key="hibernate.connection.autocommit">false</prop>
       <prop key="hibernate.connection.isolation">2</prop>
   </props>
</property>
...
</bean>
...
The reason I believe the TCP connection to mysql.farfaraway.com is slow, is that most database query from select 1 to super complicated query with X joins all returned in 70ms. While 70ms is pretty slow, comparing to my local mysql which is less than 5ms.

mysql> select 1;
+---+
| 1 |
+---+
| 1 |
+---+
1 row in set (0.07 sec)
With some AOP setup I was able to manage to print out the delay around foo() call with and without transaction management layer. Surprisingly, the version above took 1300ms to execute with transaction management, and 200ms without it no matter if it's the first call or repeated call. Taking a close look at each step, the longest step is that it took 800ms to establish new JDBC connection. Obviously, connection pooling isn't working. JDBC connection is supposed to be already allocated in most cases.

2011-03-29 16:13:44,682 [DEBUG] servlet.CallTracingFilter/22406408@qtp-31601333-20 - /v1/version/repository
...
2011-03-29 16:13:44,760 [DEBUG] mortbay.log/22406408@qtp-31601333-20 - /v1/version/repository - loaded interface java.sql.Savepoint
2011-03-29 16:13:44,760 [DEBUG] mortbay.log/22406408@qtp-31601333-20 - /v1/version/repository - loaded interface java.sql.Savepoint from null
2011-03-29 16:13:44,762 [DEBUG] jdbc.ConnectionManager/22406408@qtp-31601333-20 - /v1/version/repository - opening JDBC connection
2011-03-29 16:13:45,537 [DEBUG] datasource.DataSourceUtils/22406408@qtp-31601333-20 - /v1/version/repository - Setting JDBC Connection [com.mysql.jdbc.JDBC4Connection@11e1813] rea
d-only
2011-03-29 16:13:45,537 [DEBUG] impl.SessionImpl/22406408@qtp-31601333-20 - /v1/version/repository - setting flush mode to: MANUAL
2011-03-29 16:13:45,540 [DEBUG] transaction.JDBCTransaction/22406408@qtp-31601333-20 - /v1/version/repository - begin
2011-03-29 16:13:45,540 [DEBUG] transaction.JDBCTransaction/22406408@qtp-31601333-20 - /v1/version/repository - current autocommit status: true
2011-03-29 16:13:45,540 [DEBUG] transaction.JDBCTransaction/22406408@qtp-31601333-20 - /v1/version/repository - disabling autocommit
2011-03-29 16:13:45,609 [DEBUG] jdbc.JDBCContext/22406408@qtp-31601333-20 - /v1/version/repository - after transaction begin
...
2011-03-29 16:19:05,634 [INFO] MyService/32623642@qtp-31601333-21 - /v1/version/set/nkX1vZDH8rsA3NPeAkcmrA - [RUPcufrQ] Invocation of foo succeeds and returns null after 246ms
2011-03-29 16:19:05,634 [DEBUG] interceptor.TransactionInterceptor/32623642@qtp-31601333-21 - /v1/version/set/nkX1vZDH8rsA3NPeAkcmrA - Completing transaction for [MyService.foo]
...
2011-03-29 16:19:05,804 [INFO] servlet.CallTracingFilter/32623642@qtp-31601333-21 - /v1/version/set/nkX1vZDH8rsA3NPeAkcmrA - [3plLQVoH] Http call to /v1/version/set/nkX1vZDH8rsA3NPeAkcmrA succeeded after 1313ms

Version 2: commons-dbcp

MysqlConnectionPoolDataSource is not very well documented. There isn't official manual, source code isn't fully documented, and the class literally has hundreds of properties with zero Javadoc. Instead of digging into that, I went with something I'm familiar with, commons-dbcp. With configuration below, service should start up with a pre-allocated JDBC pool and each call should not require to establish new connection in most cases.

//... connection pool configuration
...
class = "org.apache.commons.dbcp.BasicDataSource";
url = "jdbc:mysql://mysql.far-far-away.com/mysystem";
driverClassName = "com.mysql.jdbc.Driver";
initialSize = 2;
minIdle = 0;
maxActive = 10;
minEvictableIdleTimeMillis = 120000;
username = ...

Now it takes 800ms with transaction management and 70ms without it. 70ms without transaction management is pretty much minimal since "select 1" takes 70ms. What an improvement!

However it still takes 70ms to pull out JDBC connection, 140ms to set isolation level and 70ms to disable auto commit. Obviously, blocking call on TCP connection is make once to get existing connection out from pool, twice when setting isolation level and once to disable auto commit.

2011-03-29 17:36:48,487 [INFO] servlet.CallTracingFilter/21266875@qtp-31601333-20 - /v1/version/repository - [HTLIDcFl] Http call to /v1/version/repository started with request: /v1/version/repository
...
2011-03-29 17:36:48,489 [DEBUG] hibernate3.HibernateTransactionManager/21266875@qtp-31601333-20 - /v1/version/repository - Preparing JDBC Connection of Hibernate Session [org.hibernate.impl.SessionImpl@15d533d]
2011-03-29 17:36:48,489 [DEBUG] jdbc.ConnectionManager/21266875@qtp-31601333-20 - /v1/version/repository - opening JDBC connection
2011-03-29 17:36:48,558 [DEBUG] datasource.DataSourceUtils/21266875@qtp-31601333-20 - /v1/version/repository - Setting JDBC Connection [jdbc:mysql://mysql.farfaraway.com/mysystem, UserName=..., MySQL-AB JDBC Driver] read-only
2011-03-29 17:36:48,626 [DEBUG] datasource.DataSourceUtils/21266875@qtp-31601333-20 - /v1/version/repository - Changing isolation level of JDBC Connection [jdbc:mysql://mysql.farfaraway.com/mysystem, UserName=..., MySQL-AB JDBC Driver] to 2
2011-03-29 17:36:48,764 [DEBUG] impl.SessionImpl/21266875@qtp-31601333-20 - /v1/version/repository - setting flush mode to: MANUAL
2011-03-29 17:36:48,764 [DEBUG] transaction.JDBCTransaction/21266875@qtp-31601333-20 - /v1/version/repository - begin
2011-03-29 17:36:48,764 [DEBUG] transaction.JDBCTransaction/21266875@qtp-31601333-20 - /v1/version/repository - current autocommit status: true
2011-03-29 17:36:48,764 [DEBUG] transaction.JDBCTransaction/21266875@qtp-31601333-20 - /v1/version/repository - disabling autocommit
2011-03-29 17:36:48,832 [DEBUG] jdbc.JDBCContext/21266875@qtp-31601333-20 - /v1/version/repository - after transaction begin
...
2011-03-29 17:36:48,975 [INFO] MyService/21266875@qtp-31601333-20 - /v1/version/repository - [Z9f815OF] Invocation of foo succeeds and returns null after 73ms
...
2011-03-29 17:36:49,323 [INFO] servlet.CallTracingFilter/21266875@qtp-31601333-20 - /v1/version/repository - [HTLIDcFl] Http call to /v1/version/repository succeeded after 836ms

Version 3: Set default autocommit and isolation

Default auto commit and transaction isolation can be defined in commons-dbcp, however Spring still always sets isolation for each transaction. This actually makes sense since @Transaction annotation allows operation to override isolation. To be sure isolation is set correctly each time, Spring has to set it each time.

As the writer of service code, I personally know that my code always use READ_COMMITTED isolation level. Based on such fact, I could remove isolation from all @Transactional annotation, rely on default isolation and set default isolation in commons-dbcp. This works fine unless there is one single operation that requires isolation level different from default one.

//... service code
@Transactional(isolation=Isolation.READ_COMMITTED)
public void foo() {
//... do something with database
}
//... connection pool configuration
...
class = "org.apache.commons.dbcp.BasicDataSource";
defaultAutoCommit = false;
defaultTransactionIsolation = 2;


With changes above, time consumption is down to 600ms. Auto commit and isolation setting is gone as expected. The last piece is the 70ms connection pulling time. There also is a 70ms delay in Hibernate JDBCContext/after transaction begin, which I couldn't explain through out this article.

2011-03-29 18:07:35,887 [DEBUG] hibernate3.HibernateTransactionManager/4540490@qtp-14707008-20 -/v1/version/repository - Preparing JDBC Connection of Hibernate Session [org.hiber
nate.impl.SessionImpl@ee5a06]
2011-03-29 18:07:35,887 [DEBUG] jdbc.ConnectionManager/4540490@qtp-14707008-20 - /v1/version/repository - opening JDBC connection
2011-03-29 18:07:36,096 [DEBUG] datasource.DataSourceUtils/4540490@qtp-14707008-20 - /v1/version/repository - Setting JDBC Connection [jdbc:mysql://mysql.farfaraway.com/mysystem, UserName=..., MySQL-AB JDBC Driver] read-only
2011-03-29 18:07:36,096 [DEBUG] impl.SessionImpl/4540490@qtp-14707008-20 - /v1/version/repository - setting flush mode to: MANUAL
2011-03-29 18:07:36,096 [DEBUG] transaction.JDBCTransaction/4540490@qtp-14707008-20 - /v1/version/repository - begin
2011-03-29 18:07:36,096 [DEBUG] transaction.JDBCTransaction/4540490@qtp-14707008-20 - /v1/version/repository - current autocommit status: false
2011-03-29 18:07:36,096 [DEBUG] jdbc.JDBCContext/4540490@qtp-14707008-20 - /v1/version/repository - after transaction begin2011-03-29 18:07:36,164 [DEBUG] hibernate3.HibernateTransactionManager/4540490@qtp-14707008-20 - /v1/version/repository - Exposing Hibernate transaction as JDBC transaction ...

Version 4: C3P0

To further explore, I switched to C3P0 just to see what can happen. Unfortunately C3P0 can't set default auto commit from configuration, I had to write a customizer to set it.
//... connection pool configuration
...
class = "org.apache.commons.dbcp.BasicDataSource";
connectionCustomizerClassName = "myapp.JdbcConnectionInitializer";
minPoolSize = 2;
maxPoolSize = 10;
maxIdleTime = 120;
...
//... Customizer
public class JdbcConnectionInitializer
extends AbstractConnectionCustomizer
{
@Override
public void onAcquire( Connection c, String id )
    throws SQLException
{
    c.setAutoCommit( false );
}
}


The total time is reduced to 300ms. The two delays in dbcp, connection pulling and strange delay in hibernate JDBCContext are both gone.

This is still not finished yet. Since my MYSQL server didn't completely turn auto commit off, the auto commit is actually set on and off during transaction commit phase. Once server is configured correctly, the total execution time reached to 160ms, which is an ideal state where each operation call only involves one single blocking TCP communication.

Summary

Communication delayDurationHow to avoidConclusion
Open JDBC connectionVery longUse connection pool like commons-dbcp or C3P0 to pre-allocate connectionFor long running service, it's almost always true that connection pool should be considered
Borrow connection from pool1 tcp call in commons-dbcpUse C3P0 insteadDon't know how to avoid in commons-dbcp
Setting transaction isolation2 tcp callsIf possible, always use default isolation level for application in SpringIf application does require more than 1 isolation levels in system, this delay can not be avoided
Setting auto commit before transaction starts1 tcp callSet default auto commit, which requires customizer class in C3P0Not a problem is server turns it off
Strange delay in Hibernate JDBCContext2 tcp callOnly found in commons-dbcp. Use C3P0 insteadCan't explain yet
Turning auto commit on and off to commit transaction1 or 2 tcp callsConfigure database server to disable auto commitMay not be always feasible if you don't have control of database server

Comments

life_is_beautiful said…
Hi,

You mentioned that c3p0 doesn't allow setting of autoCommit through configurations. As a result of which you had written a customizer class :

public class JdbcConnectionInitializer
extends AbstractConnectionCustomizer ...

Could you please elaborate , on, how to make the hibernate persistence unit read this customized class ?

Thanks
Binita
11:39 PM
Jiaqi Guo said…
com.mchange.v2.c3p0.ComboPooledDataSource class has a property named connectionCustomizerClassName. I set it to class name of my own JdbcConnectionInitializer.
4:57 PM
Post a Comment

Popular posts from this blog

Spring, Angular and other reasons I like and hate Bazel at the same time

For several weeks I've been trying to put together an Angular application served Java Spring MVC web server in Bazel. I've seen the Java, Angular combination works well in Google, and given the popularity of Java, I want get it to work with open source. How hard can it be to run arguably the best JS framework on a server in probably the most popular server-side language with  the mono-repo of planet-scale ? The rest of this post walks through the headaches and nightmares I had to get things to work but if you are just here to look for a working example, github/jiaqi/angular-on-java is all you need. https://github.com/jiaqi/angular-on-java Java web application with Appengine rule Surprisingly there isn't an official way of building Java web application in Bazel, the closest thing is the Appengine rule  and Spring MVC seems to work well with it. 3 Java classes, a JSP and an appengine.xml was all I need. At this point, the server starts well but I got "No
Post a Comment
Read more

Customize IdGenerator in JPA, gap between Hibernate and JPA annotations

JPA annotation is like a subset of Hibernate annotation, this means people will find something available in Hibernate missing in JPA. One of the important missing features in JPA is customized ID generator. JPA doesn't provide an approach for developer to plug in their own IdGenerator. For example, if you want the primary key of a table to be BigInteger coming from sequence, JPA will be out of solution. Assume you don't mind the mixture of Hibernate and JPA Annotation and your JPA provider is Hibernate, which is mostly the case, a solution before JPA starts introducing new Annotation is, to replace JPA @SequenceGenerator with Hibernate @GenericGenerator. Now, let the code talk. /** * Ordinary JPA sequence. * If the Long is changed into BigInteger, * there will be runtime error complaining about the type of primary key */ @Id @Column(name = "id", precision = 12) @GeneratedValue(strategy = GenerationType.SEQUENCE, generator = "XyzIdGenerator") @SequenceGe
4 comments
Read more

A dozen things to know about AWS Simple Workflow in Eclipse and Maven

Amazon AWS Simple Workflow AWS Simple Workflow(SWF) from Amazon is a unique workflow solution comparing to traditional workflow products such as JBPM and OSWorkflow. SWF is extremely scalable and engineer friendly(in that flow is defined with Java code) while it comes with limitations and lots of gotchas. Always use Flow Framework The very first thing to know is, it's almost impossible to build a SWF application correctly without Flow Framework . Even though the low level SWF RESTful service API is public and available in SDK, for most workflow with parallelism, timer or notification, consider all possibilities of how each event can interlace with another, it's beyond manageable to write correct code with low-level API to cover all use cases. For this matter SWF is quite unique comparing to other thin-client AWS technologies. The SWF flow framework heavily depends on AspectJ for various purposes. If you are not familiar with AspectJ in Eclipse and Maven, this article
Post a Comment
Read more