Tomcat hangs unexpectedly - Connection pool exhausted?

classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

Tomcat hangs unexpectedly - Connection pool exhausted?

Swan,Nicole
I don't recall this ever happening before, but twice today Tomcat has
hung unexpectedly.  Restarting the service got it going again, but I'd
like to fix this, if possible, so it doesn't happen again.  Both times I
was saving an item in dotCMS when it hung (first time saving an image
and the second time a template), but it seems like this is just a
coincidence.  I saw nothing out of the ordinary in the system logs or
the catalina log, but did find a lot of the following type of error in
the wrapper log.  They all seemed to be dumped around the time I
restarted the service, but the DBCP object creation times in the errors
vary from yesterday through to right before I restarted.  Oddly, these
type of errors were shown in the log around the time I did the first
restart, but there are none at the time of the second restart.
Examples:

2008/01/25 11:17:18 | DBCP object created 2008-01-24 10:11:20 by the
following code was never closed:
2008/01/25 11:17:18 | java.lang.Exception
2008/01/25 11:17:18 | at
org.apache.commons.dbcp.AbandonedTrace.setStackTrace(AbandonedTrace.java
:157)
2008/01/25 11:17:18 | at
org.apache.commons.dbcp.AbandonedObjectPool.borrowObject(AbandonedObject
Pool.java:76)
2008/01/25 11:17:18 | at
org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSourc
e.java:95)
2008/01/25 11:17:18 | at
org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.ja
va:540)
2008/01/25 11:17:18 | at
com.dotmarketing.db.DbConnectionFactory.getConnection(DbConnectionFactor
y.java:46)
2008/01/25 11:17:18 | at
com.dotmarketing.db.HibernateUtil.getSession(HibernateUtil.java:349)
2008/01/25 11:17:18 | at
com.dotmarketing.db.HibernateUtil.load(HibernateUtil.java:210)
2008/01/25 11:17:18 | at
com.dotmarketing.portlets.report.factories.ReportFactory.getReport(Repor
tFactory.java:70)
2008/01/25 11:17:18 | at
com.dotmarketing.portlets.report.action.RunReportAction.processAction(Ru
nReportAction.java:133)
2008/01/25 11:17:18 | at
com.liferay.portal.struts.PortletRequestProcessor.process(PortletRequest
Processor.java:140)
2008/01/25 11:17:18 | at
com.liferay.portlet.StrutsPortlet.processAction(StrutsPortlet.java:118)
2008/01/25 11:17:18 | at
com.liferay.portlet.CachePortlet.processAction(CachePortlet.java:131)
2008/01/25 11:17:18 | at
com.liferay.portal.action.LayoutAction._processPortletRequest(LayoutActi
on.java:222)
2008/01/25 11:17:18 | at
com.liferay.portal.action.LayoutAction._processActionRequest(LayoutActio
n.java:239)
2008/01/25 11:17:18 | at
com.liferay.portal.action.LayoutAction.execute(LayoutAction.java:93)

2008/01/25 11:20:19 | DBCP object created 2008-01-25 11:16:50 by the
following code was never closed:
2008/01/25 11:20:19 | java.lang.Exception
2008/01/25 11:20:19 | at
org.apache.commons.dbcp.AbandonedTrace.init(AbandonedTrace.java:96)
2008/01/25 11:20:19 | at
org.apache.commons.dbcp.AbandonedTrace.<init>(AbandonedTrace.java:79)
2008/01/25 11:20:19 | at
org.apache.commons.dbcp.DelegatingResultSet.<init>(DelegatingResultSet.j
ava:71)
2008/01/25 11:20:19 | at
org.apache.commons.dbcp.DelegatingResultSet.wrapResultSet(DelegatingResu
ltSet.java:80)
2008/01/25 11:20:19 | at
org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(Delegat
ingPreparedStatement.java:92)
2008/01/25 11:20:19 | at
net.sf.hibernate.impl.BatcherImpl.getResultSet(BatcherImpl.java:83)
2008/01/25 11:20:19 | at
net.sf.hibernate.loader.Loader.getResultSet(Loader.java:794)
2008/01/25 11:20:19 | at
net.sf.hibernate.loader.Loader.doQuery(Loader.java:188)
2008/01/25 11:20:19 | at
net.sf.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Lo
ader.java:132)
2008/01/25 11:20:19 | at
net.sf.hibernate.loader.Loader.doList(Loader.java:949)
2008/01/25 11:20:19 | at
net.sf.hibernate.loader.Loader.list(Loader.java:940)
2008/01/25 11:20:19 | at
net.sf.hibernate.hql.QueryTranslator.list(QueryTranslator.java:833)
2008/01/25 11:20:19 | at
net.sf.hibernate.impl.SessionImpl.find(SessionImpl.java:1475)
2008/01/25 11:20:19 | at
net.sf.hibernate.impl.QueryImpl.list(QueryImpl.java:39)
2008/01/25 11:20:19 | at
com.dotmarketing.db.DotHibernate.load(DotHibernate.java:311)
2008/01/25 11:20:19 | at
com.dotmarketing.factories.InodeFactory.getInodeOfClassByCondition(Inode
Factory.java:766)
2008/01/25 11:20:19 | at
com.csu.factories.CourseFactory.getCourseByCourseNumber(CourseFactory.ja
va:54)
2008/01/25 11:20:19 | at
com.csu.filters.CoursesFilter.doFilter(CoursesFilter.java:90)

