hibernate数据库连接池爆满的原因及源码分析

首先是线上出现了连接池满的异常

017-09-08 21:29:08 [Thread-23] ERROR: org.hibernate.util.JDBCExceptionReporter#logExceptions : [Thread-23] Timeout: Pool empty. Unable to fetch a connection in 5 seconds, none available[size:2; busy:2; idle:0; lastwait:5000].
2017-09-08 21:29:08 [Thread-23] ERROR: org.hibernate.util.JDBCExceptionReporter#logExceptions : [Thread-23] Timeout: Pool empty. Unable to fetch a connection in 5 seconds, none available[size:2; busy:2; idle:0; lastwait:5000].
2017-09-08 21:29:10 [Thread-22] ERROR: org.hibernate.util.JDBCExceptionReporter#logExceptions : [Thread-22] Timeout: Pool empty. Unable to fetch a connection in 5 seconds, none available[size:2; busy:2; idle:0; lastwait:5000].
2017-09-08 21:29:10 [Thread-22] ERROR: org.hibernate.util.JDBCExceptionReporter#logExceptions : [Thread-22] Timeout: Pool empty. Unable to fetch a connection in 5 seconds, none available[size:2; busy:2; idle:0; lastwait:5000].
Exception in thread "Thread-23" org.springframework.transaction.CannotCreateTransactionException: Could not open Hibernate Session for transaction; nested exception is org.hibernate.exception.GenericJDBCException: Cannot open connection
    at org.springframework.orm.hibernate3.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:596)
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:371)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:329)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:105)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.aop.framework.adapter.ThrowsAdviceInterceptor.invoke(ThrowsAdviceInterceptor.java:124)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:622)
    at com.upg.ucars.basesystem.autotask.core.autotasklog.AutoTaskLogService$$EnhancerByCGLIB$$ad1ea0d3.saveAutoTaskLog(<generated>)
    at com.upg.ucars.basesystem.autotask.core.AutoTaskInstance.notifySubTaskStatus(AutoTaskInstance.java:184)
    at com.upg.ucars.basesystem.autotask.core.AutoTaskInstance.setStatus(AutoTaskInstance.java:150)
    at com.upg.ucars.basesystem.autotask.core.AbstractMemberAutoTask$MemberTaskProcessor.run(AbstractMemberAutoTask.java:241)
Caused by: org.hibernate.exception.GenericJDBCException: Cannot open connection
    at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:140)
    at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:128)
    at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
    at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:52)
    at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:449)
    at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167)
    at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:160)
    at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:81)
    at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1473)
    at org.springframework.orm.hibernate3.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:555)
    ... 15 more
Caused by: org.apache.tomcat.jdbc.pool.PoolExhaustedException: [Thread-23] Timeout: Pool empty. Unable to fetch a connection in 5 seconds, none available[size:2; busy:2; idle:0; lastwait:5000].
    at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:708)
    at org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:198)
    at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:132)
    at org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:81)
    at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446)
    ... 20 more
Exception in thread "Thread-22" org.springframework.transaction.CannotCreateTransactionException: Could not open Hibernate Session for transaction; nested exception is org.hibernate.exception.GenericJDBCException: Cannot open connection
    at org.springframework.orm.hibernate3.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:596)
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:371)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:329)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:105)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.aop.framework.adapter.ThrowsAdviceInterceptor.invoke(ThrowsAdviceInterceptor.java:124)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
    at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:622)
    at com.upg.ucars.basesystem.autotask.core.autotasklog.AutoTaskLogService$$EnhancerByCGLIB$$ad1ea0d3.saveAutoTaskLog(<generated>)
    at com.upg.ucars.basesystem.autotask.core.AutoTaskInstance.notifySubTaskStatus(AutoTaskInstance.java:184)
    at com.upg.ucars.basesystem.autotask.core.AutoTaskInstance.setStatus(AutoTaskInstance.java:150)
    at com.upg.ucars.basesystem.autotask.core.AbstractMemberAutoTask$MemberTaskProcessor.run(AbstractMemberAutoTask.java:241)
Caused by: org.hibernate.exception.GenericJDBCException: Cannot open connection
    at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:140)
    at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:128)
    at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
    at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:52)
    at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:449)
    at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:167)
    at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:160)
    at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:81)
    at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1473)
    at org.springframework.orm.hibernate3.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:555)
    ... 15 more
