You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by Richard Mixon <rn...@qwest.net> on 2006/04/05 04:57:26 UTC
Diagnosing DBCP JDBC connection leak using removeAbandoned parm
Bear with me, I'll try to make this short, but want to give enough
info/background that it makes sense. Basically we are a bit confused by the
output of the DBCP logAbandoned parameter. Any help is appreciated.
Environment: We are using Tomcat 4.1.18 (for now), MySQL 4.0.18, Java
1.5.0_04-b05, all running under Linux kernel 2.4.22-1.2115.nptlsmp on a dual
Xeon dedicated server.
Anyway, we determined that we had a connection leak when our application
froze today. We obtained a thread dump and it showed that everyone of the
Tomcat threads that were running application code, were waiting to get a
connection from the DBCP pool.
Each process looked something like this in the thread dump:
"Thread-171" daemon prio=1 tid=0x8a88a528 nid=0x46e9 in Object.wait()
[0x9559f000..0x955a0700]
at java.lang.Object.wait(Native Method)
- waiting on <0x4a08cb78> (a
org.apache.commons.dbcp.AbandonedObjectPool)
at java.lang.Object.wait(Object.java:474)
at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(Unknown
Source)
- locked <0x4a08cb78> (a org.apache.commons.dbcp.AbandonedObjectPool)
at
org.apache.commons.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjectPool
.java:117)
- locked <0x4a08cb78> (a org.apache.commons.dbcp.AbandonedObjectPool)
at
org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.ja
va:110)
at
org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:3
12)
at com.acme.Connector.CreateConnection(Connector.java:56)
at com.acme.OpenMailData.insert(OpenMailData.java:282)
at com.acme.trackopenmail.doPost(trackopenmail.java:127)
at com.acme.trackopenmail.doGet(trackopenmail.java:65)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:740)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Application
FilterChain.java:247)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterCh
ain.java:193)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.ja
va:260)
at
org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invok
eNext(StandardPipeline.java:643)
at
org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:480)
at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:995)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.ja
va:191)
at
org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invok
eNext(StandardPipeline.java:643)
at
org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:480)
at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:995)
at
org.apache.catalina.core.StandardContext.invoke(StandardContext.java:2415)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:180
)
at
org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invok
eNext(StandardPipeline.java:643)
at
org.apache.catalina.valves.ErrorDispatcherValve.invoke(ErrorDispatcherValve.
java:170)
at
org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invok
eNext(StandardPipeline.java:641)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:172
)
at
org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invok
eNext(StandardPipeline.java:641)
at
org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:480)
at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:995)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java
:174)
at
org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invok
eNext(StandardPipeline.java:643)
at
org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:480)
at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:995)
at
org.apache.coyote.tomcat4.CoyoteAdapter.service(CoyoteAdapter.java:223)
at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:261)
at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:360)
at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:632)
at
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:590)
at org.apache.jk.common.SocketConnection.runIt(ChannelSocket.java:707)
at
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.jav
a:530)
at java.lang.Thread.run(Thread.java:595)
So, we decided to change our removeAbandonedTimeout to 60 (from the default
of 300 seconds) and also to supply the parameter logAbandoned=true for DBCP.
So far, this seems to have "helped" the situation, but we realize that the
real problem is that connections are not being properly closed and this is
only giving us a bit of breathing room.
The good news is that we immediately started seeing logging of "abandoned"
connections in catalina.out. This gave us a good place to start looking for
logic problems that caused the connections to not be closed.
The puzzling part is the actual message we are getting.
1) The dates look like they are from lalaland (e.g. a date of April 34,
2006 in the second line below).
Maybe I do not understand how remove abandoned is working - the timeout
is supposed to start once a
connection is determined to be "idle".
2) Second the abandoned objects do not appear to be in order - they jump
from 10:23 to 13:34, 13:01,
13:35, back to 10:29 (see below).
Here is an extract/grep from our catalina.out:
DBCP object created 2006-23-04 10:23:35 by the following code was never
closed:
DBCP object created 2006-34-04 13:34:55 by the following code was never
closed:
DBCP object created 2006-01-04 13:01:49 by the following code was never
closed:
DBCP object created 2006-35-04 13:35:00 by the following code was never
closed:
DBCP object created 2006-29-04 10:29:21 by the following code was never
closed:
DBCP object created 2006-36-04 13:36:39 by the following code was never
closed:
DBCP object created 2006-23-04 10:23:35 by the following code was never
closed:
DBCP object created 2006-36-04 13:36:43 by the following code was never
closed:
DBCP object created 2006-01-04 13:01:49 by the following code was never
closed:
DBCP object created 2006-36-04 13:36:56 by the following code was never
closed:
DBCP object created 2006-40-04 13:40:30 by the following code was never
closed:
DBCP object created 2006-15-04 15:15:02 by the following code was never
closed:
DBCP object created 2006-15-04 15:15:02 by the following code was never
closed:
DBCP object created 2006-11-04 14:11:46 by the following code was never
closed:
DBCP object created 2006-00-04 16:00:01 by the following code was never
closed:
DBCP object created 2006-00-04 16:00:01 by the following code was never
closed:
DBCP object created 2006-39-04 13:39:55 by the following code was never
closed:
DBCP object created 2006-00-04 16:00:02 by the following code was never
closed:
DBCP object created 2006-00-04 16:00:02 by the following code was never
closed:
DBCP object created 2006-11-04 14:11:46 by the following code was never
closed:
DBCP object created 2006-26-04 16:26:18 by the following code was never
closed:
DBCP object created 2006-26-04 16:26:18 by the following code was never
closed:
DBCP object created 2006-26-04 16:26:18 by the following code was never
closed:
And, here's the relevant portion of our server.xml:
<Host name="acme.com" debug="0" autoDeploy="false"
appBase="/home/httpd/vhosts/acme.com">
<Alias>www.acme.com</Alias>
<Logger className="org.apache.catalina.logger.FileLogger"
directory="logs" prefix="acme.com_log."
suffix=".txt"
timestamp="true"/>
<Context path="" docBase="httpdocs" reloadable="true" debug="0">
<Resource name="jdbc/acme.com" auth="Container"
type="javax.sql.DataSource"/>
<ResourceParams name="jdbc/acme.com">
<parameter>
<name>url</name>
<value>jdbc:mysql://localhost/acme?autoReconnect=true&zeroDateTimeBehavi
or=convertToNull&noDatetimeStringSync=true</value>
</parameter>
<parameter>
<name>driverClassName</name>
<value>com.mysql.jdbc.Driver</value>
</parameter>
<parameter>
<name>username</name>
<value>acme</value>
</parameter>
<parameter>
<name>password</name>
<value>secret</value>
</parameter>
<parameter>
<name>removeAbandoned</name>
<value>true</value>
</parameter>
<parameter>
<name>removeAbandonedTimeout</name>
<value>60</value>
</parameter>
<parameter>
<name>logAbandoned</name>
<value>true</value>
</parameter>
</ResourceParams>
</Context>
</Host>
What is stranger, is that when we inspect the code, its not clear to us how
the connection could not be closed - we have a finally block that should do
this. Here is a complete message from the log, followed by the offending
code:
DBCP object created 2006-26-04 16:26:18 by the following code was never
closed:
java.lang.Exception
at org.apache.commons.dbcp.AbandonedTrace.init(AbandonedTrace.java:139)
at
org.apache.commons.dbcp.AbandonedTrace.<init>(AbandonedTrace.java:122)
at
org.apache.commons.dbcp.DelegatingStatement.<init>(DelegatingStatement.java:
101)
at
org.apache.commons.dbcp.DelegatingConnection.createStatement(DelegatingConne
ction.java:172)
at com.acme.trackopenmail.doPost(trackopenmail.java:155)
at com.acme.trackopenmail.doGet(trackopenmail.java:65)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:740)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)
at
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(Application
FilterChain.java:247)
at
org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterCh
ain.java:193)
at
org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.ja
va:260)
at
org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invok
eNext(StandardPipeline.java:643)
at
org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:480)
at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:995)
at
org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.ja
va:191)
at
org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invok
eNext(StandardPipeline.java:643)
at
org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:480)
at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:995)
at
org.apache.catalina.core.StandardContext.invoke(StandardContext.java:2415)
at
org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:180
)
at
org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invok
eNext(StandardPipeline.java:643)
at
org.apache.catalina.valves.ErrorDispatcherValve.invoke(ErrorDispatcherValve.
java:170)
at
org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invok
eNext(StandardPipeline.java:641)
at
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:172
)
at
org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invok
eNext(StandardPipeline.java:641)
at
org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:480)
at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:995)
at
org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java
:174)
at
org.apache.catalina.core.StandardPipeline$StandardPipelineValveContext.invok
eNext(StandardPipeline.java:643)
at
org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:480)
at org.apache.catalina.core.ContainerBase.invoke(ContainerBase.java:995)
at
org.apache.coyote.tomcat4.CoyoteAdapter.service(CoyoteAdapter.java:223)
at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:261)
at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:360)
at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:632)
at
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:590)
at org.apache.jk.common.SocketConnection.runIt(ChannelSocket.java:707)
at
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.jav
a:530)
at java.lang.Thread.run(Thread.java:595)
Here is the code from the doPost method:
...
Connection conn = new Connector().CreateConnection();
Statement stmt=null;
ResultSet rset=null;
try {
String open_total = "-100";
stmt = conn.createStatement();
rset = stmt.executeQuery ("select count(OPEN_MAIL_MEMBER_ID) from
OPEN_MAIL where OPEN_MAIL_MEMBER_ID="+memberid);
while (rset.next()) {
open_total = rset.getString(1);
}
stmt = conn.createStatement();
stmt.executeUpdate ("update EMAIL_ADDR set
OPEN_MAIL_TOTAL="+open_total+" where EMAIL_ADDR_ID="+memberid);
} catch (Exception e) {
SharedUtilities.logError(e);
} finally {
try {
rset.close();
stmt.close();
conn.close();
} catch (Exception e) {
SharedUtilities.logError(e);
}
}
...
BTW, the customer is moving to Tomcat 5.5.16 as soon as possible, but that's
a different story.
Thank you - Richard
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Diagnosing DBCP JDBC connection leak using removeAbandoned parm - short version
Posted by Mark Lai <ma...@gmail.com>.
#1 Could be a logging bug. Notice how the day is always the same as the
minute.
On 4/5/06, Richard Mixon <rn...@qwest.net> wrote:
>
> I'm still curious about the crazy logAbandoned messages - not sure how to
> interpret or rely on them. I'll try a again with a briefer posting - maybe
> I
> was too detailed in the original post.
>
> We are getting strange (erroneous?) messages because of the logAbandoned
> parameter:
>
> 1) The dates look like they are from lalaland (e.g. a date of
> April 34,2006 in the second line below).
> Maybe I do not understand how remove abandoned is working - the
> timeout is supposed to start once a connection is determined to be
> "idle".
> 2) Second the abandoned objects do not appear to be in order -
> they jump from 10:23 to 13:34, 13:01, 13:35, back to 10:29 (see
> below).
>
> Here is an extract/grep from our catalina.out:
> DBCP object created 2006-23-04 10:23:35 by the following code was never
> closed:
> DBCP object created 2006-34-04 13:34:55 by the following code was never
> closed:
> DBCP object created 2006-01-04 13:01:49 by the following code was never
> closed:
> DBCP object created 2006-35-04 13:35:00 by the following code was never
> closed:
> DBCP object created 2006-29-04 10:29:21 by the following code was never
> closed:
> DBCP object created 2006-36-04 13:36:39 by the following code was never
> closed:
> DBCP object created 2006-23-04 10:23:35 by the following code was never
> closed:
> DBCP object created 2006-36-04 13:36:43 by the following code was never
> closed:
> DBCP object created 2006-01-04 13:01:49 by the following code was never
> closed:
> DBCP object created 2006-36-04 13:36:56 by the following code was never
> closed:
> DBCP object created 2006-40-04 13:40:30 by the following code was never
> closed:
> DBCP object created 2006-15-04 15:15:02 by the following code was never
> closed:
> DBCP object created 2006-15-04 15:15:02 by the following code was never
> closed:
> DBCP object created 2006-11-04 14:11:46 by the following code was never
> closed:
> DBCP object created 2006-00-04 16:00:01 by the following code was never
> closed:
> DBCP object created 2006-00-04 16:00:01 by the following code was never
> closed:
> DBCP object created 2006-39-04 13:39:55 by the following code was never
> closed:
> DBCP object created 2006-00-04 16:00:02 by the following code was never
> closed:
> DBCP object created 2006-00-04 16:00:02 by the following code was never
> closed:
> DBCP object created 2006-11-04 14:11:46 by the following code was never
> closed:
> DBCP object created 2006-26-04 16:26:18 by the following code was never
> closed:
> DBCP object created 2006-26-04 16:26:18 by the following code was never
> closed:
> DBCP object created 2006-26-04 16:26:18 by the following code was never
> closed:
>
> And, here's the relevant portion of our server.xml:
> <Host name="acme.com" debug="0" autoDeploy="false"
> appBase="/home/httpd/vhosts/acme.com">
> <Alias>www.acme.com</Alias>
> <Logger className="org.apache.catalina.logger.FileLogger"
> directory="logs" prefix="acme.com_log."
> suffix=".txt"
> timestamp="true"/>
> <Context path="" docBase="httpdocs" reloadable="true" debug="0">
> <Resource name="jdbc/acme.com" auth="Container"
> type="javax.sql.DataSource"/>
> <ResourceParams name="jdbc/acme.com">
> <parameter>
> <name>url</name>
>
>
> <value>jdbc:mysql://localhost/acme?autoReconnect=true&zeroDateTimeBehavi
> or=convertToNull&noDatetimeStringSync=true</value>
> </parameter>
> <parameter>
> <name>driverClassName</name>
> <value>com.mysql.jdbc.Driver</value>
> </parameter>
>
> <parameter>
> <name>username</name>
> <value>acme</value>
> </parameter>
> <parameter>
> <name>password</name>
> <value>secret</value>
> </parameter>
> <parameter>
> <name>removeAbandoned</name>
> <value>true</value>
> </parameter>
> <parameter>
> <name>removeAbandonedTimeout</name>
> <value>60</value>
> </parameter>
> <parameter>
> <name>logAbandoned</name>
> <value>true</value>
> </parameter>
> </ResourceParams>
> </Context>
> </Host>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
>
RE: Diagnosing DBCP JDBC connection leak using removeAbandoned parm - short version
Posted by Richard Mixon <rn...@qwest.net>.
I'm still curious about the crazy logAbandoned messages - not sure how to
interpret or rely on them. I'll try a again with a briefer posting - maybe I
was too detailed in the original post.
We are getting strange (erroneous?) messages because of the logAbandoned
parameter:
1) The dates look like they are from lalaland (e.g. a date of
April 34,2006 in the second line below).
Maybe I do not understand how remove abandoned is working - the
timeout is supposed to start once a connection is determined to be
"idle".
2) Second the abandoned objects do not appear to be in order -
they jump from 10:23 to 13:34, 13:01, 13:35, back to 10:29 (see below).
Here is an extract/grep from our catalina.out:
DBCP object created 2006-23-04 10:23:35 by the following code was never
closed:
DBCP object created 2006-34-04 13:34:55 by the following code was never
closed:
DBCP object created 2006-01-04 13:01:49 by the following code was never
closed:
DBCP object created 2006-35-04 13:35:00 by the following code was never
closed:
DBCP object created 2006-29-04 10:29:21 by the following code was never
closed:
DBCP object created 2006-36-04 13:36:39 by the following code was never
closed:
DBCP object created 2006-23-04 10:23:35 by the following code was never
closed:
DBCP object created 2006-36-04 13:36:43 by the following code was never
closed:
DBCP object created 2006-01-04 13:01:49 by the following code was never
closed:
DBCP object created 2006-36-04 13:36:56 by the following code was never
closed:
DBCP object created 2006-40-04 13:40:30 by the following code was never
closed:
DBCP object created 2006-15-04 15:15:02 by the following code was never
closed:
DBCP object created 2006-15-04 15:15:02 by the following code was never
closed:
DBCP object created 2006-11-04 14:11:46 by the following code was never
closed:
DBCP object created 2006-00-04 16:00:01 by the following code was never
closed:
DBCP object created 2006-00-04 16:00:01 by the following code was never
closed:
DBCP object created 2006-39-04 13:39:55 by the following code was never
closed:
DBCP object created 2006-00-04 16:00:02 by the following code was never
closed:
DBCP object created 2006-00-04 16:00:02 by the following code was never
closed:
DBCP object created 2006-11-04 14:11:46 by the following code was never
closed:
DBCP object created 2006-26-04 16:26:18 by the following code was never
closed:
DBCP object created 2006-26-04 16:26:18 by the following code was never
closed:
DBCP object created 2006-26-04 16:26:18 by the following code was never
closed:
And, here's the relevant portion of our server.xml:
<Host name="acme.com" debug="0" autoDeploy="false"
appBase="/home/httpd/vhosts/acme.com">
<Alias>www.acme.com</Alias>
<Logger className="org.apache.catalina.logger.FileLogger"
directory="logs" prefix="acme.com_log."
suffix=".txt"
timestamp="true"/>
<Context path="" docBase="httpdocs" reloadable="true" debug="0">
<Resource name="jdbc/acme.com" auth="Container"
type="javax.sql.DataSource"/>
<ResourceParams name="jdbc/acme.com">
<parameter>
<name>url</name>
<value>jdbc:mysql://localhost/acme?autoReconnect=true&zeroDateTimeBehavi
or=convertToNull&noDatetimeStringSync=true</value>
</parameter>
<parameter>
<name>driverClassName</name>
<value>com.mysql.jdbc.Driver</value>
</parameter>
<parameter>
<name>username</name>
<value>acme</value>
</parameter>
<parameter>
<name>password</name>
<value>secret</value>
</parameter>
<parameter>
<name>removeAbandoned</name>
<value>true</value>
</parameter>
<parameter>
<name>removeAbandonedTimeout</name>
<value>60</value>
</parameter>
<parameter>
<name>logAbandoned</name>
<value>true</value>
</parameter>
</ResourceParams>
</Context>
</Host>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org