Hibernate Session Saturation Probleme

aldwin · **Joined:** Thu Nov 30, 2006 12:21 pm **Posts:** 14

Hello ,
I'm a new user of Hibernate 3.2 , I have a strange phenome that occures when I run my application .What I'm doing is executing a SQL query via Criteria API , I want to execute the same query x times but with different parameters , It work fine if the number of query don't rich 9 ! and if the number is greater than 9 the application did'nt return and still turning ...
Hibernate version:3.2

Mapping documents:

Code between sessionFactory.openSession() and session.close():

database : SQL Server

The generated SQL (show_sql=true):

Debug level Hibernate log :DEBUG

this is the trace of the LOGS of the executing : I copy the 8th query executing & the 9th which didn't return

Code:

 2007-01-05 15:57:46,702 [DEBUG] com.webtiss.sita.sgp.business.impl.SiteOperationBusiness:224 - doPrepareFilter - Emplacement id : 304 
2007-01-05 15:57:46,702 [DEBUG] com.webtiss.sita.sgp.business.impl.SiteOperationBusiness:254 - 35 
2007-01-05 15:57:46,702 [DEBUG] org.springframework.orm.hibernate3.SessionFactoryUtils:333 - Opening Hibernate Session 
2007-01-05 15:57:46,702 [DEBUG] org.hibernate.impl.SessionImpl:220 - opened session at timestamp: 4784165137211392 
2007-01-05 15:57:46,702 [DEBUG] com.webtiss.sita.sgp.dao.hibernate.CollecteDAOHibernate:70 - getAll CollecteDAOHibernate without op criteria 
2007-01-05 15:57:46,702 [DEBUG] com.webtiss.sita.sgp.dao.hibernate.CollecteDAOHibernate:73 - after 
2007-01-05 15:57:46,702 [DEBUG] org.hibernate.jdbc.AbstractBatcher:358 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 
2007-01-05 15:57:46,718 [DEBUG] org.hibernate.jdbc.ConnectionManager:415 - opening JDBC connection 
2007-01-05 15:57:46,718 [DEBUG] org.hibernate.SQL:393 - select this_.id as id9_0_, this_.ano_id as ano2_9_0_, this_.regroup_ano_id as regroup3_9_0_, this_.commentaire as commenta4_9_0_, this_.date_heure as date5_9_0_, this_.destination_id as destinat6_9_0_, this_.emplacement_id as emplacem7_9_0_, this_.etiq_cont_id as etiq8_9_0_, this_.qte_cont as qte9_9_0_, this_.qte_dechet as qte10_9_0_, this_.regoup_comment as regoup11_9_0_, this_.regroup_date_heure as regroup12_9_0_, this_.operateur_id as operateur13_9_0_ from collecte this_ where this_.emplacement_id=? and this_.date_heure between ? and ? 
Hibernate: select this_.id as id9_0_, this_.ano_id as ano2_9_0_, this_.regroup_ano_id as regroup3_9_0_, this_.commentaire as commenta4_9_0_, this_.date_heure as date5_9_0_, this_.destination_id as destinat6_9_0_, this_.emplacement_id as emplacem7_9_0_, this_.etiq_cont_id as etiq8_9_0_, this_.qte_cont as qte9_9_0_, this_.qte_dechet as qte10_9_0_, this_.regoup_comment as regoup11_9_0_, this_.regroup_date_heure as regroup12_9_0_, this_.operateur_id as operateur13_9_0_ from collecte this_ where this_.emplacement_id=? and this_.date_heure between ? and ?
2007-01-05 15:57:46,718 [DEBUG] org.hibernate.jdbc.AbstractBatcher:476 - preparing statement 
2007-01-05 15:57:46,718 [DEBUG] org.hibernate.engine.IdentifierValue:104 - id unsaved-value: 0 
2007-01-05 15:57:46,718 [DEBUG] org.hibernate.type.LongType:80 - binding '304' to parameter: 1 
2007-01-05 15:57:46,718 [DEBUG] org.hibernate.type.TimestampType:80 - binding '2004-07-01 15:57:42' to parameter: 2 
2007-01-05 15:57:46,718 [DEBUG] org.hibernate.type.TimestampType:80 - binding '2004-07-02 15:57:42' to parameter: 3 
2007-01-05 15:57:46,718 [DEBUG] org.hibernate.jdbc.AbstractBatcher:374 - about to open ResultSet (open ResultSets: 0, globally: 0) 
2007-01-05 15:57:46,718 [DEBUG] org.hibernate.loader.Loader:682 - processing result set 
2007-01-05 15:57:46,718 [DEBUG] org.hibernate.loader.Loader:709 - done processing result set (0 rows) 
2007-01-05 15:57:46,718 [DEBUG] org.hibernate.jdbc.AbstractBatcher:381 - about to close ResultSet (open ResultSets: 1, globally: 1) 
2007-01-05 15:57:46,718 [DEBUG] org.hibernate.jdbc.AbstractBatcher:366 - about to close PreparedStatement (open PreparedStatements: 1, globally: 1) 
2007-01-05 15:57:46,718 [DEBUG] org.hibernate.jdbc.AbstractBatcher:525 - closing statement 
2007-01-05 15:57:46,718 [DEBUG] org.hibernate.loader.Loader:839 - total objects hydrated: 0 
2007-01-05 15:57:46,718 [DEBUG] org.hibernate.engine.StatefulPersistenceContext:748 - initializing non-lazy collections 
2007-01-05 15:57:46,718 [DEBUG] org.hibernate.jdbc.JDBCContext:233 - after autocommit 
2007-01-05 15:57:46,718 [DEBUG] org.hibernate.jdbc.ConnectionManager:296 - transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources! 
2007-01-05 15:57:46,718 [DEBUG] org.hibernate.impl.SessionImpl:422 - after transaction completion 
2007-01-05 15:57:46,718 [DEBUG] com.webtiss.sita.sgp.business.impl.SiteOperationBusiness:224 - doPrepareFilter - Emplacement id : 305 
2007-01-05 15:57:46,718 [DEBUG] com.webtiss.sita.sgp.business.impl.SiteOperationBusiness:254 - 35 
2007-01-05 15:57:46,718 [DEBUG] org.springframework.orm.hibernate3.SessionFactoryUtils:333 - Opening Hibernate Session 
2007-01-05 15:57:46,718 [DEBUG] org.hibernate.impl.SessionImpl:220 - opened session at timestamp: 4784165137276928 
2007-01-05 15:57:46,734 [DEBUG] com.webtiss.sita.sgp.dao.hibernate.CollecteDAOHibernate:70 - getAll CollecteDAOHibernate without op criteria 
2007-01-05 15:57:46,734 [DEBUG] com.webtiss.sita.sgp.dao.hibernate.CollecteDAOHibernate:73 - after 
2007-01-05 15:57:46,734 [DEBUG] org.hibernate.jdbc.AbstractBatcher:358 - about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 
2007-01-05 15:57:46,734 [DEBUG] org.hibernate.jdbc.ConnectionManager:415 - opening JDBC connection 