Caused by: org.apache.tomcat.jdbc.pool.PoolExhaustedException: [Thread-22] Timeout: Pool empty. Unable to fetch a connection in 5 seconds, none available[size:2; busy:2; idle:0; lastwait:5000].
    at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:708)
    at org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:198)
    at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:132)
    at org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:81)
    at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:446)
    ... 20 more

项目采用mysql+spring+hibernate,spring的事务配置如下：

   

<bean id="sessionFactory" class="com.upg.ucars.framework.annotation.XAnnotationSessionFactoryBean">
        <property name="entityInterceptor">
            <ref bean="myEntityInterceptor"/>
        </property>

        <property name="dataSource">
            <ref local="localDataSource"/>
        </property>
        <property name="exclude">
            <list>
                <value>com/upg/loan</value>
            </list>
        </property>
        <property name="mappingLocations">
            <list>
                <value>classpath*:/org/jbpm/**/*.hbm.xml</value>
                <value>classpath*:/com/upg/**/*.hbm.xml</value>
            </list>
        </property>
        <property name="packagesToScan" value="com.upg"/>
        <property name="hibernateProperties">
            <props>
                <!--<prop key="hibernate.dialect">org.hibernate.dialect.DB2Dialect</prop> -->
                <prop key="hibernate.dialect">com.upg.ucars.framework.dialect.MySQLDialect</prop>
                <prop key="connection.provider_class">org.hibernate.connection.C3P0ConnectionProvider</prop>
                <prop key="hibernate.show_sql">false</prop>
                <prop key="hibernate.format_sql">false</prop>
                <!-- <prop key="hibernate.default_schema">xcars</prop> -->
                <prop key="hibernate.jdbc.use_scrollable.resultset">true</prop>
                <prop key="hibernate.cache.use_query_cache">true</prop>
                <prop key="hibernate.cache.use_second_level_cache">true</prop>
                <prop key="hibernate.cache.provider_class">org.hibernate.cache.EhCacheProvider</prop>
                <prop key="hibernate.query.factory_class">org.hibernate.hql.ast.ASTQueryTranslatorFactory</prop>
<!--                 <prop key="hibernate.connection.release_mode">after_transaction</prop>                
 -->            </props>
        </property>
        <property name="lobHandler" ref="oracleLobHandler" />
        <property name="typeDefinitions">
            <list>
                <bean class="org.springframework.orm.hibernate3.TypeDefinitionBean">
                    <property name="typeName" value="xclob"/>
                    <property name="typeClass" value="org.springframework.orm.hibernate3.support.ClobStringType"/>
                </bean>
            </list>
        </property>
    </bean>


    <bean id="transactionManager"
          class="org.springframework.orm.hibernate3.HibernateTransactionManager">
        <property name="sessionFactory" ref="sessionFactory"></property>
    </bean>
    
     <bean id="transactionTemplate"
          class="org.springframework.transaction.support.TransactionTemplate">
        <property name="transactionManager" ref="transactionManager" />
    </bean>
    
    <tx:advice id="txAdvice" transaction-manager="transactionManager">
        <tx:attributes>
            <tx:method name="get*" read-only="true" propagation="SUPPORTS" />
            <tx:method name="find*" read-only="true" propagation="SUPPORTS" />
            <tx:method name="query*" read-only="true" propagation="SUPPORTS" />
            <tx:method name="autoGenCode"  propagation="REQUIRES_NEW" />
            <tx:method name="openAccount"  propagation="NOT_SUPPORTED" />
              <tx:method name="signContractSafe" propagation="NOT_SUPPORTED" />
            <tx:method name="safeSignContract" propagation="REQUIRED" />
            <!--
            <tx:method name="updateAfterCommuTrans"  propagation="REQUIRES_NEW" />
            <tx:method name="updateAfterMZCommuTrans"  propagation="REQUIRES_NEW" />
            <tx:method name="updateAfterCZCommuTrans"  propagation="REQUIRES_NEW" />
            <tx:method name="createAcctFlowNewSession"  propagation="REQUIRES_NEW" />
            <tx:method name="buildAcctRecord"  propagation="REQUIRES_NEW" />
            <tx:method name="deleteAcctRecord"  propagation="REQUIRES_NEW" />
            <tx:method name="buildNegativeAcctRecord"  propagation="REQUIRES_NEW" />
             -->
            <tx:method name="clearEndProcessInstance"  propagation="REQUIRES_NEW" />
            <tx:method name="*" read-only="false" propagation="REQUIRED" />
        </tx:attributes>
    </tx:advice>
    <aop:config proxy-target-class="true">
        <aop:pointcut id="txServiceFosc" expression="execution (* com.upg..*Service*.*(..))
            and !execution (* com.upg..action.*.*(..))" />
        <aop:advisor pointcut-ref="txServiceFosc" advice-ref="txAdvice" />
        <aop:advisor pointcut-ref="txServiceFosc" advice-ref="xcarsExceptionInterceptor" />
    </aop:config>