My working theory is that the connection pool was exhausted by such
instances where connections weren't closed properly.  I will be looking
at fixing the specific classes shown in these log errors, however, that
doesn't explain why this has only happened today (that I can recall).
Also, further weakening my theory, our connection pool is set to remove
abandoned connections after 20 seconds (and to log them).

Is my theory completely off base?  Is there something else I should be
looking at?

Thanks!

--Nicole
-------------------------------
Nicole Swan
Web Designer/Programmer
Continuing Education
Colorado State University

(970) 491-3835
www.learn.colostate.edu


dotCMS: Opensource CMS goodness.
http://www.dotcms.org 
Yahoo! Groups Links

<*> To visit your group on the web, go to:
    http://groups.yahoo.com/group/dotcms/

<*> Your email settings:
    Individual Email | Traditional

<*> To change settings online go to:
    http://groups.yahoo.com/group/dotcms/join
    (Yahoo! ID required)

<*> To change settings via email:
    mailto:[hidden email]
    mailto:[hidden email]

<*> To unsubscribe from this group, send an email to:
    [hidden email]

<*> Your use of Yahoo! Groups is subject to:
    http://docs.yahoo.com/info/terms/
 
Reply | Threaded
Open this post in threaded view
|

Re: Tomcat hangs unexpectedly - Connection pool exhausted?

Maria Ahues Bouza
Nicole,

It seems that somewhere in a report that's running the db connection is not
being closed.

com.dotmarketing.portlets.report.factories.ReportFactory.getReport(Repor

tFactory.java:70)


Thanks
Maria

On 1/25/08, Swan,Nicole <[hidden email]> wrote:

