Re: Tomcat JDBC Pool memory leak when using StatementFinalizer interceptor
Hi Filip, On Fri, Jul 13, 2018 at 4:33 PM, Filip Hanik wrote: > hi Martin, > > On Fri, Jul 13, 2018 at 5:48 AM, Martin Knoblauch > wrote: > > > Hi, (moving to developers list) > > > > any ideas on the problem below? This thing is kind of itching me :-) > > > > So I instrumented the "StatementFinalizer" class with some logging and > > learned that over time a few instances of the "StatementFinalizer" are > > created, used and destroyed. So far so good. For most of those instances, > > the overall number of statements that are added to the "statements" list > by > > "createStatement" and the number of statements removed from the list by > > "closeInvoked" is identical and after "closeInvoked" finishes, the list > is > > empty. > > > > But only for most instances of "StatementFinalizer". I could find that > > there is one instance that is used (statements are added), but the > > invocation of "closednvoked" stops after some minutes into the > application. > > As a result the "statements" list starts growing. > > > > Could it be that your application checks out a connection and uses it for > the life time of the application? > Meaning Connection.close is never called? > > So in fact some instrumentation and digging deeper showed 3 different problems in the application: 1) there is one SQL Statement not closed (revealed by "StatementFinalizer(trace=true)") 2) there is one connection not closed after the "final" SQL statement (revealed by properly activating the "Abandoned" mechanism) 3) there is one connection that is used heavily over the entire lifetime of the application, and never closed. This one accumulates the memory that made me ask the "leak" question Need to address all three to the application developers. Given that 1+2 each only happen once, the best solution to avoid the "leak" might really be to just not use the "StatementFinalizer". Thanks Martin > I see that you set `removeAbandonedTimeout="0"` which yields in an > infinite value. > This would be done if an application never closes a connection. > > If you set removeAbandonedTimeout to a positive value and the system logs > that your connections are not being closed, then you know this is the case. > > If that is the scenario you have, then you should simply remove the > StatementFinalizer as it will not do anything for you. > > In most cases you shouldn't need StatementFinalizer, as applications (and > frameworks) are pretty at closing resources properly. > > > Filip > > > > > > > > Rings any bells? > > > > Thanks > > Martin > > > > On Wed, Jul 11, 2018 at 4:22 PM, Martin Knoblauch > > wrote: > > > > > Hi, > > > > > > while analyzing some heap dump for other reasons, I found that our > > > application is apparently aggregating a considerable amount of memory > in > > > "org.apache.tomcat.jdbc.pool.TrapException", which is never cleaned by > > > GC. Digging deeper, it seems that the entries of the "statements" > linked > > > list in the StatementFinalizer are never removed from the list, so > after > > > three weeks of lifetime one ends up with a list of 7 million entries, > > each > > > 80 bytes. > > > > > > Now it might be, that we are just using the StatementFinalizer in a > > wrong > > > manner. And what we see is expected behavior. Below is our pool > > > configuration. Maybe something is just missing :-) > > > > > > We are at Tomcat 8.0.36 (yeah, I know, but that is the version we have > to > > > use) and Java 8 (1.8.0_171). Underlying DB is Oracle 12.1.0.2 and we > are > > > using the latest "ojdbc7.jar" from Oracle. > > > > > > > > > > > name="jdbc/SimManagerDS" > > > auth="Container" > > > > > > type="javax.sql.DataSource" > > > description="Oracle datasource for xxx using > > > tomcat.jdbc.pool" > > > factory="org.apache.tomcat. > jdbc.pool.DataSourceFactory" > > > jmxEnabled="true" > > > jdbcInterceptors="ConnectionState;StatementFinalizer; > > > ResetAbandonedTimer;StatementCache(prepared=true,max=200)" > > > > > > initialSize="7" > > > minIdle="7" > > > maxActive="30" > > > maxIdle="10" > > > > > > testWhileIdle="true" > > > testOnBorrow="true" > > > testOnConnect="false" > > > testOnReturn="false" > > > validationQuery="SELECT 1 from dual" > > > validationInterval="3" > > > > > > logAbandoned="true" > > > removeAbandoned="false" > > > removeAbandonedTimeout="0" > > > suspectTimeout="600" > > > > > > timeBetweenEvictionRunsMillis="3" > > > minEvictableIdleTimeMillis="6" > > > maxWait="6" > > > maxAge="0" > > > > > > connectionProperties="(defaultRowPrefetch=200)" > > > > >
Re: Tomcat JDBC Pool memory leak when using StatementFinalizer interceptor
On Wed, Jul 18, 2018 at 3:24 PM, Martin Knoblauch
wrote:
> Hi Filip,
>
> On Fri, Jul 13, 2018 at 4:33 PM, Filip Hanik wrote:
>
>> hi Martin,
>>
>> On Fri, Jul 13, 2018 at 5:48 AM, Martin Knoblauch
>> wrote:
>>
>> > Hi, (moving to developers list)
>> >
>> > any ideas on the problem below? This thing is kind of itching me :-)
>> >
>> > So I instrumented the "StatementFinalizer" class with some logging and
>> > learned that over time a few instances of the "StatementFinalizer" are
>> > created, used and destroyed. So far so good. For most of those
>> instances,
>> > the overall number of statements that are added to the "statements"
>> list by
>> > "createStatement" and the number of statements removed from the list by
>> > "closeInvoked" is identical and after "closeInvoked" finishes, the list
>> is
>> > empty.
>> >
>> > But only for most instances of "StatementFinalizer". I could find that
>> > there is one instance that is used (statements are added), but the
>> > invocation of "closednvoked" stops after some minutes into the
>> application.
>> > As a result the "statements" list starts growing.
>> >
>>
>> Could it be that your application checks out a connection and uses it for
>> the life time of the application?
>> Meaning Connection.close is never called?
>>
>>
> So in fact some instrumentation and digging deeper showed 3 different
> problems in the application:
>
> 1) there is one SQL Statement not closed (revealed by
> "StatementFinalizer(trace=true)")
> 2) there is one connection not closed after the "final" SQL statement
> (revealed by properly activating the "Abandoned" mechanism)
> 3) there is one connection that is used heavily over the entire lifetime
> of the application, and never closed. This one accumulates the memory that
> made me ask the "leak" question
>
> Need to address all three to the application developers.
>
> Given that 1+2 each only happen once, the best solution to avoid the
> "leak" might really be to just not use the "StatementFinalizer".
>
>
>
But then, just for the fun of it, would something like this patch be of
interest? It adds a private method "removeClosed()" to the
"StatementFinalizer code. What it does is to remove all "closed" or "null"
statements from the "statements" list. In order to keep it low in the
performance profile, it only does this every "sweepMinutes" minutes (new
interceptor property). My testing shows it keeps the memory consumption
down.
Martin
---
apache-tomcat-8.0.36-src/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/StatementFinalizer.java
2016-06-09 16:00:49.0 +0200
+++
apache-tomcat-8.0.36-src-mkn/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/StatementFinalizer.java
2018-07-18 14:53:35.242785369 +0200
@@ -18,7 +18,9 @@
import java.lang.ref.WeakReference;
import java.lang.reflect.Method;
+import java.sql.SQLException;
import java.sql.Statement;
+import java.util.Iterator;
import java.util.LinkedList;
import java.util.List;
import java.util.Map;
@@ -40,15 +42,64 @@
protected List statements = new LinkedList<>();
private boolean logCreationStack = false;
+private long sweepMillis = 0;
+private long lastSweep = 0;
+
+private int addedStmts = 0;
+
+/**
+ * Removes closed or "null" statements from the "statements" list. Useful
for connections that are
+ * never closed. Returns without doing anything in the following cases:
+ * - Interceptor property "sweepMinutes" is 0 (default)
+ * - First call after "borrow"
+ * - Time difference between now and last sweep has not reached yet
+ * - Only one statement on list (or list is empty)
+ */
+private void removeClosed() {
+
+if (sweepMillis == 0) // Nothing to do
+return;
+if (lastSweep == 0) { // First time around. Nothing to do
+lastSweep = System.currentTimeMillis();
+return;
+}
+if ((System.currentTimeMillis() - lastSweep) < sweepMillis) // Age not
reached, nothing to do
+return;
+if (statements.size() < 2) // empty, or exactely one statement (has
just been added), nothing to do
+return;
+
+lastSweep = System.currentTimeMillis();
+Iterator it = statements.iterator();
+int clsdStmts = 0;
+int nullStmts = 0;
+while(it.hasNext()){
+StatementEntry ws = (StatementEntry)it.next();
+Statement st = ws.getStatement();
+try {
+if (st == null) nullStmts++;
+else if (st.isClosed()) clsdStmts++;
+if ((st == null) || st.isClosed()) it.remove();
+} catch (SQLException e) {
+//ignore this one
+}
+}
+if (log.isDebugEnabled())
+log.debug(" Statements since last sweep: added= "+addedStmts+",
closed= "+
+clsdStmts+", null="+nullStmts+", remaining=
"+statements.size());
+addedStmts = 0; // re-arm
+}
@Override
public Object createStatement(Object proxy, Method method, Object[]
args, Object statement, long t
Re: Tomcat JDBC Pool memory leak when using StatementFinalizer interceptor
Thanks Martin, I agree, regardless of use case, the pool should not
generate a leak.
let me review your proposal
Filip
On Wed, Jul 18, 2018 at 07:48 Martin Knoblauch wrote:
> On Wed, Jul 18, 2018 at 3:24 PM, Martin Knoblauch
> wrote:
>
> > Hi Filip,
> >
> > On Fri, Jul 13, 2018 at 4:33 PM, Filip Hanik wrote:
> >
> >> hi Martin,
> >>
> >> On Fri, Jul 13, 2018 at 5:48 AM, Martin Knoblauch
> >> wrote:
> >>
> >> > Hi, (moving to developers list)
> >> >
> >> > any ideas on the problem below? This thing is kind of itching me :-)
> >> >
> >> > So I instrumented the "StatementFinalizer" class with some logging and
> >> > learned that over time a few instances of the "StatementFinalizer" are
> >> > created, used and destroyed. So far so good. For most of those
> >> instances,
> >> > the overall number of statements that are added to the "statements"
> >> list by
> >> > "createStatement" and the number of statements removed from the list
> by
> >> > "closeInvoked" is identical and after "closeInvoked" finishes, the
> list
> >> is
> >> > empty.
> >> >
> >> > But only for most instances of "StatementFinalizer". I could find
> that
> >> > there is one instance that is used (statements are added), but the
> >> > invocation of "closednvoked" stops after some minutes into the
> >> application.
> >> > As a result the "statements" list starts growing.
> >> >
> >>
> >> Could it be that your application checks out a connection and uses it
> for
> >> the life time of the application?
> >> Meaning Connection.close is never called?
> >>
> >>
> > So in fact some instrumentation and digging deeper showed 3 different
> > problems in the application:
> >
> > 1) there is one SQL Statement not closed (revealed by
> > "StatementFinalizer(trace=true)")
> > 2) there is one connection not closed after the "final" SQL statement
> > (revealed by properly activating the "Abandoned" mechanism)
> > 3) there is one connection that is used heavily over the entire lifetime
> > of the application, and never closed. This one accumulates the memory
> that
> > made me ask the "leak" question
> >
> > Need to address all three to the application developers.
> >
> > Given that 1+2 each only happen once, the best solution to avoid the
> > "leak" might really be to just not use the "StatementFinalizer".
> >
> >
> >
> But then, just for the fun of it, would something like this patch be of
> interest? It adds a private method "removeClosed()" to the
> "StatementFinalizer code. What it does is to remove all "closed" or "null"
> statements from the "statements" list. In order to keep it low in the
> performance profile, it only does this every "sweepMinutes" minutes (new
> interceptor property). My testing shows it keeps the memory consumption
> down.
>
> Martin
>
> ---
>
> apache-tomcat-8.0.36-src/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/StatementFinalizer.java
> 2016-06-09 16:00:49.0 +0200
> +++
>
> apache-tomcat-8.0.36-src-mkn/modules/jdbc-pool/src/main/java/org/apache/tomcat/jdbc/pool/interceptor/StatementFinalizer.java
> 2018-07-18 14:53:35.242785369 +0200
> @@ -18,7 +18,9 @@
>
> import java.lang.ref.WeakReference;
> import java.lang.reflect.Method;
> +import java.sql.SQLException;
> import java.sql.Statement;
> +import java.util.Iterator;
> import java.util.LinkedList;
> import java.util.List;
> import java.util.Map;
> @@ -40,15 +42,64 @@
> protected List statements = new LinkedList<>();
>
> private boolean logCreationStack = false;
> +private long sweepMillis = 0;
> +private long lastSweep = 0;
> +
> +private int addedStmts = 0;
> +
> +/**
> + * Removes closed or "null" statements from the "statements" list. Useful
> for connections that are
> + * never closed. Returns without doing anything in the following cases:
> + * - Interceptor property "sweepMinutes" is 0 (default)
> + * - First call after "borrow"
> + * - Time difference between now and last sweep has not reached yet
> + * - Only one statement on list (or list is empty)
> + */
> +private void removeClosed() {
> +
> +if (sweepMillis == 0) // Nothing to do
> +return;
> +if (lastSweep == 0) { // First time around. Nothing to do
> +lastSweep = System.currentTimeMillis();
> +return;
> +}
> +if ((System.currentTimeMillis() - lastSweep) < sweepMillis) // Age not
> reached, nothing to do
> +return;
> +if (statements.size() < 2) // empty, or exactely one statement (has
> just been added), nothing to do
> +return;
> +
> +lastSweep = System.currentTimeMillis();
> +Iterator it = statements.iterator();
> +int clsdStmts = 0;
> +int nullStmts = 0;
> +while(it.hasNext()){
> +StatementEntry ws = (StatementEntry)it.next();
> +Statement st = ws.getStatement();
> +try {
> +if (st == null) nullStmts++;
> +else if (st.isClosed()) clsdStmts++;
> +if ((st == null) || st.isClosed()) it.remov