后有同事发现一个定时脚本里直接调了dao而不是service导致spring的事务管理没起作用，这个定时脚本每3分钟跑一次，执行的是update语句，结果把连接池的资源都耗光了，后改成调用service后这个问题也没了。但为什么呢，想可能是dao在执行update后没有commit，由于默认的autocommit=fasle,既然没commit，那数据库连接也就不会释放了。但因为没能从源码上知道答案，所以也只是猜测。

//LoanApplyExtDaoImpl
@Override
    public void updateApplyExtStatusByTime(String timeBegin,String audittime) {
        StringBuffer sql =new StringBuffer();
        sql.append("update jk_loan_apply_ext a,jk_user_loan_record b set a.status=3   
" +
                "where a.loan_apply_id=b.loan_apply_id and a.status=2 
" +
                "and b.create_time>'"+timeBegin+"' and b.create_time<'"+audittime+"' ");
        getSession().createSQLQuery(sql.toString()).executeUpdate();
    }

这几天趁着有时间分析了下源码，记录如下

连接池：

    <bean id="dataSourceParent" class="org.apache.tomcat.jdbc.pool.DataSource" abstract="true" destroy-method="close">
        <property name="driverClassName" >
            <value>net.sf.log4jdbc.DriverSpy</value>
        </property>
        <property name="initialSize" value="${dataSource.dbcp.initialSize}"/>
        <property name="maxActive" value="${dataSource.dbcp.maxActive}"/>
        <property name="maxWait" value="${dataSource.dbcp.maxWait}"/>
        <property name="maxIdle" value="${dataSource.dbcp.maxIdle}"/>
        <property name="minIdle" value="${dataSource.dbcp.minIdle}"/>
        <property name="testOnBorrow" value="true"/>
        <property name="testWhileIdle" value="false"/>
        <property name="validationQuery" value="select 1 from dual"/>
    </bean>

因为Pool empty. Unable to fetch a connection in 5 seconds, none available[size:2; busy:2; idle:0; lastwait:5000].这句话来自org.apache.tomcat.jdbc.pool.ConnectionPool

   private PooledConnection borrowConnection(int wait, String username, String password) throws SQLException {

        if (isClosed()) {
            throw new SQLException("Connection pool closed.");
        } //end if

        //get the current time stamp
        long now = System.currentTimeMillis();
        //see if there is one available immediately
        PooledConnection con = idle.poll();

        while (true) {
            if (con!=null) {
                //configure the connection and return it
                PooledConnection result = borrowConnection(now, con, username, password);
                borrowedCount.incrementAndGet();
                if (result!=null) return result;
            }

            //if we get here, see if we need to create one
            //this is not 100% accurate since it doesn't use a shared
            //atomic variable - a connection can become idle while we are creating
            //a new connection
            if (size.get() < getPoolProperties().getMaxActive()) {
                //atomic duplicate check
                if (size.addAndGet(1) > getPoolProperties().getMaxActive()) {
                    //if we got here, two threads passed through the first if
                    size.decrementAndGet();
                } else {
                    //create a connection, we're below the limit
                    return createConnection(now, con, username, password);
                }
            } //end if

            //calculate wait time for this iteration
            long maxWait = wait;
            //if the passed in wait time is -1, means we should use the pool property value
            if (wait==-1) {
                maxWait = (getPoolProperties().getMaxWait()<=0)?Long.MAX_VALUE:getPoolProperties().getMaxWait();
            }

            long timetowait = Math.max(0, maxWait - (System.currentTimeMillis() - now));
            waitcount.incrementAndGet();
            try {
                //retrieve an existing connection
                con = idle.poll(timetowait, TimeUnit.MILLISECONDS);
            } catch (InterruptedException ex) {
                if (getPoolProperties().getPropagateInterruptState()) {
                    Thread.currentThread().interrupt();
                }
                SQLException sx = new SQLException("Pool wait interrupted.");
                sx.initCause(ex);
                throw sx;
            } finally {
                waitcount.decrementAndGet();
            }
            if (maxWait==0 && con == null) { //no wait, return one if we have one
                if (jmxPool!=null) {
                    jmxPool.notify(org.apache.tomcat.jdbc.pool.jmx.ConnectionPool.POOL_EMPTY, "Pool empty - no wait.");
                }
                throw new PoolExhaustedException("[" + Thread.currentThread().getName()+"] " +
                        "NoWait: Pool empty. Unable to fetch a connection, none available["+busy.size()+" in use].");
            }
            //we didn't get a connection, lets see if we timed out
            if (con == null) {
                if ((System.currentTimeMillis() - now) >= maxWait) {
                    if (jmxPool!=null) {
                        jmxPool.notify(org.apache.tomcat.jdbc.pool.jmx.ConnectionPool.POOL_EMPTY, "Pool empty - timeout.");
                    }
                    throw new PoolExhaustedException("[" + Thread.currentThread().getName()+"] " +
                        "Timeout: Pool empty. Unable to fetch a connection in " + (maxWait / 1000) +
                        " seconds, none available[size:"+size.get() +"; busy:"+busy.size()+"; idle:"+idle.size()+"; lastwait:"+timetowait+"].");
                } else {
                    //no timeout, lets try again
                    continue;
                }
            }
        } //while
    }

