-->
These old forums are deprecated now and set to read-only. We are waiting for you on our new forums!
More modern, Discourse-based and with GitHub/Google/Twitter authentication built-in.

All times are UTC - 5 hours [ DST ]



Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 1 post ] 
Author Message
 Post subject: Running out of connections
PostPosted: Tue Jan 22, 2013 5:23 pm 
Newbie

Joined: Tue Jan 22, 2013 5:11 pm
Posts: 1
I have inherited a web app that utilizes Spring (2.0), Hibernate (3.2.1), Tomcat 6.0.29 and DBCP on Oracle 10g

The application has been stable for years, but we are now adding functionality to it and have run into a problem, getting the: "Cannot get a connection, pool error Timeout waiting for idle object" error. After viewing the Hibernate debug logs, I see that each HQL call seems to be using a JDBC connection and not releasing until the end of the entire process.

As I mentioned, before the additional functionality was added, this particular method was running fine. The additional code has pushed the number of connections required to complete the process over the limit. Being somewhat new to Hibernate, I'm not sure if it is behaving as expected by using so many connections - or if the original configuration needs some tweaking - or if we should look at a Hibernate upgrade.

Any thoughts are greatly appreciated.

LOG snippet:

Quote:

[DevWeb] DEBUG [2013/01/22 09:49:03] | opened session at timestamp: 13588733438
[DevWeb] DEBUG [2013/01/22 09:49:03] | opening JDBC connection
[DevWeb] DEBUG [2013/01/22 09:49:03] | setting flush mode to: NEVER
[DevWeb] DEBUG [2013/01/22 09:49:03] | begin
[DevWeb] DEBUG [2013/01/22 09:49:03] | current autocommit status: false
[DevWeb] DEBUG [2013/01/22 09:49:03] | after transaction begin
[DevWeb] DEBUG [2013/01/22 09:49:03] | located HQL query plan in cache (from ApplicationLink as applicationLink where applicationLink.application = ? and upper(applicationLink.appServerName) = upper(?))
[DevWeb] DEBUG [2013/01/22 09:49:03] | located HQL query plan in cache (from ApplicationLink as applicationLink where applicationLink.application = ? and upper(applicationLink.appServerName) = upper(?))
[DevWeb] DEBUG [2013/01/22 09:49:03] | find: from ApplicationLink as applicationLink where applicationLink.application = ? and upper(applicationLink.appServerName) = upper(?)
[DevWeb] DEBUG [2013/01/22 09:49:03] | parameters: [it.DevWeb.domain.Application#231, a11-edu-eee-01]
[DevWeb] DEBUG [2013/01/22 09:49:03] | named parameters: {}
[DevWeb] DEBUG [2013/01/22 09:49:03] | about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
[DevWeb] DEBUG [2013/01/22 09:49:03] | select applicatio0_.APLI_PKEY as APLI1_3_, applicatio0_.APPL_PKEY as APPL2_3_, applicatio0_.APP_SERVER_NAME as APP3_3_, applicatio0_.APP_LINK as APP4_3_, applicatio0_.MOBILE_ACCESS_FLAG as MOBILE5_3_, applicatio0_.MOBILE_APP_LINK as MOBILE6_3_, applicatio0_.APP_MAINTENANCE_FLAG as APP7_3_, applicatio0_.APP_MAINTENANCE_LINK as APP8_3_ from TSS_APPLICATION_LINKS applicatio0_ where applicatio0_.APPL_PKEY=? and upper(applicatio0_.APP_SERVER_NAME)=upper(?)
[DevWeb] DEBUG [2013/01/22 09:49:03] | preparing statement
[DevWeb] DEBUG [2013/01/22 09:49:03] | id unsaved-value: null
[DevWeb] DEBUG [2013/01/22 09:49:03] | binding '231' to parameter: 1
[DevWeb] DEBUG [2013/01/22 09:49:03] | binding 'a11-edu-eee-01' to parameter: 2
[DevWeb] DEBUG [2013/01/22 09:49:03] | about to open ResultSet (open ResultSets: 0, globally: 0)
[DevWeb] DEBUG [2013/01/22 09:49:03] | processing result set
[DevWeb] DEBUG [2013/01/22 09:49:03] | result set row: 0
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning '229' as column: APLI1_3_
[DevWeb] DEBUG [2013/01/22 09:49:03] | result row: EntityKey[it.DevWeb.domain.ApplicationLink#229]
[DevWeb] DEBUG [2013/01/22 09:49:03] | Initializing object from ResultSet: [it.DevWeb.domain.ApplicationLink#229]
[DevWeb] DEBUG [2013/01/22 09:49:03] | Hydrating entity: [it.DevWeb.domain.ApplicationLink#229]
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning '231' as column: APPL2_3_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'a11-edu-eee-01' as column: APP3_3_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'N' as column: APP4_3_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'N' as column: MOBILE5_3_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning null as column: MOBILE6_3_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'N' as column: APP7_3_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning null as column: APP8_3_
[DevWeb] DEBUG [2013/01/22 09:49:03] | done processing result set (1 rows)
[DevWeb] DEBUG [2013/01/22 09:49:03] | about to close ResultSet (open ResultSets: 1, globally: 1)
[DevWeb] DEBUG [2013/01/22 09:49:03] | about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
[DevWeb] DEBUG [2013/01/22 09:49:03] | closing statement
[DevWeb] DEBUG [2013/01/22 09:49:03] | total objects hydrated: 1
[DevWeb] DEBUG [2013/01/22 09:49:03] | resolving associations for [it.DevWeb.domain.ApplicationLink#229]
[DevWeb] DEBUG [2013/01/22 09:49:03] | loading entity: [it.DevWeb.domain.Application#231]
[DevWeb] DEBUG [2013/01/22 09:49:03] | attempting to resolve: [it.DevWeb.domain.Application#231]
[DevWeb] DEBUG [2013/01/22 09:49:03] | object not resolved in any cache: [it.DevWeb.domain.Application#231]
[DevWeb] DEBUG [2013/01/22 09:49:03] | Fetching entity: [it.DevWeb.domain.Application#231]
[DevWeb] DEBUG [2013/01/22 09:49:03] | loading entity: [it.DevWeb.domain.Application#231]
[DevWeb] DEBUG [2013/01/22 09:49:03] | about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
[DevWeb] DEBUG [2013/01/22 09:49:03] | select applicatio0_.APPL_PKEY as APPL1_4_0_, applicatio0_.APP_NAME as APP2_4_0_, applicatio0_.APP_NAME_IN_MENU as APP3_4_0_, applicatio0_.EMAIL_FROM as EMAIL4_4_0_, applicatio0_.APPROVER_EMAIL as APPROVER5_4_0_, applicatio0_.HAS_USER_FLAG as HAS6_4_0_, applicatio0_.HAS_AGENT_FLAG as HAS7_4_0_, applicatio0_.HAS_INTERNAL_FLAG as HAS8_4_0_, applicatio0_.HAS_EXT_GOVT_FLAG as HAS9_4_0_, applicatio0_.HAS_MASTER_FLAG as HAS10_4_0_, applicatio0_.HAS_ADMIN_FLAG as HAS11_4_0_, applicatio0_.WHATS_NEW as WHATS12_4_0_, applicatio0_.REQ_FLAG as REQ13_4_0_, applicatio0_.REQ_1_FLAG as REQ14_4_0_, applicatio0_.ALLOW_REG_FLAG as ALLOW15_4_0_, applicatio0_.APP_DESCRIPTION as APP16_4_0_, applicatio0_.APPLICATION_ENABLER_EMAIL as APPLICA17_4_0_, applicatio0_.USES_ID_FLAG as USES18_4_0_, applicatio0_.REQ_2_FLAG as REQ19_4_0_, applicatio0_.REQ_3_FLAG as REQ20_4_0_, applicatio0_.REQ_4_FLAG as REQ21_4_0_, applicatio0_.REQ_COMMENT_FLAG as REQ22_4_0_, applicatio0_.REQ_5_FLAG as REQ23_4_0_, applicatio0_.REQ_6_FLAG as REQ24_4_0_, applicatio0_.GROUP_NAME as LDAP25_4_0_, applicatio0_.REQ_7_FLAG as REQ26_4_0_ from APPLICATIONS applicatio0_ where applicatio0_.APPL_PKEY=?
[DevWeb] DEBUG [2013/01/22 09:49:03] | preparing statement
[DevWeb] DEBUG [2013/01/22 09:49:03] | binding '231' to parameter: 1
[DevWeb] DEBUG [2013/01/22 09:49:03] | about to open ResultSet (open ResultSets: 0, globally: 0)
[DevWeb] DEBUG [2013/01/22 09:49:03] | processing result set
[DevWeb] DEBUG [2013/01/22 09:49:03] | result set row: 0
[DevWeb] DEBUG [2013/01/22 09:49:03] | result row: EntityKey[it.DevWeb.domain.Application#231]
[DevWeb] DEBUG [2013/01/22 09:49:03] | Initializing object from ResultSet: [it.DevWeb.domain.Application#231]
[DevWeb] DEBUG [2013/01/22 09:49:03] | Hydrating entity: [it.DevWeb.domain.Application#231]
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'Dev Web (Iaa Tomcat)' as column: APP2_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'Iaa Tomcat Workstation' as column: APP3_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'iaa@test.com' as column: EMAIL4_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'bob@test.com' as column: APPROVER5_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'Y' as column: HAS6_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'Y' as column: HAS7_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'N' as column: HAS8_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'N' as column: HAS9_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'Y' as column: HAS10_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'Y' as column: HAS11_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning null as column: WHATS12_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'N' as column: REQ13_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'N' as column: REQ14_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'Y' as column: ALLOW15_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'Dev Web with Tomcat' as column: APP16_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning null as column: APPLICA17_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'N' as column: USES18_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'N' as column: REQ19_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'N' as column: REQ20_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'N' as column: REQ21_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'N' as column: REQ22_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'N' as column: REQ23_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'N' as column: REQ24_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning null as column: RT25_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | returning 'N' as column: REQ26_4_0_
[DevWeb] DEBUG [2013/01/22 09:49:03] | done processing result set (1 rows)
[DevWeb] DEBUG [2013/01/22 09:49:03] | about to close ResultSet (open ResultSets: 1, globally: 1)
[DevWeb] DEBUG [2013/01/22 09:49:03] | about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
[DevWeb] DEBUG [2013/01/22 09:49:03] | closing statement
[DevWeb] DEBUG [2013/01/22 09:49:03] | total objects hydrated: 1
[DevWeb] DEBUG [2013/01/22 09:49:03] | resolving associations for [it.DevWeb.domain.Application#231]
[DevWeb] DEBUG [2013/01/22 09:49:03] | creating collection wrapper:[it.DevWeb.domain.Application.applicationRoles#231]
[DevWeb] DEBUG [2013/01/22 09:49:03] | creating collection wrapper:[it.DevWeb.domain.Application.sessions#231]
[DevWeb] DEBUG [2013/01/22 09:49:03] | creating collection wrapper:[it.DevWeb.domain.Application.applicationLinks#231]
[DevWeb] DEBUG [2013/01/22 09:49:03] | done materializing entity [it.DevWeb.domain.Application#231]
[DevWeb] DEBUG [2013/01/22 09:49:03] | done entity load
[DevWeb] DEBUG [2013/01/22 09:49:03] | done materializing entity [it.DevWeb.domain.ApplicationLink#229]
[DevWeb] DEBUG [2013/01/22 09:49:03] | initializing non-lazy collections
[DevWeb] DEBUG [2013/01/22 09:49:03] | commit
[DevWeb] DEBUG [2013/01/22 09:49:03] | before transaction completion
[DevWeb] DEBUG [2013/01/22 09:49:03] | before transaction completion
[DevWeb] DEBUG [2013/01/22 09:49:03] | committed JDBC Connection
[DevWeb] DEBUG [2013/01/22 09:49:03] | after transaction completion
[DevWeb] DEBUG [2013/01/22 09:49:03] | transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!
[DevWeb] DEBUG [2013/01/22 09:49:03] | after transaction completion
[DevWeb] DEBUG [2013/01/22 09:49:03] | setting flush mode to: NEVER
[DevWeb] DEBUG [2013/01/22 09:49:03] | opened session at timestamp: 13588733437
[DevWeb] DEBUG [2013/01/22 09:49:03] | opening JDBC connection
[DevWeb] DEBUG [2013/01/22 09:49:03] | setting flush mode to: NEVER
[DevWeb] DEBUG [2013/01/22 09:49:03] | begin
[DevWeb] DEBUG [2013/01/22 09:49:03] | current autocommit status: false
.
.
.
much of the same as above
.
.
.
[DevWeb] DEBUG [2013/01/22 09:49:03] | opened session at timestamp: 13588733439
[DevWeb] DEBUG [2013/01/22 09:49:03] | opening JDBC connection
[DevWeb] DEBUG [2013/01/22 09:49:08] | SQL Exception
org.apache.tomcat.dbcp.dbcp.SQLNestedException: Cannot get a connection, pool error Timeout waiting for idle object
at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:114)
at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044)
at org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:81)
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:417)
at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
at org.hibernate.jdbc.BorrowedConnectionProxy.invoke(BorrowedConnectionProxy.java:50)
at $Proxy11.setReadOnly(Unknown Source)
at org.springframework.jdbc.datasource.DataSourceUtils.prepareConnectionForTransaction(DataSourceUtils.java:156)
at org.springframework.orm.hibernate3.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:442)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:315)
at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:257)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:102)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:209)
at $Proxy4.findByUserAndApplication(Unknown Source)
at it.DevWeb.webapp.controller.AccountController.onSubmit(AccountController.java:583)
at org.springframework.web.servlet.mvc.SimpleFormController.processFormSubmission(SimpleFormController.java:258)
at org.springframework.web.servlet.mvc.AbstractFormController.handleRequestInternal(AbstractFormController.java:250)
at org.springframework.web.servlet.mvc.AbstractController.handleRequest(AbstractController.java:153)
at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:45)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:806)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:736)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:396)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:360)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.springframework.orm.hibernate3.support.OpenSessionInViewFilter.doFilterInternal(OpenSessionInViewFilter.java:174)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:77)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298)
at org.apache.coyote.http11.Http11AprProcessor.process(Http11AprProcessor.java:861)
at org.apache.coyote.http11.Http11AprProtocol$Http11ConnectionHandler.process(Http11AprProtocol.java:579)
at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1584)
at java.lang.Thread.run(Thread.java:619)
Caused by: java.util.NoSuchElementException: Timeout waiting for idle object
at org.apache.tomcat.dbcp.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1134)
at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106)
... 41 more