>
>   I don't recall this ever happening before, but twice today Tomcat has
> hung unexpectedly. Restarting the service got it going again, but I'd
> like to fix this, if possible, so it doesn't happen again. Both times I
> was saving an item in dotCMS when it hung (first time saving an image
> and the second time a template), but it seems like this is just a
> coincidence. I saw nothing out of the ordinary in the system logs or
> the catalina log, but did find a lot of the following type of error in
> the wrapper log. They all seemed to be dumped around the time I
> restarted the service, but the DBCP object creation times in the errors
> vary from yesterday through to right before I restarted. Oddly, these
> type of errors were shown in the log around the time I did the first
> restart, but there are none at the time of the second restart.
> Examples:
>
> 2008/01/25 11:17:18 | DBCP object created 2008-01-24 10:11:20 by the
> following code was never closed:
> 2008/01/25 11:17:18 | java.lang.Exception
> 2008/01/25 11:17:18 | at
> org.apache.commons.dbcp.AbandonedTrace.setStackTrace(AbandonedTrace.java
> :157)
> 2008/01/25 11:17:18 | at
> org.apache.commons.dbcp.AbandonedObjectPool.borrowObject(AbandonedObject
> Pool.java:76)
> 2008/01/25 11:17:18 | at
> org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSourc
> e.java:95)
> 2008/01/25 11:17:18 | at
> org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.ja
> va:540)
> 2008/01/25 11:17:18 | at
> com.dotmarketing.db.DbConnectionFactory.getConnection(DbConnectionFactor
> y.java:46)
> 2008/01/25 11:17:18 | at
> com.dotmarketing.db.HibernateUtil.getSession(HibernateUtil.java:349)
> 2008/01/25 11:17:18 | at
> com.dotmarketing.db.HibernateUtil.load(HibernateUtil.java:210)
> 2008/01/25 11:17:18 | at
> com.dotmarketing.portlets.report.factories.ReportFactory.getReport(Repor
> tFactory.java:70)
> 2008/01/25 11:17:18 | at
> com.dotmarketing.portlets.report.action.RunReportAction.processAction(Ru
> nReportAction.java:133)
> 2008/01/25 11:17:18 | at
> com.liferay.portal.struts.PortletRequestProcessor.process(PortletRequest
> Processor.java:140)
> 2008/01/25 11:17:18 | at
> com.liferay.portlet.StrutsPortlet.processAction(StrutsPortlet.java:118)
> 2008/01/25 11:17:18 | at
> com.liferay.portlet.CachePortlet.processAction(CachePortlet.java:131)
> 2008/01/25 11:17:18 | at
> com.liferay.portal.action.LayoutAction._processPortletRequest(LayoutActi
> on.java:222)
> 2008/01/25 11:17:18 | at
> com.liferay.portal.action.LayoutAction._processActionRequest(LayoutActio
> n.java:239)
> 2008/01/25 11:17:18 | at
> com.liferay.portal.action.LayoutAction.execute(LayoutAction.java:93)
>
> 2008/01/25 11:20:19 | DBCP object created 2008-01-25 11:16:50 by the
> following code was never closed:
> 2008/01/25 11:20:19 | java.lang.Exception
> 2008/01/25 11:20:19 | at
> org.apache.commons.dbcp.AbandonedTrace.init(AbandonedTrace.java:96)
> 2008/01/25 11:20:19 | at
> org.apache.commons.dbcp.AbandonedTrace.<init>(AbandonedTrace.java:79)
> 2008/01/25 11:20:19 | at
> org.apache.commons.dbcp.DelegatingResultSet.<init>(DelegatingResultSet.j
> ava:71)
> 2008/01/25 11:20:19 | at
> org.apache.commons.dbcp.DelegatingResultSet.wrapResultSet(DelegatingResu
> ltSet.java:80)
> 2008/01/25 11:20:19 | at
> org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(Delegat
> ingPreparedStatement.java:92)
> 2008/01/25 11:20:19 | at
> net.sf.hibernate.impl.BatcherImpl.getResultSet(BatcherImpl.java:83)
> 2008/01/25 11:20:19 | at
> net.sf.hibernate.loader.Loader.getResultSet(Loader.java:794)
> 2008/01/25 11:20:19 | at
> net.sf.hibernate.loader.Loader.doQuery(Loader.java:188)
> 2008/01/25 11:20:19 | at
> net.sf.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Lo
> ader.java:132)
> 2008/01/25 11:20:19 | at
> net.sf.hibernate.loader.Loader.doList(Loader.java:949)
> 2008/01/25 11:20:19 | at
> net.sf.hibernate.loader.Loader.list(Loader.java:940)
> 2008/01/25 11:20:19 | at
> net.sf.hibernate.hql.QueryTranslator.list(QueryTranslator.java:833)
> 2008/01/25 11:20:19 | at
> net.sf.hibernate.impl.SessionImpl.find(SessionImpl.java:1475)
> 2008/01/25 11:20:19 | at
> net.sf.hibernate.impl.QueryImpl.list(QueryImpl.java:39)
> 2008/01/25 11:20:19 | at
> com.dotmarketing.db.DotHibernate.load(DotHibernate.java:311)
> 2008/01/25 11:20:19 | at
> com.dotmarketing.factories.InodeFactory.getInodeOfClassByCondition(Inode
> Factory.java:766)
> 2008/01/25 11:20:19 | at
> com.csu.factories.CourseFactory.getCourseByCourseNumber(CourseFactory.ja
> va:54)
> 2008/01/25 11:20:19 | at
> com.csu.filters.CoursesFilter.doFilter(CoursesFilter.java:90)
>
> My working theory is that the connection pool was exhausted by such
> instances where connections weren't closed properly. I will be looking
> at fixing the specific classes shown in these log errors, however, that
> doesn't explain why this has only happened today (that I can recall).
> Also, further weakening my theory, our connection pool is set to remove
> abandoned connections after 20 seconds (and to log them).
>
> Is my theory completely off base? Is there something else I should be
> looking at?
>
> Thanks!
>
> --Nicole
> -------------------------------
> Nicole Swan
> Web Designer/Programmer
> Continuing Education
> Colorado State University
>
> (970) 491-3835
> www.learn.colostate.edu
>  
>



--
Maria Ahues Bouza
Project Manager, dotCMS Services & Support

www.dotmarketing.com
www.dotcms.org
T: 305.858.1422 x (9) 272
D: 786.594.5272
F: 786.594.5288
Reply | Threaded
Open this post in threaded view
|

RE: Tomcat hangs unexpectedly - Connection pool exhausted?

Swan,Nicole
Thanks for the reply, Maria.  I've noticed the same problem, and I will be going through the abandoned connections logged to look at fixing the different classes that appear to be abandoning connections.  However, what confounds me a bit is why this just happened to be a problem yesterday.   The connection pool is configured to remove abandoned connections after 20 seconds, so it seems like these connections should be getting cleaned up.  I'm also curious why all these errors were dumped during the first restart, but not the second.


--Nicole


-----Original Message-----
From: [hidden email] on behalf of Maria Bouza
Sent: Fri 1/25/2008 5:36 PM
To: [hidden email]
Subject: Re: [dotcms] Tomcat hangs unexpectedly - Connection pool exhausted?
 
Nicole,

It seems that somewhere in a report that's running the db connection is not
being closed.

com.dotmarketing.portlets.report.factories.ReportFactory.getReport(Repor

tFactory.java:70)


Thanks
Maria

On 1/25/08, Swan,Nicole <[hidden email]> wrote:

