首先是线上出现了连接池满的异常
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也不会导致数据库连接不释放了。