Thursday, September 08, 2011

Spring transaction timeout doesn't work??

I would like to cancel a transaction if it last too long, for example if a transaction has kept processing 2 minutes(expected 30 seconds), it will holds much resource and blocks other transactions(hurt the scalability), it is a reasonable choice to stop it permanently.
The solution looks like very simple, spring supports set transaction timeout when declare a transaction advice(in AOP style), and the timeout setting will ultimately propagated to underlying hibernate runtime which implements timeout by java.sql.Statement.setQueryTimeout()(ok, it isn't transaction timeout, but anyway setQueryTimeout can solve my problem).
Now, let's try this solution.

  • spring 2.5.6
  • hibernate 3.3.1
  • c3p0 0.9.1.2
  • jdk 1.6.0_12
First we implement a TicketService, notice that the class name must match the AOP pointcut definition.

public class DefaultTicketService implements TicketService{
    public void sell() {
        // checking and insert some records to underlying database
        ....
        DAO.execute("update merchant set statue=2 where merchant_id=111");
        // sleep to reach the transaction deadline
        try {Thread.sleep(15 * 1000);} catch(Exception e){}
    }
}
Below is the spring transaction defintion:

<bean id="transactionManager" class="org.springframework.orm.jpa.JpaTransactionManager">
    <property name="entityManagerFactory" ref="entityManagerFactory" />
    <property name="dataSource" ref="dataSource" />
bean>

<tx:advice id="defaultTxAdvice" transaction-manager="transactionManager">
    <tx:attributes>
        
        <tx:method name="get*" read-only="true" />
        
        <tx:method name="*" timeout="10" rollback-for="ApplicationException" />
    tx:attributes>
tx:advice
To verify if my timeout configuration has enabled by spring, I amended the source code of org.springframework.orm.jpa.JpaTransactionManager to output more debug information.

protected void doBegin(Object transaction, TransactionDefinition definition) {
    ... ...        
    // Register transaction timeout.
    int timeout = determineTimeout(definition);
    if (timeout != TransactionDefinition.TIMEOUT_DEFAULT) {
        if (logger.isDebugEnabled()) {
            logger.debug("****setTimeoutinSeconds(" + timeout
                    + " seconds) to EntityManager(" + txObject.getEntityManagerHolder()
                    + "), the transaction begin time:"
                    + new Date(System.currentTimeMillis()));
        }
        txObject.getEntityManagerHolder().setTimeoutInSeconds(timeout);
    }
    ... ... }
protected void doCommit(DefaultTransactionStatus status) {
    JpaTransactionObject txObject = (JpaTransactionObject) status.getTransaction();
    if (status.isDebug()) {
        logger.debug("Committing JPA transaction on EntityManager ["
                + txObject.getEntityManagerHolder().getEntityManager() + "]");
    }
    try {
        if (status.isDebug()) {
            logger.debug("The deadline of entityManager("
                    + txObject.getEntityManagerHolder().getEntityManager() + "):"
                    + txObject.getEntityManagerHolder().getDeadline() + ", and current time:"
                    + new Date(System.currentTimeMillis()));
        }
        EntityTransaction tx = txObject.getEntityManagerHolder().getEntityManager()
                .getTransaction();
        tx.commit();
    ... ...
}
Then I implemented a servlet to receive HTTP request and delete it to TicketService, and deploy it to tomcat6.

Before calling the ticket servcie by HTTP from a client, I have to emulate the situation of transction timeout, it is simple, open Oracle SQL Developer, connect to the same database, and execute a sql to lock the given row in table merchant(select * from merchant where merchant_id=111 for update).

Ok, it is time to run test....below is the debug output:

[JpaTransactionManager] Opened new EntityManager [org.hibernate.ejb.EntityManagerImpl@350225] for JPA transaction[JpaTransactionManager] ****[Begin]timeout:10 seconds,The deadline of entityManager(org.hibernate.ejb.EntityManagerImpl@350225):null, and current time:Tue Sep 06 15:05:42 CST 2011
[JpaTransactionManager] Exposing JPA transaction as JDBC transaction [SimpleConnectionHandle: com.mchange.v2.c3p0.impl.NewProxyConnection@1eb41d6]
[JpaTransactionManager] Found thread-bound EntityManager [org.hibernate.ejb.EntityManagerImpl@350225] for JPA transaction... ...
[JpaTransactionManager] Initiating transaction commit[JpaTransactionManager] Committing JPA transaction on EntityManager [org.hibernate.ejb.EntityManagerImpl@350225]
[JpaTransactionManager] ****[Commit]The deadline of entityManager(org.hibernate.ejb.EntityManagerImpl@350225):Tue Sep 06 15:05:52 CST 2011, and current time:Tue Sep 06 15:05:58 CST 2011
[JpaTransactionManager] Closing JPA EntityManager [org.hibernate.ejb.EntityManagerImpl@350225] after transaction[EntityManagerFactoryUtils] Closing JPA EntityManager
The test result is transaction will be blocked for ever if I don't commit/rollbak from Oracle SQL Developer. If I commit/rollback the transaction in Oracle SQL Developer, the transaction in spring will got committed.
?? Spring transaction timeout setting doesn't work??
After research some on internet, I found a interesting thread in Spring community  JpaTransactionManager does not support transaction timeouts.I overriden the implementaion of HibernateJpaDialect,


@Override
public Object beginTransaction(final EntityManager entityManager,
        final TransactionDefinition definition) throws SQLException {
    if (definition.getTimeout() != TransactionDefinition.TIMEOUT_DEFAULT) {
        getSession(entityManager).getTransaction().setTimeout(definition.getTimeout());
        if (logger.isDebugEnabled())
            logger.debug("****config hibernate transaction timeout:" + definition.getTimeout());
    }

    return super.beginTransaction(entityManager, definition);
}
and the spring configuration:

<bean id="entityManagerFactory"
    class="org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean">
    <property name="persistenceUnitName" value="lottery_te" />
    <property name="dataSource" ref="dataSource" />
    <property name="jpaVendorAdapter">
        <bean class="org.springframework.orm.jpa.vendor.HibernateJpaVendorAdapter" />
    property>
    
bean>
Now the test result is more stranger!! If I committed in oracle when past the set number of timeout seconds, spring will get a exception:

org.springframework.orm.hibernate3.HibernateSystemException: transaction timeout expired; nested exception is org.hibernate.TransactionException: transaction timeout expired
at org.springframework.orm.hibernate3.SessionFactoryUtils.convertHibernateAccessException(SessionFactoryUtils.java:679)
at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:102)
at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:471)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:754)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:723)
at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:393)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:120)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:89)
:(, I have been wait so long time, and finally got a timeout expired exception, what is the logic????  This exception should be thrown out once after the number of timeout seconds past.

Now that hibernate support transactin timeout by Statement.setQueryTimeout(), maybe I can call setQueryTimeout() directly. Oops! Spring/hibernate/C3p0 have wrapped the underlying implementation layer and layer, how can I see this method???

Try other approach! After checking the document of oracle jdbc, yes, oracle jdbc driver supports a connection properties "Oracle.jdbc.ReadTimeout" which is actually a socket read timeout. I can use this properties to cancel/stop a timeout transaction.

Test it first, I wrote a simple test class to verify my understanding.

public class JdbcQueryTimeoutTest {
private static Log logger = LogFactory.getLog(JdbcQueryTimeoutTest.class);
private static int timeout = 5; // seconds
public static Connection getConnection() throws Exception {
    ComboPooledDataSource cpds = new ComboPooledDataSource();
    cpds.setDriverClass("oracle.jdbc.driver.OracleDriver"); // loads the
                                                            // jdbc driver
    cpds.setJdbcUrl("jdbc:oracle:thin:@192.168.2.9:1521/ORCL");
    cpds.setUser("ramonal");
    cpds.setPassword("ramonal");
    cpds.setConnectionCustomizerClassName("com.mpos.lottery.te.common.dao.OracleConnectionCustomizer");

    // NOTE: once you decide to use cpds.setProperties() to set some
    // connection properties, all properties must be set, including
    // user/password(although you have set them by separated API, such as
    // cpds.setUser, cpds.setPassword), otherwise a exception
    // "java.sql.SQLException: 调用中无效的参数" will be thrown out.
    Properties prop = new Properties();
    prop.setProperty("oracle.jdbc.ReadTimeout", (timeout * 1000) + "");
    prop.setProperty("user", "ramonal");
    prop.setProperty("password", "ramonal");
    cpds.setProperties(prop);

    // the settings below are optional -- c3p0 can work with defaults
    cpds.setMinPoolSize(1);
    cpds.setAcquireIncrement(1);
    cpds.setInitialPoolSize(1);
    cpds.setMaxPoolSize(1);

    logger.debug("start to checkout connection from pool!");
    return cpds.getConnection();
}
public static void main(String args[]) throws Exception {
    Timer timer = null;
    Connection conn = null;
    try {
        // try C3p0
        conn = getConnection();

        conn.setAutoCommit(false);
        Statement stat = conn.createStatement();
        // setQueryTimeout can define the timeout for per statements, it is
        // more fine-grained then the gloabl connection
        // setting(oracle.jdbc.ReadTimeout), but below constraints deny this
        // solution:
        // 1. When adopt spring(2.5.6)+hibernate(3.1.3), the transaction
        // timeout defintion will be propagated to underlying hibernate
        // runtime, which will finally use setQueryTimeout to implement it,
        // but by testing this solution multiple times, it demonstrate that
        // it doesn't work, and the test result is really strange, the
        // transaction won't rollback when past the set number of timeout
        // seconds, and a SQLException(transaction has expired) will be
        // thrown out if finnaly the long transaction got to commit.
        // 2. We can't cal setQueryTimeout in program, as the transaction
        // mechanism has been wrapped by hibernate/spring, you can't see the
        // API from code.
        // stat.setQueryTimeout(timeout);

        logger.debug("start to execute statement!");
        stat.execute("update merchant set status=2 where merchant_id=111");
        logger.debug("get ready to commit!");
        conn.commit();
        logger.debug("commit successfully!");
    } catch (Exception e) {
        logger.debug("conn.isClose():" + conn.isClosed());
        if (conn != null && !conn.isClosed()) {
            conn.rollback();
        }
        logger.error(e.getMessage(), e);
    } finally {
        if (conn != null && !conn.isClosed())
            conn.close();
        if (timer != null)
            timer.cancel();
    }
}

Now I can get a socket timeout exception, and the database connection will be physically closed, the transaction will be rollback anyway. This solution can solve my problem, even though a read timeout, it is actually almost same with setQueryTimeout(), as only when jdbc driver issues a database request(statement),
a socket read timeout maybe thrown out. The difference is by setQueryTimeout() it won't affect commit() and rollback, only statements.

What will happen if read timeout when commit?? Will client got exception, but the transaction is committed to database?? Let's consider it later.

Ok, refactor my webapp with 'Oracle.jdbc.ReadTimeout'. It is also very simple, only need to amend the configuration of C3p0(no need spring transaction timeout setting).

   <bean id="dataSource" class="com.mchange.v2.c3p0.ComboPooledDataSource"
    destroy-method="close">
    <property name="driverClass" value="${jdbc.driver}" />
    <property name="jdbcUrl" value="${jdbc.url}" />
    <property name="minPoolSize" value="30" />
    <property name="maxPoolSize" value="100" />
    <property name="initialPoolSize" value="30" />
    <property name="maxStatements" value="0" />
    <property name="maxStatementsPerConnection" value="0" />
    <property name="checkoutTimeout" value="60000" />
    <property name="numHelperThreads" value="10" />
    <property name="debugUnreturnedConnectionStackTraces" value="true" />
    <property name="unreturnedConnectionTimeout" value="3600" />
    <property name="maxIdleTime" value="3600" />
    <property name="idleConnectionTestPeriod" value="300" />
    <property name="preferredTestQuery" value="select sysdate from DUAL" />
    <property name="properties">
      <props>
          <prop key="user">ramonalprop>
          <prop key="password">ramonalprop>
          <prop key="oracle.jdbc.ReadTimeout">5000prop>
      props>
    property>
bean>

Now a long running transaction which past the set number of timeout seconds will be stopped automatically.

UPDATED:
Recently I ran test on spring3.0.5 + hibernate3.2.6, it seems that transaction timeout can work now.