>
>   I don't recall this ever happening before, but twice today Tomcat has
> hung unexpectedly. Restarting the service got it going again, but I'd
> like to fix this, if possible, so it doesn't happen again. Both times I
> was saving an item in dotCMS when it hung (first time saving an image
> and the second time a template), but it seems like this is just a
> coincidence. I saw nothing out of the ordinary in the system logs or
> the catalina log, but did find a lot of the following type of error in
> the wrapper log. They all seemed to be dumped around the time I
> restarted the service, but the DBCP object creation times in the errors
> vary from yesterday through to right before I restarted. Oddly, these
> type of errors were shown in the log around the time I did the first
> restart, but there are none at the time of the second restart.
> Examples:
>
> 2008/01/25 11:17:18 | DBCP object created 2008-01-24 10:11:20 by the
> following code was never closed:
> 2008/01/25 11:17:18 | java.lang.Exception
> 2008/01/25 11:17:18 | at
> org.apache.commons.dbcp.AbandonedTrace.setStackTrace(AbandonedTrace.java
> :157)
> 2008/01/25 11:17:18 | at
> org.apache.commons.dbcp.AbandonedObjectPool.borrowObject(AbandonedObject
> Pool.java:76)
> 2008/01/25 11:17:18 | at
> org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSourc
> e.java:95)
> 2008/01/25 11:17:18 | at
> org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.ja
> va:540)
> 2008/01/25 11:17:18 | at
> com.dotmarketing.db.DbConnectionFactory.getConnection(DbConnectionFactor
> y.java:46)
> 2008/01/25 11:17:18 | at
> com.dotmarketing.db.HibernateUtil.getSession(HibernateUtil.java:349)
> 2008/01/25 11:17:18 | at
> com.dotmarketing.db.HibernateUtil.load(HibernateUtil.java:210)
> 2008/01/25 11:17:18 | at
> com.dotmarketing.portlets.report.factories.ReportFactory.getReport(Repor
> tFactory.java:70)
> 2008/01/25 11:17:18 | at
> com.dotmarketing.portlets.report.action.RunReportAction.processAction(Ru
> nReportAction.java:133)
> 2008/01/25 11:17:18 | at
> com.liferay.portal.struts.PortletRequestProcessor.process(PortletRequest
> Processor.java:140)
> 2008/01/25 11:17:18 | at
> com.liferay.portlet.StrutsPortlet.processAction(StrutsPortlet.java:118)
> 2008/01/25 11:17:18 | at
> com.liferay.portlet.CachePortlet.processAction(CachePortlet.java:131)
> 2008/01/25 11:17:18 | at
> com.liferay.portal.action.LayoutAction._processPortletRequest(LayoutActi
> on.java:222)
> 2008/01/25 11:17:18 | at
> com.liferay.portal.action.LayoutAction._processActionRequest(LayoutActio
> n.java:239)
> 2008/01/25 11:17:18 | at
> com.liferay.portal.action.LayoutAction.execute(LayoutAction.java:93)
>
> 2008/01/25 11:20:19 | DBCP object created 2008-01-25 11:16:50 by the
> following code was never closed:
> 2008/01/25 11:20:19 | java.lang.Exception
> 2008/01/25 11:20:19 | at
> org.apache.commons.dbcp.AbandonedTrace.init(AbandonedTrace.java:96)
> 2008/01/25 11:20:19 | at
> org.apache.commons.dbcp.AbandonedTrace.<init>(AbandonedTrace.java:79)
> 2008/01/25 11:20:19 | at
> org.apache.commons.dbcp.DelegatingResultSet.<init>(DelegatingResultSet.j
> ava:71)
> 2008/01/25 11:20:19 | at
> org.apache.commons.dbcp.DelegatingResultSet.wrapResultSet(DelegatingResu
> ltSet.java:80)
> 2008/01/25 11:20:19 | at
> org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(Delegat
> ingPreparedStatement.java:92)
> 2008/01/25 11:20:19 | at
> net.sf.hibernate.impl.BatcherImpl.getResultSet(BatcherImpl.java:83)
> 2008/01/25 11:20:19 | at
> net.sf.hibernate.loader.Loader.getResultSet(Loader.java:794)
> 2008/01/25 11:20:19 | at
> net.sf.hibernate.loader.Loader.doQuery(Loader.java:188)
> 2008/01/25 11:20:19 | at
> net.sf.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Lo
> ader.java:132)
> 2008/01/25 11:20:19 | at
> net.sf.hibernate.loader.Loader.doList(Loader.java:949)
> 2008/01/25 11:20:19 | at
> net.sf.hibernate.loader.Loader.list(Loader.java:940)
> 2008/01/25 11:20:19 | at
> net.sf.hibernate.hql.QueryTranslator.list(QueryTranslator.java:833)
> 2008/01/25 11:20:19 | at
> net.sf.hibernate.impl.SessionImpl.find(SessionImpl.java:1475)
> 2008/01/25 11:20:19 | at
> net.sf.hibernate.impl.QueryImpl.list(QueryImpl.java:39)
> 2008/01/25 11:20:19 | at
> com.dotmarketing.db.DotHibernate.load(DotHibernate.java:311)
> 2008/01/25 11:20:19 | at
> com.dotmarketing.factories.InodeFactory.getInodeOfClassByCondition(Inode
> Factory.java:766)
> 2008/01/25 11:20:19 | at
> com.csu.factories.CourseFactory.getCourseByCourseNumber(CourseFactory.ja
> va:54)
> 2008/01/25 11:20:19 | at
> com.csu.filters.CoursesFilter.doFilter(CoursesFilter.java:90)
>
> My working theory is that the connection pool was exhausted by such
> instances where connections weren't closed properly. I will be looking
> at fixing the specific classes shown in these log errors, however, that
> doesn't explain why this has only happened today (that I can recall).
> Also, further weakening my theory, our connection pool is set to remove
> abandoned connections after 20 seconds (and to log them).
>
> Is my theory completely off base? Is there something else I should be
> looking at?
>
> Thanks!
>
> --Nicole
> -------------------------------
> Nicole Swan
> Web Designer/Programmer
> Continuing Education
> Colorado State University
>
> (970) 491-3835
> www.learn.colostate.edu
>  
>



