PDA

View Full Version : DB connections not released back to pool using Hibernate


erlendfg
08-24-2010, 02:36 PM
When I enable the spy tag in Resin's connection pool for debugging the database connections, I see that connections are never released back to the pool. They will remain open until timeout.

Our application uses Struts 2, Hibernate 3.3.2ga and runs on Resin 3.0.26. I have also tested the application on Resin 4.0.9 without any luck. The version which is now in production uses c3po instead, but we really want to switch to Resin's own connection pool since it is more reliable and stable when the database is down for maintenance.

I was expecting that the connections were released back to the pool when calling session.close(), but they still remain open.

We have an interceptor in Struts 2 which is called at the end of the request, and it will close the Hibernate session. The relevant classes are shown below. Please note that some methods are disabled at the moment since we are migrating from WebWork to Struts 2.


public class HibernateCloseInterceptor implements Interceptor {

private static final long serialVersionUID = 3393621813249316358L;
private static Logger logger = Logger.getLogger(HibernateCloseInterceptor.class);


public void init() {
}


public void destroy() {
}


public String intercept(ActionInvocation invocation) throws Exception {

try {
// Prosess the request.
Object result = invocation.invoke();

// Close Hibernate used with this request.
HibernateUtil.commitTransaction();
return (String) result;
} finally {
HibernateUtil.closeSession();
}
}

}



package no.uio.webapps.pay.util;

import java.io.FileInputStream;
import java.sql.Connection;
import java.util.Properties;

import no.uio.webapps.pay.exceptions.InfrastructureExcept ion;

import org.apache.log4j.Logger;
import org.hibernate.HibernateException;
import org.hibernate.SessionFactory;
import org.hibernate.Transaction;
import org.hibernate.cfg.AnnotationConfiguration;
import org.hibernate.classic.Session;

public class HibernateUtil {

private static final SessionFactory sessionFactory;
private static Logger logger = Logger.getLogger(HibernateUtil.class);

static {
try {

// Determine which hibernate configuration file to use:
FileInputStream hibernateFileInputStream;

String filename = ConfigUtil.getAppConfPath();
if (!filename.endsWith("properties")) {
filename = filename + "hibernate.properties";
}
logger.info("Resetting hibernate from: " + filename + "\n");

hibernateFileInputStream = new FileInputStream(filename);
// logger.info("DEBUG: bytes:" + hibernateFileInputStream.available() );

// Reads the hibernate properties from file.
Properties hibProperties = new Properties();
hibProperties.load(hibernateFileInputStream);

AnnotationConfiguration cfg = new AnnotationConfiguration();

cfg.setProperties(hibProperties);
cfg.configure();

sessionFactory = cfg.buildSessionFactory();

} catch (Throwable ex) {
// Make sure you log the exception, as it might be swallowed
System.err.println("Initial SessionFactory creation failed." + ex);
throw new ExceptionInInitializerError(ex);
}
}


public static SessionFactory getSessionFactory() {
return sessionFactory;
}


public static Session getSession() {
Session session = getSessionFactory().getCurrentSession();
Transaction transaction = session.getTransaction();

try {
if (!transaction.isActive()) {
session.beginTransaction();

logger.info("Starting new transaction");
} else {
logger.info("Transaction in progress, returning only the current session");
}
} catch (HibernateException e) {
logger.warn("Exception occured in 'beginTransaction'.", e);
throw new InfrastructureException(e);
}
return session;
}


public static Connection getConnection() {
try {
return getSession().connection();
} catch (HibernateException e) {
logger.warn("Exception occured in 'getConnection'.", e);
throw new InfrastructureException(e);
}
}


public static void rollbackTransaction() {
try {
getSession().getTransaction().rollback();
} catch (HibernateException e) {
logger.warn("Exception occured in 'rollbackTransaction'.", e);
throw new InfrastructureException(e);
}
}


public static void commitTransaction() {
try {
getSession().getTransaction().commit();
} catch (HibernateException e) {
logger.warn("Exception occured in 'commitTransaction'.", e);
rollbackTransaction();
throw new InfrastructureException(e);
}
}


public static void beginTransaction() {
// Transaction transaction = getSession().getTransaction();
// try {
// if (transaction == null) {
// transaction = getSession().beginTransaction();
// }
// } catch (HibernateException e) {
// logger.warn("Exception occured in 'beginTransaction'.", e);
// throw new InfrastructureException(e);
// }
}


public static void closeSession() {
Session session = getSession();
try {
if (session != null && session.isOpen()) {
session.close();
}
} catch (HibernateException e) {
logger.warn("Exception occured in 'closeSession'.", e);
throw new InfrastructureException(e);
}
}

}

emil
08-24-2010, 04:46 PM
Hi,

I was expecting that the connections were released back to the pool when calling session.close(), but they still remain open.