in this case:

AccountController.java calls getApplicationService().findByUser(contextUser);


Typical HQL method code:

Code:
public class ApplicationDAOHibernate extends HibernateDaoSupport implements ApplicationRoleDAO {

   public Application findByUser(User user) {

      String query = "from Application as applicationRole where application.user = ? ";
      ApplicationRole applicationRole = null;
      Object[] parameters = { user };
      List list = this.getHibernateTemplate().find(query, parameters);
      if (list.size() > 0) {
         application = (Application) list.get(0);
      }
      return application;
   }

.
.
.
}



Configuration:


applicationContext.xml

Code:
<beans>
   <!-- JNDI DataSource -->
   <bean id="dataSource" class="org.springframework.jndi.JndiObjectFactoryBean">
      <property name="jndiName">
         <value>java:comp/env/jdbc/THEDataSource</value>
      </property>
   </bean>

   <!-- Hibernate SessionFactory -->
   <bean id="sessionFactory" class="org.springframework.orm.hibernate3.LocalSessionFactoryBean">
      <property name="dataSource">
         <ref local="dataSource"/>
      </property>
      <property name="mappingResources">
         <list>
            <value>it/DevWeb/domain/User.hbm.xml</value>
            <value>it/DevWeb/domain/Session.hbm.xml</value>
            <value>it/DevWeb/domain/Application.hbm.xml</value>
            <value>it/DevWeb/domain/RegApprovalSession.hbm.xml</value>
            .
            .
            .
         </list>
      </property>
      <property name="hibernateProperties">
         <props>
            <prop key="hibernate.dialect">org.hibernate.dialect.Oracle9Dialect</prop>
         </props>
      </property>
   </bean>

   <!-- Transaction manager for the Hibernate SessionFactory. -->
   <bean id="transactionManager" class="org.springframework.orm.hibernate3.HibernateTransactionManager">
      <property name="sessionFactory">
         <ref local="sessionFactory"/>
      </property>
   </bean>

   <!-- UserDAO: Hibernate implementation -->
   <bean id="userDAO" class="it.DevWeb.dao.hibernate.UserDAOHibernate">
      <property name="sessionFactory">
         <ref local="sessionFactory"/>
      </property>
   </bean>

   <!-- User Service -->
   <bean id="userServiceTarget" class="it.DevWeb.business.impl.UserServiceImpl">
      <property name="userDAO">
         <ref local="userDAO"/>
      </property>
   </bean>

   <!-- Transaction declarations for User Service -->
   <bean id="userService" class="org.springframework.transaction.interceptor.TransactionProxyFactoryBean">
      <property name="transactionManager">
         <ref local="transactionManager"/>
      </property>
      <property name="target">
         <ref local="userServiceTarget"/>
      </property>
      <property name="transactionAttributes">
         <props>
            <prop key="insert">PROPAGATION_REQUIRED</prop>
            <prop key="update">PROPAGATION_REQUIRED</prop>
            <prop key="merge">PROPAGATION_REQUIRED</prop>
            <prop key="*">PROPAGATION_REQUIRED,readOnly</prop>
         </props>
      </property>
   </bean>
.
.
.
</beans>


tomcat-context.xml

Code:
<Context reloadable="false">
   <Resource name="jdbc/THEDataSource" auth="Container" type="javax.sql.DataSource"
      
      factory="org.apache.tomcat.dbcp.dbcp.BasicDataSourceFactory"
      maxActive="100"
      maxIdle="5"
      maxWait="5000"
      validationQuery="SELECT 1 FROM DUAL"
      testOnBorrow="true"
      defaultAutoCommit="false" 
      driverClassName="oracle.jdbc.driver.OracleDriver"
      username="scott"
      password="tiger"
      url="jdbc:oracle:thin:@it01:1523:appdev"/>
   
</Context>



Top
 Profile  
 
Display posts from previous:  Sort by  
Forum locked This topic is locked, you cannot edit posts or make further replies.  [ 1 post ] 

All times are UTC - 5 hours [ DST ]


You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum

Search for:
© Copyright 2014, Red Hat Inc. All rights reserved. JBoss and Hibernate are registered trademarks and servicemarks of Red Hat, Inc.