ConnectionManager is not releasing connections properly.
Hello, I've been working with EJB3 for a couple of months and everything worked fine, 'till one day the following exception came up:
2006-01-25 14:00:08,826 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] run: IdleRemover notifying pools, interval: 30000
2006-01-25 14:00:15,169 WARN [org.hibernate.jdbc.ConnectionManager] unclosed connection, forgot to call close() on your session?
2006-01-25 14:00:15,190 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4662145905418240
2006-01-25 14:00:15,190 DEBUG [org.hibernate.impl.SessionImpl] find: from Actividad s
2006-01-25 14:00:38,836 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] run: IdleRemover notifying pools, interval: 30000
2006-01-25 14:00:38,836 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=udgvirtual, password=--hidden--}
2006-01-25 14:00:38,842 DEBUG [org.jboss.resource.adapter.jdbc.local.LocalManagedConnectionFactory] Using properties: {user=udgvirtual, password=--hidden--}
2006-01-25 14:00:45,196 WARN [org.hibernate.util.JDBCExceptionReporter] SQL Error: 0, SQLState: null
2006-01-25 14:00:45,196 ERROR [org.hibernate.util.JDBCExceptionReporter] No ManagedConnections available within configured blocking timeout ( 30000 [ms] ); - nested throwable: (javax.resource.ResourceException: No ManagedConnections available within configured blocking timeout ( 30000 [ms] ))
2006-01-25 14:00:45,196 DEBUG [org.hibernate.impl.SessionImpl] after transaction completion
2006-01-25 14:00:45,197 ERROR [org.apache.catalina.core.ContainerBase.[jboss.web].[localhost].[/mypage].[jsp]] Servlet.service() for servlet jsp threw exception
org.hibernate.exception.GenericJDBCException: Cannot open connection
at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:91)
at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:79)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:29)
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:307)
at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:109)
at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:105)
at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1561)
at org.hibernate.loader.Loader.doQuery(Loader.java:661)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:223)
at org.hibernate.loader.Loader.doList(Loader.java:2147)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2026)
at org.hibernate.loader.Loader.list(Loader.java:2021)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:369)
at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:298)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1020)
at org.hibernate.impl.QueryImpl.list(QueryImpl.java:74)
at org.hibernate.ejb.QueryImpl.getResultList(QueryImpl.java:38)
... more
Caused by: org.jboss.util.NestedSQLException: No ManagedConnections available within configured blocking timeout ( 30000 [ms] ); - nested throwable: (javax.resource.ResourceException: No ManagedConnections available within configured blocking timeout ( 30000 [ms] ))
at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:79)
at org.hibernate.connection.DatasourceConnectionProvider.getConnection(DatasourceConnectionProvider.java:69)
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:304)
... 41 more
Caused by: javax.resource.ResourceException: No ManagedConnections available within configured blocking timeout ( 30000 [ms] )
at org.jboss.resource.connectionmanager.InternalManagedConnectionPool.getConnection(InternalManagedConnectionPool.java:246)
at org.jboss.resource.connectionmanager.JBossManagedConnectionPool$BasePool.getConnection(JBossManagedConnectionPool.java:529)
at org.jboss.resource.connectionmanager.BaseConnectionManager2.getManagedConnection(BaseConnectionManager2.java:410)
at org.jboss.resource.connectionmanager.TxConnectionManager.getManagedConnection(TxConnectionManager.java:342)
at org.jboss.resource.connectionmanager.BaseConnectionManager2.allocateConnection(BaseConnectionManager2.java:462)
at org.jboss.resource.connectionmanager.BaseConnectionManager2$ConnectionManagerProxy.allocateConnection(BaseConnectionManager2.java:894)
at org.jboss.resource.adapter.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:73)
... 43 more
All my jsp pages have the following directive on top:
<%@ include file='WEB-INF/sys.jsp' %>
... the file resides inside WEB-INF to reside outside client view, so server side it is included at translation time, the file includes:
<%@ page import="lots.of.imports" %>
<%@ taglib tagdir="/WEB-INF/tags/sometags" prefix="tags" %>
<%! EntityManager em = null ; %>
<%
try {
em = ((EntityManagerFactory)(( new InitialContext()).lookup("java:/EntityManagerFactories/MyEntityManagerFactory"))).getEntityManager();
em.getTransaction().begin() ;
} catch ( Exception Ex ) {
Ex.printStackTrace();
}
%>
... and some other validation code not relevant to this issue. The connection is as follows:
<datasources> <local-tx-datasource> <jndi-name>MyJNDIName</jndi-name> <connection-url>jdbc:postgresql://localhost/ejb3</connection-url> <driver-class>org.postgresql.Driver</driver-class> <user-name>ejb3</user-name> <password>xxxxxxx</password> <max-pool-size>20</max-pool-size><!-- max was 200 when problem came up --!> <min-pool-size>1</min-pool-size> <idle-timeout-minutes>1</idle-timeout-minutes> </local-tx-datasource> </datasources>
The datasource is configured to hold 200 connection, I've lowered the limit to 20 to reproduce this issue faster, the problem is:
Whenever I make a request, an EntityManager is fetched from the EntityManagerFactory within Namig Context, then if I try to close the EM an exception arises that forbids JTA-bound EntityManager to be closed, so I cannot close within code, must be ContainerManaged, however connections are not being released, instead new ones are being created every time.
There is however this warning, wich auto_close and auto_flush on persistence.xml used to do the trick:
2006-01-25 14:00:15,169 WARN [org.hibernate.jdbc.ConnectionManager] unclosed connection, forgot to call close() on your session?
persistence.xml:
<entity-manager> <name>MyEntityManagerFactory</name> <jta-data-source>java:/MyJNDIName</jta-data-source> <properties> <property name="hibernate.hbm2ddl.auto" value="update" /> <property name="hibernate.default_schema" value="public" /> <property name="transaction.flush_before_completion" value="true" /> <property name="connection.release_mode">auto</property> <property name="transaction.manager_lookup_class">org.hibernate.transaction.JBossTransactionManagerLookup</property> <property name="transaction.factory_class">org.hibernate.transaction.JTATransactionFactory</property> <property name="hibernate.transaction.flush_before_completion" value="true" /> <property name="hibernate.transaction.auto_close_session" value="true" /> <property name="hibernate.connection.pool_size" value="10" /> <property name="hibernate.connection.autocommit" value="true" /> </properties> </entity-manager>
Some old logs from the server have this line:
2005-12-02 22:00:16,559 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection
while most recent logs show this line:
2006-01-25 12:57:19,687 INFO [org.hibernate.jdbc.ConnectionManager] Skipping aggresive-release due to open resources on batcher
Checking the server processes running there are several connections to postgres while all of them are idle, new querys open new connections, wich eventually come up to max-pool-size and are then dennied. Connections seem to be idle, yet they are not being reused
This other line comes up every once in a while, yet it does not remove idle connections.
2006-01-25 15:51:48,846 DEBUG [org.jboss.resource.connectionmanager.IdleRemover] run: IdleRemover notifying pools, interval: 30000
It apparently only notifies pool to do it's thing, wich it doesnt.
I've been trying different configurations for persistence.xml, diferent configurations for my datasource, diferent forms of retrieving the EntityManager, JTA-bound and ApplicationManaged (wich I close at the end of jsp execution), running within transaction or without one, tryed downloading newest hibernate, older hibernate, recompiling hibernate, while this issue seems to be on ConnectionManager I won't discard any possibilities of it being my mistake. As far as the documentation says I believe I'm doing things right.
Please, can you see anything wrong here ? Anyone ?
Even google has not been able to help me this time :S
I'm aware there is a lot of data here to be procesed, but I would really be thankful if someone helps me out to find wether is it my fault or is it something in hibernate or even jBoss.
----------------------
Running:
jBoss 4.0.3SP1
Hibernate 3.1.1
Debian GNU/Linux
Xeon Dual
PostgreSQL
(Been tested on other local servers with same results)