I don't have any idea of what is happening there?
plz help

dominicus · **Posted:** Fri Jan 05, 2007 12:11 pm

It looks like you are not closing your connections. Are you closing the sessions ?

aldwin · **Joined:** Thu Nov 30, 2006 12:21 pm **Posts:** 14

Thank you for your suggestion , I have fixed the probleme by setting the
connexion closing mode to after_statement;
the portion of hibernate properties config in my XML is :

Code:

<property name="hibernateProperties">
         <props>
            <prop key="hibernate.dialect">org.hibernate.dialect.SQLServerDialect</prop>
            <prop key="hibernate.hbm2ddl.auto">update</prop>
            <prop key="hibernate.show_sql">true</prop> 
             <prop key="hibernate.cache.provider_class">net.sf.ehcache.hibernate.EhCacheProvider</prop>
            <prop key="hibernate.cache.use_query_cache">true</prop>
            <prop key="hibernate.c3p0.acquire_increment">1</prop>
                <prop key="hibernate.c3p0.minPoolSize">30</prop>
                <prop key="hibernate.c3p0.maxPoolSize">150</prop>
            <prop key="hibernate.c3p0.timeout">30</prop>
            <prop key="hibernate.c3p0.max_statement">0</prop>  
            <prop key="hibernate.c3p0.idle_test_period">30</prop>
            <prop key="hibernate.connection.release_mode">after_statement</prop>
            
         </props>
      </property>

The probleme was that for each SQL query hibernate instanciate a new JDBC connection ?? (I don't undesrtand why? because I use a JDBC connexion Pool ) and you can observe that in this way the ressource limit is reached quickly ...
I don't find the default value of the size of JDBC pool for a Basic Date Source : org.apache.commons.dbcp.BasicDataSource ;
Thera also another solution but less elegante in comparison with the first :
we can set the maxActive for a value which we may estimate that will be never riched in the context of the application : for example :

Code:

<bean id="data.source" class="org.apache.commons.dbcp.BasicDataSource" destroy-method="close">
      <property name="driverClassName"><value>net.sourceforge.jtds.jdbc.Driver</value></property>
      <property name="url"><value>jdbc:jtds:sqlserver://localhost:1433/sgp;tds=8.0;lastupdatecount=true</value></property>
      <property name="username"><value>sita1</value></property>
      <property name="password"><value>???</value></property>
<property name="maxActive"><value>50</value></property>
   </bean>

I hope my post will be useful
thanks

batmat · **Posted:** Fri Jan 05, 2007 5:45 pm

From your code in the french part, I seem to understand you're using Spring, are you ?

If so, I just guess you didn't demarcate your transaction properly. Where do you beginTransaction(), and where do you commit()?

I feat after_transaction is just hiding a bigger problem in your case.

mbrunecky · **Joined:** Wed Dec 07, 2005 4:19 pm **Posts:** 53

You did not post any code, nor too much description of the context, so it's hard to pass a judgement.

It really _looks_ like you are not closing sessions (though you definitely seem to be running out of connections - Java Thread Dump could confirm that very easily.

Fixing the problem by forcing connection release on each statement (only recommended for JTA if I remeber correctly) may have fixed your problem with releasing connections - but it may have created other ones.

For one, failure to close session(s) could mean a memory leak, as your session(s) will keep cache of loaded objects in memory, keeping everything you ever loaded (thru those sessions) in memory...

If you have a good reason for not closing sessions, another reason for your problem may be not bracketing you objects loads by Hibernate transactions (begin/commit transaction). Using the default 3.1 connection release mode AFTER_TRANSACTION means that the JDBC Connection will be released when you commit/rollback.
[Don't ask me why Hibernate wants you to begin/commit transaction aroud selects, but everybody does it -- and with connection release mode AFTER_TRANSACTION, you need a transaction end there].

Another problem with not closing session is that you may have uncommited changes in your session.... ses.isDirty()

The second concern, if you are not using JTA and switch to connection release mode AFTER_STATEMENT, what happens to your transaction integrity when you release connection after each statement...