--
Maria Ahues Bouza
Project Manager, dotCMS Services & Support

www.dotmarketing.com
www.dotcms.org
T: 305.858.1422 x (9) 272
D: 786.594.5272
F: 786.594.5288



dotCMS: Opensource CMS goodness.
http://www.dotcms.org 
Yahoo! Groups Links

<*> To visit your group on the web, go to:
    http://groups.yahoo.com/group/dotcms/

<*> Your email settings:
    Individual Email | Traditional

<*> To change settings online go to:
    http://groups.yahoo.com/group/dotcms/join
    (Yahoo! ID required)

<*> To change settings via email:
    mailto:[hidden email]
    mailto:[hidden email]

<*> To unsubscribe from this group, send an email to:
    [hidden email]

<*> Your use of Yahoo! Groups is subject to:
    http://docs.yahoo.com/info/terms/
 

winmail.dat (7K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Tomcat hangs unexpectedly - Connection pool exhausted?

Maria Ahues Bouza
Nicole,

Have you created a new report or new scheduled task to create a report, code
that might not be closing the connections?
That's all I can think of, the connection pool should remove abandoned
connections but if you have some code that is not closing connections is
easy for this to happen.
I wouldn't be able to tell you exactly what's happening until checking the
code and debugging more. These are the most difficult issues to find.

Thanks
Maria

On 1/26/08, Swan,Nicole <[hidden email]> wrote:

>
>   Thanks for the reply, Maria. I've noticed the same problem, and I will
> be going through the abandoned connections logged to look at fixing the
> different classes that appear to be abandoning connections. However, what
> confounds me a bit is why this just happened to be a problem yesterday. The
> connection pool is configured to remove abandoned connections after 20
> seconds, so it seems like these connections should be getting cleaned up.
> I'm also curious why all these errors were dumped during the first restart,
> but not the second.
>
> --Nicole
>
>
> -----Original Message-----
> From: [hidden email] <dotcms%40yahoogroups.com> on behalf of Maria
> Bouza
> Sent: Fri 1/25/2008 5:36 PM
> To: [hidden email] <dotcms%40yahoogroups.com>
> Subject: Re: [dotcms] Tomcat hangs unexpectedly - Connection pool
> exhausted?
>
> Nicole,
>
> It seems that somewhere in a report that's running the db connection is
> not
> being closed.
>
> com.dotmarketing.portlets.report.factories.ReportFactory.getReport(Repor
>
> tFactory.java:70)
>
> Thanks
> Maria
>
> On 1/25/08, Swan,Nicole <[hidden email]<nswan%40learn.colostate.edu>>
> wrote:
> >
> > I don't recall this ever happening before, but twice today Tomcat has
> > hung unexpectedly. Restarting the service got it going again, but I'd
> > like to fix this, if possible, so it doesn't happen again. Both times I
> > was saving an item in dotCMS when it hung (first time saving an image
> > and the second time a template), but it seems like this is just a
> > coincidence. I saw nothing out of the ordinary in the system logs or
> > the catalina log, but did find a lot of the following type of error in
> > the wrapper log. They all seemed to be dumped around the time I
> > restarted the service, but the DBCP object creation times in the errors
> > vary from yesterday through to right before I restarted. Oddly, these
> > type of errors were shown in the log around the time I did the first
> > restart, but there are none at the time of the second restart.
> > Examples:
> >
> > 2008/01/25 11:17:18 | DBCP object created 2008-01-24 10:11:20 by the
> > following code was never closed:
> > 2008/01/25 11:17:18 | java.lang.Exception
> > 2008/01/25 11:17:18 | at
> > org.apache.commons.dbcp.AbandonedTrace.setStackTrace(AbandonedTrace.java
> > :157)
> > 2008/01/25 11:17:18 | at
> > org.apache.commons.dbcp.AbandonedObjectPool.borrowObject(AbandonedObject
> > Pool.java:76)
> > 2008/01/25 11:17:18 | at
> > org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSourc
> > e.java:95)
> > 2008/01/25 11:17:18 | at
> > org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.ja
> > va:540)
> > 2008/01/25 11:17:18 | at
> > com.dotmarketing.db.DbConnectionFactory.getConnection(DbConnectionFactor
> > y.java:46)
> > 2008/01/25 11:17:18 | at
> > com.dotmarketing.db.HibernateUtil.getSession(HibernateUtil.java:349)
> > 2008/01/25 11:17:18 | at
> > com.dotmarketing.db.HibernateUtil.load(HibernateUtil.java:210)
> > 2008/01/25 11:17:18 | at
> > com.dotmarketing.portlets.report.factories.ReportFactory.getReport(Repor
> > tFactory.java:70)
> > 2008/01/25 11:17:18 | at
> > com.dotmarketing.portlets.report.action.RunReportAction.processAction(Ru
> > nReportAction.java:133)
> > 2008/01/25 11:17:18 | at
> > com.liferay.portal.struts.PortletRequestProcessor.process(PortletRequest
> > Processor.java:140)
> > 2008/01/25 11:17:18 | at
> > com.liferay.portlet.StrutsPortlet.processAction(StrutsPortlet.java:118)
> > 2008/01/25 11:17:18 | at
> > com.liferay.portlet.CachePortlet.processAction(CachePortlet.java:131)
> > 2008/01/25 11:17:18 | at
> > com.liferay.portal.action.LayoutAction._processPortletRequest(LayoutActi
> > on.java:222)
> > 2008/01/25 11:17:18 | at
> > com.liferay.portal.action.LayoutAction._processActionRequest(LayoutActio
> > n.java:239)
> > 2008/01/25 11:17:18 | at
> > com.liferay.portal.action.LayoutAction.execute(LayoutAction.java:93)
> >
> > 2008/01/25 11:20:19 | DBCP object created 2008-01-25 11:16:50 by the
> > following code was never closed:
> > 2008/01/25 11:20:19 | java.lang.Exception
> > 2008/01/25 11:20:19 | at
> > org.apache.commons.dbcp.AbandonedTrace.init(AbandonedTrace.java:96)
> > 2008/01/25 11:20:19 | at
> > org.apache.commons.dbcp.AbandonedTrace.<init>(AbandonedTrace.java:79)
> > 2008/01/25 11:20:19 | at
> > org.apache.commons.dbcp.DelegatingResultSet.<init>(DelegatingResultSet.j
> > ava:71)
> > 2008/01/25 11:20:19 | at
> > org.apache.commons.dbcp.DelegatingResultSet.wrapResultSet(DelegatingResu
> > ltSet.java:80)
> > 2008/01/25 11:20:19 | at
> > org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(Delegat
> > ingPreparedStatement.java:92)
> > 2008/01/25 11:20:19 | at
> > net.sf.hibernate.impl.BatcherImpl.getResultSet(BatcherImpl.java:83)
> > 2008/01/25 11:20:19 | at
> > net.sf.hibernate.loader.Loader.getResultSet(Loader.java:794)
> > 2008/01/25 11:20:19 | at
> > net.sf.hibernate.loader.Loader.doQuery(Loader.java:188)
> > 2008/01/25 11:20:19 | at
> > net.sf.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Lo
> > ader.java:132)
> > 2008/01/25 11:20:19 | at
> > net.sf.hibernate.loader.Loader.doList(Loader.java:949)
> > 2008/01/25 11:20:19 | at
> > net.sf.hibernate.loader.Loader.list(Loader.java:940)
> > 2008/01/25 11:20:19 | at
> > net.sf.hibernate.hql.QueryTranslator.list(QueryTranslator.java:833)
> > 2008/01/25 11:20:19 | at
> > net.sf.hibernate.impl.SessionImpl.find(SessionImpl.java:1475)
> > 2008/01/25 11:20:19 | at
> > net.sf.hibernate.impl.QueryImpl.list(QueryImpl.java:39)
> > 2008/01/25 11:20:19 | at
> > com.dotmarketing.db.DotHibernate.load(DotHibernate.java:311)
> > 2008/01/25 11:20:19 | at
> > com.dotmarketing.factories.InodeFactory.getInodeOfClassByCondition(Inode
> > Factory.java:766)
> > 2008/01/25 11:20:19 | at
> > com.csu.factories.CourseFactory.getCourseByCourseNumber(CourseFactory.ja
> > va:54)
> > 2008/01/25 11:20:19 | at
> > com.csu.filters.CoursesFilter.doFilter(CoursesFilter.java:90)
> >
> > My working theory is that the connection pool was exhausted by such
> > instances where connections weren't closed properly. I will be looking
> > at fixing the specific classes shown in these log errors, however, that
> > doesn't explain why this has only happened today (that I can recall).
> > Also, further weakening my theory, our connection pool is set to remove
> > abandoned connections after 20 seconds (and to log them).
> >
> > Is my theory completely off base? Is there something else I should be
> > looking at?
> >
> > Thanks!
> >
> > --Nicole
> > -------------------------------
> > Nicole Swan
> > Web Designer/Programmer
> > Continuing Education
> > Colorado State University
> >
> > (970) 491-3835
> > www.learn.colostate.edu
> >
> >
>
> --
> Maria Ahues Bouza
> Project Manager, dotCMS Services & Support
>
> www.dotmarketing.com
> www.dotcms.org
> T: 305.858.1422 x (9) 272
> D: 786.594.5272
> F: 786.594.5288
>
>  
>
>


