Tuesday, March 15, 2011

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
Post a Comment