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

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"> <value>com/upg/loan</value> </list> </property> <property name="mappingLocations"> <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"> <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   \n" +
                "where a.loan_apply_id=b.loan_apply_id and a.status=2 \n" +
                "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也不会导致数据库连接不释放了。

喜欢艺术的码农