--
Maria Ahues Bouza
Project Manager, dotCMS Services & Support

www.dotmarketing.com
www.dotcms.org
T: 305.858.1422 x (9) 272
D: 786.594.5272
F: 786.594.5288
Reply | Threaded
Open this post in threaded view
|

RE: Tomcat hangs unexpectedly - Connection pool exhausted?

Swan,Nicole
This really isn't specific to any Report class activity I was doing --
notice from the logs that the ReportFactory abandoned connection that I
originally posted as an example was created in the ReportFactory 1/24 at
10:11 AM but the first hangup occurred 1/25 at about 11:15 AM.  My logs
show abandoned connections for many dotCMS classes as well as a couple
CSU-specific classes, all dumped at the time of the first restart (but
none dumped at the time of the second restart).  As I noted, I'll be
looking to fix this code as abandoned connections certainly aren't on my
list of code "must haves," but my larger concern is getting to the
bottom of the reason for Tomcat's hangup.  It could just be a weird
fluke as I haven't had any issues since the second restart.  If anyone
has additional ideas I'm all ears.
 
--Nicole

________________________________

From: [hidden email] [mailto:[hidden email]] On Behalf
Of Maria Bouza
Sent: Monday, January 28, 2008 9:52 AM
To: [hidden email]
Subject: Re: [dotcms] Tomcat hangs unexpectedly - Connection pool
exhausted?