con = idle.poll(timetowait, TimeUnit.MILLISECONDS);这句从pool里取一个连接，如果返回的为null，就会抛
Timeout: Pool empty. Unable to fetch a connection in 5 seconds, none available[size:2; busy:2; idle:0; lastwait:5000].

那为什么会取不到？那当然是连接没有释放。再看org.hibernate.jdbc.ConnectionManager

    /**
     * To be called after execution of each JDBC statement.  Used to
     * conditionally release the JDBC connection aggressively if
     * the configured release mode indicates.
     */
    public void afterStatement() {
        if ( isAggressiveRelease() ) {
            if ( isFlushing ) {
                log.debug( "skipping aggressive-release due to flush cycle" );
            }
            else if ( batcher.hasOpenResources() ) {
                log.debug( "skipping aggresive-release due to open resources on batcher" );
            }
            else if ( borrowedConnection != null ) {
                log.debug( "skipping aggresive-release due to borrowed connection" );
            }
            else {
                aggressiveRelease();
            }
        }
    }
    
/**
     * To be called after local transaction completion.  Used to conditionally
     * release the JDBC connection aggressively if the configured release mode
     * indicates.
     */
    public void afterTransaction() {
        if ( isAfterTransactionRelease() ) {
            aggressiveRelease();
        }
        else if ( isAggressiveReleaseNoTransactionCheck() && batcher.hasOpenResources() ) {
            log.info( "forcing batcher resource cleanup on transaction completion; forgot to close ScrollableResults/Iterator?" );
            batcher.closeStatements();
            aggressiveRelease();
        }
        else if ( isOnCloseRelease() ) {
            // log a message about potential connection leaks
            log.debug( "transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!" );
        }
        batcher.unsetTransactionTimeout();
    }

    private boolean isAfterTransactionRelease() {
        return releaseMode == ConnectionReleaseMode.AFTER_TRANSACTION;
    }

    private boolean isOnCloseRelease() {
        return releaseMode == ConnectionReleaseMode.ON_CLOSE;
    }


    public boolean isAggressiveRelease() {
        if ( releaseMode == ConnectionReleaseMode.AFTER_STATEMENT ) {
            return true;
        }
        else if ( releaseMode == ConnectionReleaseMode.AFTER_TRANSACTION ) {
            boolean inAutoCommitState;
            try {
                inAutoCommitState = isAutoCommit()&& !callback.isTransactionInProgress();
            }
            catch( SQLException e ) {
                // assume we are in an auto-commit state
                inAutoCommitState = true;
            }
            return inAutoCommitState;
        }
        return false;
    }

如果spring声明式事务没起作用，会走到afterTransaction()这个方法，从代码上看到releaseMode == ConnectionReleaseMode.AFTER_TRANSACTION会触发aggressiveRelease方法，在hibernate的配置上加上<prop key="hibernate.connection.release_mode">after_transaction</prop>后果然即使直接调Dao也不会导致数据库连接不释放了。