I'm not sure what you mean... the connections (i.e. the TCP connection) should remain open until timeout. Do you mean that connections are opened once, then never used again and only die at timeout? That should mean that the number of connections grows pretty fast. Resin should be returning the connections to the pool at the end of each request. If you could provide the logs you mentioned, that might help as well.

Thanks,
Emil

erlendfg
08-25-2010, 01:23 PM
Yes, it seems that they are opened once and not reused. The number of connections are growing fast and suddenly we get an exception such as: "Closing dangling connections. All connections must have a close() in a finally block".

I'm just posting the log from Resin 4.0.9 Professional. I do have logs for 3.0.26 as well. The first part of the log is from the first request. Then I'm doing a lot of other requests which is not shown in the log - just for showing that the connections are not reused. So take a look at the end, where all the connections are released at max-idle-time:


[2010-08-25 15:05:57.590] {main} ProResin[id=pay-2] started in 4383ms
[2010-08-25 15:06:09.201] {server://127.0.0.1:6861-2} jdbc/epay.0:getMetaData() -> oracle.jdbc.driver.OracleDatabaseMetaData
[2010-08-25 15:06:09.241] {server://127.0.0.1:6861-2} jdbc/epay.0:clearWarnings()
[2010-08-25 15:06:09.976] {server://127.0.0.1:6861-2} jdbc/epay.0:getAutoCommit() -> true
[2010-08-25 15:06:09.976] {server://127.0.0.1:6861-2} jdbc/epay.0:setAutoCommit(false)
[2010-08-25 15:06:10.143] {server://127.0.0.1:6861-2} jdbc/epay.0.0:prepareStatement(select country0_.COUNTRY_CODE as col_0_0_ from COUNTRY country0_ where country0_.COUNTRY_CODE=?)
[2010-08-25 15:06:10.258] {server://127.0.0.1:6861-2} jdbc/epay.0.0:setString(1,NO)
[2010-08-25 15:06:10.258] {server://127.0.0.1:6861-2} jdbc/epay.0.0:executeQuery(select country0_.COUNTRY_CODE as col_0_0_ from COUNTRY country0_ where country0_.COUNTRY_CODE=?)
[2010-08-25 15:06:10.272] {server://127.0.0.1:6861-2} jdbc/epay.0.1:prepareStatement(select country0_.COUNTRY_CODE as COUNTRY1_7_0_, country0_.NAME as NAME7_0_ from COUNTRY country0_ where country0_.COUNTRY_CODE=?)
[2010-08-25 15:06:10.272] {server://127.0.0.1:6861-2} jdbc/epay.0.1:setString(1,NO)
[2010-08-25 15:06:10.272] {server://127.0.0.1:6861-2} jdbc/epay.0.1:executeQuery(select country0_.COUNTRY_CODE as COUNTRY1_7_0_, country0_.NAME as NAME7_0_ from COUNTRY country0_ where country0_.COUNTRY_CODE=?)
[2010-08-25 15:06:10.278] {server://127.0.0.1:6861-2} jdbc/epay.0.1:getMaxRows() -> 0
[2010-08-25 15:06:10.278] {server://127.0.0.1:6861-2} jdbc/epay.0.1:getQueryTimeout() -> 0
[2010-08-25 15:06:10.278] {server://127.0.0.1:6861-2} jdbc/epay.0.1:clearParameters()
[2010-08-25 15:06:10.278] {server://127.0.0.1:6861-2} jdbc/epay.0.1:clearParameters()
[2010-08-25 15:06:10.278] {server://127.0.0.1:6861-2} jdbc/epay.0:isClosed() -> false
[2010-08-25 15:06:10.278] {server://127.0.0.1:6861-2} jdbc/epay.0:getAutoCommit() -> false
[2010-08-25 15:06:10.281] {server://127.0.0.1:6861-2} jdbc/epay.0.0:getMaxRows() -> 0
[2010-08-25 15:06:10.281] {server://127.0.0.1:6861-2} jdbc/epay.0.0:getQueryTimeout() -> 0
[2010-08-25 15:06:10.281] {server://127.0.0.1:6861-2} jdbc/epay.0.0:clearParameters()
[2010-08-25 15:06:10.281] {server://127.0.0.1:6861-2} jdbc/epay.0.0:clearParameters()
[2010-08-25 15:06:10.282] {server://127.0.0.1:6861-2} jdbc/epay.0:isClosed() -> false
[2010-08-25 15:06:10.282] {server://127.0.0.1:6861-2} jdbc/epay.0:getAutoCommit() -> false
[2010-08-25 15:06:10.616] {server://127.0.0.1:6861-2} jdbc/epay.0:isClosed() -> false
[2010-08-25 15:06:10.616] {server://127.0.0.1:6861-2} jdbc/epay.0:getAutoCommit() -> false
[2010-08-25 15:06:10.616] {server://127.0.0.1:6861-2} jdbc/epay.0:commit()
[2010-08-25 15:06:10.617] {server://127.0.0.1:6861-2} jdbc/epay.0:setAutoCommit(true)
[2010-08-25 15:06:10.617] {server://127.0.0.1:6861-2} jdbc/epay.0:isClosed() -> false
[2010-08-25 15:06:10.619] {server://127.0.0.1:6861-2} jdbc/epay.0:getWarnings() -> null
[2010-08-25 15:06:10.619] {server://127.0.0.1:6861-2} jdbc/epay.0:clearWarnings()
[2010-08-25 15:06:10.619] {server://127.0.0.1:6861-2} jdbc/epay.0:clearWarnings()
[2010-08-25 15:06:10.623] {server://127.0.0.1:6861-2} jdbc/epay.0:getAutoCommit() -> true
[2010-08-25 15:06:10.623] {server://127.0.0.1:6861-2} jdbc/epay.0:setAutoCommit(false)
[2010-08-25 15:06:10.624] {server://127.0.0.1:6861-2} jdbc/epay.0:isClosed() -> false
[2010-08-25 15:06:10.624] {server://127.0.0.1:6861-2} jdbc/epay.0:getWarnings() -> null
[2010-08-25 15:06:10.624] {server://127.0.0.1:6861-2} jdbc/epay.0:clearWarnings()
[2010-08-25 15:06:10.624] {server://127.0.0.1:6861-2} jdbc/epay.0:rollback()
[2010-08-25 15:06:10.625] {server://127.0.0.1:6861-2} jdbc/epay.0:setAutoCommit(true)
[2010-08-25 15:06:10.625] {server://127.0.0.1:6861-2} jdbc/epay.0:clearWarnings()



[2010-08-25 15:12:22.989] {server://127.0.0.1:6861-20} jdbc/epay.1.18:close()
[2010-08-25 15:12:22.990] {server://127.0.0.1:6861-20} jdbc/epay.1.9:close()
[2010-08-25 15:12:22.990] {server://127.0.0.1:6861-20} jdbc/epay.1.8:close()
[2010-08-25 15:12:22.990] {server://127.0.0.1:6861-20} jdbc/epay.1.4:close()
[2010-08-25 15:12:22.990] {server://127.0.0.1:6861-20} jdbc/epay.1.10:close()
[2010-08-25 15:12:22.990] {server://127.0.0.1:6861-20} jdbc/epay.1.7:close()
[2010-08-25 15:12:22.990] {server://127.0.0.1:6861-20} jdbc/epay.1.6:close()
[2010-08-25 15:12:22.990] {server://127.0.0.1:6861-20} jdbc/epay.1.5:close()
[2010-08-25 15:12:22.990] {server://127.0.0.1:6861-20} jdbc/epay.1.20:close()
[2010-08-25 15:12:22.992] {server://127.0.0.1:6861-20} jdbc/epay.1.19:close()
[2010-08-25 15:12:22.992] {server://127.0.0.1:6861-20} jdbc/epay.1.17:close()
[2010-08-25 15:12:22.992] {server://127.0.0.1:6861-20} jdbc/epay.1.16:close()
[2010-08-25 15:12:22.992] {server://127.0.0.1:6861-20} jdbc/epay.1.15:close()
[2010-08-25 15:12:22.992] {server://127.0.0.1:6861-20} jdbc/epay.1.14:close()
[2010-08-25 15:12:22.992] {server://127.0.0.1:6861-20} jdbc/epay.1.13:close()
[2010-08-25 15:12:22.992] {server://127.0.0.1:6861-20} jdbc/epay.1.12:close()
[2010-08-25 15:12:22.992] {server://127.0.0.1:6861-20} jdbc/epay.1.11:close()
[2010-08-25 15:12:22.992] {server://127.0.0.1:6861-20} jdbc/epay.1.3:close()
[2010-08-25 15:12:22.992] {server://127.0.0.1:6861-20} jdbc/epay.1.2:close()
[2010-08-25 15:12:22.992] {server://127.0.0.1:6861-20} jdbc/epay.1.1:close()
[2010-08-25 15:12:22.992] {server://127.0.0.1:6861-20} jdbc/epay.1.0:close()
[/CODE]

emil
08-25-2010, 09:02 PM
Hi,

The message, "Closing dangling connections. All connections must have a close() in a finally block", is a hint that your application is not actually closing all the connections opened during the request. Resin is closing them for you, but it's something you should fix in your application. Nonetheless, it shouldn't affect the connection pool issue.

Since you're using 4.0.9, can you view the database pool in /resin-admin and check the Summary page? This should show the number of active, idle, total number of created connections, and failed connections. This might give a better picture of what's happening.

BTW, we just released 4.0.10. I don't think anything changed in the database pool code since 4.0.9, but you might be interested.

Emil

flemming
12-08-2010, 09:50 AM
Please try with

<jsp recycle-tags="false"/> in your resin-web.xml. This may be a tag reuse issue.

If that works as expected, do you mind posting a small sample that had a problem?

Thanks,