Nicole,

Have you created a new report or new scheduled task to create a report,
code that might not be closing the connections?
That's all I can think of, the connection pool should remove abandoned
connections but if you have some code that is not closing connections is
easy for this to happen.
I wouldn't be able to tell you exactly what's happening until checking
the code and debugging more. These are the most difficult issues to
find.

Thanks
Maria


On 1/26/08, Swan,Nicole <[hidden email]
<mailto:[hidden email]> > wrote:

        Thanks for the reply, Maria. I've noticed the same problem, and
I will be going through the abandoned connections logged to look at
fixing the different classes that appear to be abandoning connections.
However, what confounds me a bit is why this just happened to be a
problem yesterday. The connection pool is configured to remove abandoned
connections after 20 seconds, so it seems like these connections should
be getting cleaned up. I'm also curious why all these errors were dumped
during the first restart, but not the second.
       
        --Nicole

       
       
        -----Original Message-----
        From: [hidden email] <mailto:dotcms%40yahoogroups.com>
on behalf of Maria Bouza
        Sent: Fri 1/25/2008 5:36 PM
        To: [hidden email] <mailto:dotcms%40yahoogroups.com>
        Subject: Re: [dotcms] Tomcat hangs unexpectedly - Connection
pool exhausted?
       
        Nicole,
       
        It seems that somewhere in a report that's running the db
connection is not
        being closed.
       
       
com.dotmarketing.portlets.report.factories.ReportFactory.getReport(Repor
       
        tFactory.java:70)
       
        Thanks
        Maria
       
        On 1/25/08, Swan,Nicole <[hidden email]
<mailto:nswan%40learn.colostate.edu> > wrote:
        >
        > I don't recall this ever happening before, but twice today
Tomcat has
        > hung unexpectedly. Restarting the service got it going again,
but I'd
        > like to fix this, if possible, so it doesn't happen again.
Both times I
        > was saving an item in dotCMS when it hung (first time saving
an image
        > and the second time a template), but it seems like this is
just a
        > coincidence. I saw nothing out of the ordinary in the system
logs or
        > the catalina log, but did find a lot of the following type of
error in
        > the wrapper log. They all seemed to be dumped around the time
I
        > restarted the service, but the DBCP object creation times in
the errors
        > vary from yesterday through to right before I restarted.
Oddly, these
        > type of errors were shown in the log around the time I did the
first
        > restart, but there are none at the time of the second restart.
        > Examples:
        >
        > 2008/01/25 11:17:18 | DBCP object created 2008-01-24 10:11:20
by the
        > following code was never closed:
        > 2008/01/25 11:17:18 | java.lang.Exception
        > 2008/01/25 11:17:18 | at
        >
org.apache.commons.dbcp.AbandonedTrace.setStackTrace(AbandonedTrace.java
        > :157)
        > 2008/01/25 11:17:18 | at
        >
org.apache.commons.dbcp.AbandonedObjectPool.borrowObject(AbandonedObject
        > Pool.java:76)
        > 2008/01/25 11:17:18 | at
        >
org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSourc
        > e.java:95)
        > 2008/01/25 11:17:18 | at
        >
org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.ja
        > va:540)
        > 2008/01/25 11:17:18 | at
        >
com.dotmarketing.db.DbConnectionFactory.getConnection(DbConnectionFactor
        > y.java:46)
        > 2008/01/25 11:17:18 | at
        >
com.dotmarketing.db.HibernateUtil.getSession(HibernateUtil.java:349)
        > 2008/01/25 11:17:18 | at
        > com.dotmarketing.db.HibernateUtil.load(HibernateUtil.java:210)
        > 2008/01/25 11:17:18 | at
        >
com.dotmarketing.portlets.report.factories.ReportFactory.getReport(Repor
        > tFactory.java:70)
        > 2008/01/25 11:17:18 | at
        >
