[Springframework-developer] OSIV/Hibernate/DBCP under load

[Darren D. <da...@da...>]

Hi all,=20

Doing some load and stress testing on an app at a client site, we're finding
the following occurs under a certain amount of concurrent load that doesn't
seem to happen at low load levels (from the tomcat's system logs):

DBCP object created 2006-04-27 09:23:12 by the following code was never
closed:
java.lang.Exception
at
org.apache.tomcat.dbcp.dbcp.AbandonedTrace.setStackTrace(AbandonedTrace.jav=
a:157)
at
org.apache.tomcat.dbcp.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjec=
tPool.java:76)
at
org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSour=
ce.java:95)
at
org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.j=
ava:540)
at
org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getCon=
nection(LocalDataSourceConnection
Provider.java:80)
at
org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:=
298)
at
org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:1=
10)
at
org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.ja=
va:88)
at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1162)
at org.hibernate.loader.Loader.doQuery(Loader.java:390)
at
org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.j=
ava:218)
at org.hibernate.loader.Loader.doList(Loader.java:1593)
at org.hibernate.loader.Loader.list(Loader.java:1577)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:395)
at
org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:271)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:845)
at org.hibernate.impl.QueryImpl.list(QueryImpl.java:74)
at
org.springframework.orm.hibernate3.HibernateTemplate$29.doInHibernate(Hiber=
nateTemplate.java:826)
at
org.springframework.orm.hibernate3.HibernateTemplate.execute(HibernateTempl=
ate.java:365)
at
org.springframework.orm.hibernate3.HibernateTemplate.find(HibernateTemplate=
=2Ejava:817)
at
org.springframework.orm.hibernate3.HibernateTemplate.find(HibernateTemplate=
=2Ejava:809)
at
com.xxxxxxx.xxxxxxx.dao.hibernate.HibernateCurrencyDAO.getCurrencyMaps(Hibe=
rnateCurrencyDAO.java:78)
at
com.xxxxxxx.xxxxxxx.dao.hibernate.HibernateCurrencyDAO.getCurrencyByCode(Hi=
bernateCurrencyDAO.java:93)
at
com.xxxxxxx.xxxxxxx.delegate.impl.CurrencyDelegateImpl.getCurrency(Currency=
DelegateImpl.java:21)
at
com.xxxxxxx.xxxxxxx.struts.registration.helper.PaymentInfoHelper.authoriseC=
ardPayment(PaymentInfoHelper
=2Ejava:144)
at
com.xxxxxxx.xxxxxxx.struts.registration.helper.PaymentInfoHelper.goToConfir=
mationPage(PaymentInfoHelper
=2Ejava:193)
at
com.xxxxxxx.xxxxxxx.struts.registration.action.PaymentInfo.proceed(PaymentI=
nfo.java:151)
at sun.reflect.GeneratedMethodAccessor398.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImp=
l.java:25)
at java.lang.reflect.Method.invoke(Method.java:585)
at
org.apache.struts.actions.DispatchAction.dispatchMethod(DispatchAction.java=
:274)
at
org.apache.struts.actions.LookupDispatchAction.execute(LookupDispatchAction=
=2Ejava:160)
at
org.springframework.web.struts.DelegatingActionProxy.execute(DelegatingActi=
onProxy.java:106)
at
org.apache.struts.action.RequestProcessor.processActionPerform(RequestProce=
ssor.java:419)
at
org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:224)
at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1194)
at org.apache.struts.action.ActionServlet.doPost(ActionServlet.java:432)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
(remainder omitted)




additionally, the following traces occur too in the application log:

2006-04-28 13:07:54,891 ERROR [TP-Processor188][JDBCExceptionReporter:72]
Already closed.
2006-04-28 13:07:54,893 ERROR [TP-Processor188][SessionFactoryUtils:790]
Could not close Hibernate Session
org.hibernate.exception.GenericJDBCException: Cannot close connection
at
org.hibernate.exception.ErrorCodeConverter.handledNonSpecificException(Erro=
rCodeConverter.java:92)
at
org.hibernate.exception.ErrorCodeConverter.convert(ErrorCodeConverter.java:=
80)
at
org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.jav=
a:43)
at
org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.jav=
a:29)
at
org.hibernate.jdbc.ConnectionManager.closeConnection(ConnectionManager.java=
:331)
at org.hibernate.jdbc.ConnectionManager.cleanup(ConnectionManager.java:262)
at org.hibernate.jdbc.ConnectionManager.close(ConnectionManager.java:194)
at org.hibernate.impl.SessionImpl.close(SessionImpl.java:289)
at
org.springframework.orm.hibernate3.SessionFactoryUtils.doClose(SessionFacto=
ryUtils.java:787)
at
org.springframework.orm.hibernate3.SessionFactoryUtils.closeSessionOrRegist=
erDeferredClose(SessionFactoryUti
ls.java:775)
at
org.springframework.orm.hibernate3.SessionFactoryUtils.releaseSession(Sessi=
onFactoryUtils.java:748)
at
org.springframework.orm.hibernate3.support.OpenSessionInViewFilter.closeSes=
sion(OpenSessionInViewFilter.java
:258)
at
com.xxxxxxx.xxxxxxx.struts.game.action.CustomOpenSessionInViewFilter.closeS=
ession(CustomOpenSessionInVi
ewFilter.java:35)
at
org.springframework.orm.hibernate3.support.OpenSessionInViewFilter.doFilter=
Internal(OpenSessionInViewFilter.
java:184)
at
org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequest=
Filter.java:76)


The CustomOpenSessionInViewFilter just sets the flush mode to AUTO after
getting the session, and explicitly flushes it in closeSession before
delegating to super.closeSession().  Perhaps this has a bearing on it, but
I'm not sure how.

I'm wondering if Tomcat may be an issue here, but I just thought I'd check
if anyone else had come across this.

--=20
Darren Davison
Public Key: 0xDD356B0D