Marc, Thank you - We are using a recent version of the MySQL Connector/J (3.1.10), but maybe that does not mean anything. - Richard
-----Original Message----- From: Farrow, Marc [mailto:[EMAIL PROTECTED] Sent: Wednesday, April 05, 2006 4:44 AM To: Tomcat Users List Subject: RE: Diagnosing DBCP JDBC connection leak using removeAbandoned parm Can you change your code to something similar to below? I have seen issues with certain implementations of database drivers in which the JDBC interfaces are not being implemented/coded properly. Just remember that the order you call your close statements does matter (although yours looked correct). Hth Marc 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); rset.close(); rset = null; stmt.close(); stmt = null; conn.close(); conn = null; } catch (Exception e) { SharedUtilities.logError(e); } finally { try { if (rset != null) { rset.close(); } catch (SQLException e) { //Exception ignored } try { if (stmt != null) { stmt.close(); } catch (SQLException e) { //Exception ignored } try { if (conn != null) { conn.close(); } catch (SQLException e) { //Exception ignored } } -----Original Message----- From: Richard Mixon [mailto:[EMAIL PROTECTED] Sent: Tuesday, April 04, 2006 10:57 PM To: users@tomcat.apache.org Subject: 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: [EMAIL PROTECTED] For additional commands, e-mail: [EMAIL PROTECTED] --------------------------------------------------------------------- To unsubscribe, e-mail: [EMAIL PROTECTED] For additional commands, e-mail: [EMAIL PROTECTED] --------------------------------------------------------------------- To unsubscribe, e-mail: [EMAIL PROTECTED] For additional commands, e-mail: [EMAIL PROTECTED]