com.dotmarketing.portlets.report.action.RunReportAction.processAction(Ru
        > nReportAction.java:133)
        > 2008/01/25 11:17:18 | at
        >
com.liferay.portal.struts.PortletRequestProcessor.process(PortletRequest
        > Processor.java:140)
        > 2008/01/25 11:17:18 | at
        >
com.liferay.portlet.StrutsPortlet.processAction(StrutsPortlet.java:118)
        > 2008/01/25 11:17:18 | at
        >
com.liferay.portlet.CachePortlet.processAction(CachePortlet.java:131)
        > 2008/01/25 11:17:18 | at
        >
com.liferay.portal.action.LayoutAction._processPortletRequest(LayoutActi
        > on.java:222)
        > 2008/01/25 11:17:18 | at
        >
com.liferay.portal.action.LayoutAction._processActionRequest(LayoutActio
        > n.java:239)
        > 2008/01/25 11:17:18 | at
        >
com.liferay.portal.action.LayoutAction.execute(LayoutAction.java:93)
        >
        > 2008/01/25 11:20:19 | DBCP object created 2008-01-25 11:16:50
by the
        > following code was never closed:
        > 2008/01/25 11:20:19 | java.lang.Exception
        > 2008/01/25 11:20:19 | at
        >
org.apache.commons.dbcp.AbandonedTrace.init(AbandonedTrace.java:96)
        > 2008/01/25 11:20:19 | at
        >
org.apache.commons.dbcp.AbandonedTrace.<init>(AbandonedTrace.java:79)
        > 2008/01/25 11:20:19 | at
        >
org.apache.commons.dbcp.DelegatingResultSet.<init>(DelegatingResultSet.j
        > ava:71)
        > 2008/01/25 11:20:19 | at
        >
org.apache.commons.dbcp.DelegatingResultSet.wrapResultSet(DelegatingResu
        > ltSet.java:80)
        > 2008/01/25 11:20:19 | at
        >
org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(Delegat
        > ingPreparedStatement.java:92)
        > 2008/01/25 11:20:19 | at
        >
net.sf.hibernate.impl.BatcherImpl.getResultSet(BatcherImpl.java:83)
        > 2008/01/25 11:20:19 | at
        > net.sf.hibernate.loader.Loader.getResultSet(Loader.java:794)
        > 2008/01/25 11:20:19 | at
        > net.sf.hibernate.loader.Loader.doQuery(Loader.java:188)
        > 2008/01/25 11:20:19 | at
        >
net.sf.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Lo
        > ader.java:132)
        > 2008/01/25 11:20:19 | at
        > net.sf.hibernate.loader.Loader.doList(Loader.java:949)
        > 2008/01/25 11:20:19 | at
        > net.sf.hibernate.loader.Loader.list(Loader.java:940)
        > 2008/01/25 11:20:19 | at
        >
net.sf.hibernate.hql.QueryTranslator.list(QueryTranslator.java:833)
        > 2008/01/25 11:20:19 | at
        > net.sf.hibernate.impl.SessionImpl.find(SessionImpl.java:1475)
        > 2008/01/25 11:20:19 | at
        > net.sf.hibernate.impl.QueryImpl.list(QueryImpl.java:39)
        > 2008/01/25 11:20:19 | at
        > com.dotmarketing.db.DotHibernate.load(DotHibernate.java:311)
        > 2008/01/25 11:20:19 | at
        >
com.dotmarketing.factories.InodeFactory.getInodeOfClassByCondition(Inode
        > Factory.java:766)
        > 2008/01/25 11:20:19 | at
        >
com.csu.factories.CourseFactory.getCourseByCourseNumber(CourseFactory.ja
        > va:54)
        > 2008/01/25 11:20:19 | at
        > com.csu.filters.CoursesFilter.doFilter(CoursesFilter.java:90)
        >
        > My working theory is that the connection pool was exhausted by
such
        > instances where connections weren't closed properly. I will be
looking
        > at fixing the specific classes shown in these log errors,
however, that
        > doesn't explain why this has only happened today (that I can
recall).
        > Also, further weakening my theory, our connection pool is set
to remove
        > abandoned connections after 20 seconds (and to log them).
        >
        > Is my theory completely off base? Is there something else I
should be
        > looking at?
        >
        > Thanks!
        >
        > --Nicole
        > -------------------------------
        > Nicole Swan
        > Web Designer/Programmer
        > Continuing Education
        > Colorado State University
        >
        > (970) 491-3835
        > www.learn.colostate.edu <http://www.learn.colostate.edu>
        >
        >
       
       
        --
        Maria Ahues Bouza
        Project Manager, dotCMS Services & Support
       
        www.dotmarketing.com <http://www.dotmarketing.com>
        www.dotcms.org
        T: 305.858.1422 x (9) 272
        D: 786.594.5272
        F: 786.594.5288
       
       

       

       





--
Maria Ahues Bouza
Project Manager, dotCMS Services & Support

www.dotmarketing.com <http://www.dotmarketing.com>
www.dotcms.org
T: 305.858.1422 x (9) 272
D: 786.594.5272
F: 786.594.5288