glassfish
  1. glassfish
  2. GLASSFISH-17973

Connection leaks when using max-connection-usage-count

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 3.1, 3.1.1, 3.1.2_b12, 3.1.2_b13
    • Fix Version/s: 3.1.2_b17, 4.0
    • Component/s: jdbc
    • Labels:
      None

      Description

      I just made some tests with JDBC connection pool tuning and PostgreSQL.

      As PostgreSQL doesn't have a lot of timeout options (at least version 8.x doesn't), I wanted to prevent certain bad things to happen by configuring our JDBC connection pools to not reuse connection for a long time and so I am now testing the "max-connection-usage-count" parameter.

      However, enabling this parameter gives me connection leaks. I've already filed a bug for EclipseLink as I think this only happens, when a connection is being destroyed after being used for X times:


      But still I get the feeling that there is also some ToDo on the GlassFish side as my tests reveal. For these tests I did the following:

      1. setup clean GlassFish 3.1.2 promoted
      2. modify domain.xml derby pool (add these):
        steady-pool-size="1"
        max-pool-size="10"
        statement-leak-timeout-in-seconds="10"
        statement-leak-reclaim="true"
        idle-timeout-in-seconds="10"
        connection-leak-timeout-in-seconds="15"
        connection-leak-reclaim="true"
        max-connection-usage-count="10"
        fail-all-connections="true"
        
      3. deploy the attached test bundles (copy files into .../autodeploy/bundles/)
      4. start derby
      5. start domain
      6. wait some time and see the server log


      Here is a trace of a task that shows up log messages I'm worried about (resourceadapter logging set to FINE):

      $ sed -ne '/ThreadID=43;/,/^$/p' domains/domain1/server.log
      
      [#|2011-12-11T23:51:29.481+0100|INFO|glassfish3.1.2|org.ancoron.movie.stresstest.StressTestBean|_ThreadID=43;_ThreadName=Thread-2;|Running task #24|#]
      
      [#|2011-12-11T23:51:29.698+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.connectors|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.connectors.ConnectorRegistry;MethodName=getInstance;|returning the connector registry|#]
      
      [#|2011-12-11T23:51:29.702+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.connectors|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.connectors.ConnectionManagerImpl;MethodName=allocateConnection;|RAR5036:Resource reference is not defined for JNDI name [jdbc/__default__nontx]|#]
      
      [#|2011-12-11T23:51:29.703+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.connectors|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.connectors.ConnectorRegistry;MethodName=getInstance;|returning the connector registry|#]
      
      [#|2011-12-11T23:51:29.703+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.spi|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.spi.ManagedConnectionFactory;MethodName=logFine;|In equals|#]
      
      [#|2011-12-11T23:51:30.020+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.connectors|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.connectors.ConnectorRegistry;MethodName=getDescriptor;|Found/returing Connector descriptor in connector registry.|#]
      
      [#|2011-12-11T23:51:30.020+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.connectors|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.connectors.ConnectionManagerImpl;MethodName=logFine;|ConnectionMgr: poolName DerbyPool  txLevel : 1|#]
      
      [#|2011-12-11T23:51:30.020+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.pool.PoolManagerImpl;MethodName=logFine;|Returning noTxResourceManager|#]
      
      [#|2011-12-11T23:51:32.391+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.pool.ConnectionPool;MethodName=logFine;|Resource Pool: getting on wait queue|#]
      
      [#|2011-12-11T23:51:50.608+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.pool.ConnectionPool;MethodName=getResource;|removing wait monitor from queue: java.lang.Object@7bf51a2f|#]
      
      [#|2011-12-11T23:51:53.289+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.pool.ConnectionPool;MethodName=getResource;|Resource Pool: elapsed time (ms) to get connection for [ResourceSpec :- 
      connectionPoolName : DerbyPool
      isXA_ : false
      resoureId : jdbc/__default__nontx
      resoureIdType : 1
      pmResource : false
      nonTxResource : true
      lazyEnlistable : false
      lazyAssociatable : false] : 23268|#]
      
      [#|2011-12-11T23:51:53.290+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.spi|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.spi.ManagedConnection;MethodName=logFine;|In getConnection|#]
      
      [#|2011-12-11T23:51:53.290+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.spi|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.spi.ManagedConnection;MethodName=executeInitSql;|Starting Init SQL|#]
      
      [#|2011-12-11T23:51:53.291+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.spi|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.spi.ManagedConnection;MethodName=executeInitSql;|Finished executing Init SQL|#]
      
      [#|2011-12-11T23:51:53.292+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.pool.PoolManagerImpl;MethodName=logFine;|Returning noTxResourceManager|#]
      
      [#|2011-12-11T23:51:53.292+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.rm|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.rm.NoTxResourceManagerImpl;MethodName=logFine;|NoTxResourceManagerImpl :: enlistResource called|#]
      
      [#|2011-12-11T23:51:53.372+0100|FINEST|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.util|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.util.StatementLeakDetector;MethodName=startStatementLeakTracing;|Scheduled Statement leak tracing timer task|#]
      
      [#|2011-12-11T23:51:53.373+0100|FINEST|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.util|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.util.StatementLeakDetector;MethodName=stopStatementLeakTracing;|Stopped Statement leak tracing timer task|#]
      
      [#|2011-12-11T23:51:53.374+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.pool.PoolManagerImpl;MethodName=logFine;|Returning noTxResourceManager|#]
      
      [#|2011-12-11T23:51:53.374+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.rm|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.rm.NoTxResourceManagerImpl;MethodName=logFine;|NoTxResourceManagerImpl :: delistResource called|#]
      
      [#|2011-12-11T23:51:53.374+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.pool.ConnectionPool;MethodName=resourceClosed;|Pool: resourceClosed: 67|#]
      
      [#|2011-12-11T23:51:53.381+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.spi|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.spi.ManagedConnection;MethodName=logFine;|In cleanup|#]
      
      [#|2011-12-11T23:51:53.549+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.spi|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.spi.ManagedConnection;MethodName=logFine;|In destroy|#]
      
      [#|2011-12-11T23:51:53.606+0100|FINEST|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.allocator|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.allocator.LocalTxConnectorAllocator;MethodName=destroyResource;|destroyResource for LocalTxConnectorAllocator done|#]
      
      [#|2011-12-11T23:51:53.607+0100|INFO|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;|RAR7113: destroying connection since it has reached the maximum usage of : 1|#]
      
      [#|2011-12-11T23:51:53.607+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.pool.ConnectionPool;MethodName=notifyWaitingThreads;|Notifying wait monitor : java.lang.Object@3b86a79a|#]
      
      [#|2011-12-11T23:51:53.607+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.pool.ConnectionPool;MethodName=resourceClosed;|Pool: resourceFreed: 67|#]
      
      [#|2011-12-11T23:51:53.607+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.connectors|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.connectors.ConnectorRegistry;MethodName=getInstance;|returning the connector registry|#]
      
      [#|2011-12-11T23:51:53.608+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.connectors|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.connectors.ConnectionManagerImpl;MethodName=allocateConnection;|RAR5036:Resource reference is not defined for JNDI name [jdbc/__default__nontx]|#]
      
      [#|2011-12-11T23:51:53.608+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.connectors|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.connectors.ConnectorRegistry;MethodName=getInstance;|returning the connector registry|#]
      
      [#|2011-12-11T23:51:53.608+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.spi|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.spi.ManagedConnectionFactory;MethodName=logFine;|In equals|#]
      
      [#|2011-12-11T23:51:53.608+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.connectors|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.connectors.ConnectorRegistry;MethodName=getDescriptor;|Found/returing Connector descriptor in connector registry.|#]
      
      [#|2011-12-11T23:51:53.608+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.connectors|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.connectors.ConnectionManagerImpl;MethodName=logFine;|ConnectionMgr: poolName DerbyPool  txLevel : 1|#]
      
      [#|2011-12-11T23:51:53.609+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.pool.PoolManagerImpl;MethodName=logFine;|Returning noTxResourceManager|#]
      
      [#|2011-12-11T23:51:54.410+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.spi|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.spi.ManagedConnectionFactory;MethodName=logFine;|In createManagedConnection|#]
      
      [#|2011-12-11T23:51:54.413+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.spi|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.spi.ManagedConnectionFactory;MethodName=logFine;|In equals|#]
      
      [#|2011-12-11T23:51:54.416+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.spi|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.spi.ManagedConnectionFactory;MethodName=logFine;|In equals|#]
      
      [#|2011-12-11T23:51:54.417+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.spi|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.spi.ManagedConnectionFactory;MethodName=logFine;|In getResourceAdapter|#]
      
      [#|2011-12-11T23:51:54.418+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.pool.ConnectionPool;MethodName=createSingleResource;|Time taken to create a single resource : jdbc/__default__nontx and adding to the pool (ms) : 8|#]
      
      [#|2011-12-11T23:51:54.418+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.pool.ConnectionPool;MethodName=addResource;|Pool: resource added|#]
      
      [#|2011-12-11T23:51:54.600+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.pool.ConnectionPool;MethodName=addResource;|Pool: resource added|#]
      
      [#|2011-12-11T23:51:54.602+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.pool.ConnectionPool;MethodName=getResource;|Resource Pool: elapsed time (ms) to get connection for [ResourceSpec :- 
      connectionPoolName : DerbyPool
      isXA_ : false
      resoureId : jdbc/__default__nontx
      resoureIdType : 1
      pmResource : false
      nonTxResource : true
      lazyEnlistable : false
      lazyAssociatable : false] : 993|#]
      
      [#|2011-12-11T23:51:54.637+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.spi|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.spi.ManagedConnection;MethodName=logFine;|In getConnection|#]
      
      [#|2011-12-11T23:51:54.679+0100|WARNING|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.connectors|_ThreadID=43;_ThreadName=Thread-2;|RAR5117 : Failed to obtain/create connection from connection pool [ DerbyPool ]. Reason : com.sun.appserv.connectors.internal.api.PoolingException: This Managed Connection is not valid as the physical connection is not usable|#]
      
      [#|2011-12-11T23:51:54.746+0100|WARNING|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.spi|_ThreadID=43;_ThreadName=Thread-2;|RAR5114 : Error allocating connection : [Error in allocating a connection. Cause: This Managed Connection is not valid as the physical connection is not usable]|#]
      
      [#|2011-12-11T23:51:54.753+0100|INFO|glassfish3.1.2|org.eclipse.persistence.session.file:/tmp/osgiapp8911206436065082297/_MovieUnit|_ThreadID=43;_ThreadName=Thread-2;|Communication failure detected when attempting to perform read query outside of a transaction. Attempting to retry query. Error was: Exception [EclipseLink-4002] (Eclipse Persistence Services - 2.3.2.v20111125-r10461): org.eclipse.persistence.exceptions.DatabaseException
      Internal Exception: java.sql.SQLException: Error in allocating a connection. Cause: This Managed Connection is not valid as the physical connection is not usable
      Error Code: 0
      Call: SELECT DISTINCT c_type FROM mov_video WHERE (c_id = ?)
              bind => [1 parameter bound]
      Query: ReadObjectQuery(name="readObject" referenceClass=VideoEntityImpl sql="SELECT DISTINCT c_type FROM mov_video WHERE (c_id = ?)").|#]
      
      [#|2011-12-11T23:51:54.753+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.connectors|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.connectors.ConnectorRegistry;MethodName=getInstance;|returning the connector registry|#]
      
      [#|2011-12-11T23:51:54.754+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.connectors|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.connectors.ConnectionManagerImpl;MethodName=allocateConnection;|RAR5036:Resource reference is not defined for JNDI name [jdbc/__default__nontx]|#]
      
      [#|2011-12-11T23:51:54.754+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.connectors|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.connectors.ConnectorRegistry;MethodName=getInstance;|returning the connector registry|#]
      
      [#|2011-12-11T23:51:54.755+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.spi|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.spi.ManagedConnectionFactory;MethodName=logFine;|In equals|#]
      
      [#|2011-12-11T23:51:54.757+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.connectors|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.connectors.ConnectorRegistry;MethodName=getDescriptor;|Found/returing Connector descriptor in connector registry.|#]
      
      [#|2011-12-11T23:51:54.758+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.connectors|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.connectors.ConnectionManagerImpl;MethodName=logFine;|ConnectionMgr: poolName DerbyPool  txLevel : 1|#]
      
      [#|2011-12-11T23:51:54.759+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.pool.PoolManagerImpl;MethodName=logFine;|Returning noTxResourceManager|#]
      
      [#|2011-12-11T23:51:55.434+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.pool.ConnectionPool;MethodName=getResource;|Resource Pool: elapsed time (ms) to get connection for [ResourceSpec :- 
      connectionPoolName : DerbyPool
      isXA_ : false
      resoureId : jdbc/__default__nontx
      resoureIdType : 1
      pmResource : false
      nonTxResource : true
      lazyEnlistable : false
      lazyAssociatable : false] : 673|#]
      
      [#|2011-12-11T23:51:55.434+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.spi|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.spi.ManagedConnection;MethodName=logFine;|In getConnection|#]
      
      [#|2011-12-11T23:51:55.434+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.spi|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.spi.ManagedConnection;MethodName=executeInitSql;|Starting Init SQL|#]
      
      [#|2011-12-11T23:51:55.434+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.spi|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.spi.ManagedConnection;MethodName=executeInitSql;|Finished executing Init SQL|#]
      
      [#|2011-12-11T23:51:55.435+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.pool.PoolManagerImpl;MethodName=logFine;|Returning noTxResourceManager|#]
      
      [#|2011-12-11T23:51:55.435+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.rm|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.rm.NoTxResourceManagerImpl;MethodName=logFine;|NoTxResourceManagerImpl :: enlistResource called|#]
      
      [#|2011-12-11T23:51:55.437+0100|FINEST|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.util|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.util.StatementLeakDetector;MethodName=startStatementLeakTracing;|Scheduled Statement leak tracing timer task|#]
      
      [#|2011-12-11T23:51:55.442+0100|FINEST|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.util|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.util.StatementLeakDetector;MethodName=stopStatementLeakTracing;|Stopped Statement leak tracing timer task|#]
      
      [#|2011-12-11T23:51:55.443+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.pool.PoolManagerImpl;MethodName=logFine;|Returning noTxResourceManager|#]
      
      [#|2011-12-11T23:51:55.443+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.rm|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.rm.NoTxResourceManagerImpl;MethodName=logFine;|NoTxResourceManagerImpl :: delistResource called|#]
      
      [#|2011-12-11T23:51:55.455+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.pool.ConnectionPool;MethodName=resourceClosed;|Pool: resourceClosed: 97|#]
      
      [#|2011-12-11T23:51:55.455+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.spi|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.spi.ManagedConnection;MethodName=logFine;|In cleanup|#]
      
      [#|2011-12-11T23:51:55.539+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.gjc.spi|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.gjc.spi.ManagedConnection;MethodName=logFine;|In destroy|#]
      
      [#|2011-12-11T23:51:55.539+0100|FINEST|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.allocator|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.allocator.LocalTxConnectorAllocator;MethodName=destroyResource;|destroyResource for LocalTxConnectorAllocator done|#]
      
      [#|2011-12-11T23:51:55.540+0100|INFO|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;|RAR7113: destroying connection since it has reached the maximum usage of : 1|#]
      
      [#|2011-12-11T23:51:55.541+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.pool.ConnectionPool;MethodName=notifyWaitingThreads;|Notifying wait monitor : java.lang.Object@1465d8d2|#]
      
      [#|2011-12-11T23:51:55.541+0100|FINE|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=43;_ThreadName=Thread-2;ClassName=com.sun.enterprise.resource.pool.ConnectionPool;MethodName=resourceClosed;|Pool: resourceFreed: 97|#]
      
      [#|2011-12-11T23:51:55.541+0100|INFO|glassfish3.1.2|org.ancoron.movie.stresstest.StressTestBean|_ThreadID=43;_ThreadName=Thread-2;|... task #24 was successful|#]
      
      


      ...and more or less exactly 15 seconds later (the connection leak timeout):

      [#|2011-12-11T23:52:10.450+0100|WARNING|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=1114;_ThreadName=Thread-2;
      |A potential connection leak detected for connection pool DerbyPool. The stack trace of the thread is provided below : 
      com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:324)
      com.sun.enterprise.resource.pool.ConnectionPool.getResourceFromPool(ConnectionPool.java:758)
      com.sun.enterprise.resource.pool.ConnectionPool.getUnenlistedResource(ConnectionPool.java:632)
      com.sun.enterprise.resource.pool.ConnectionPool.internalGetResource(ConnectionPool.java:526)
      com.sun.enterprise.resource.pool.ConnectionPool.getResource(ConnectionPool.java:381)
      com.sun.enterprise.resource.pool.PoolManagerImpl.getResourceFromPool(PoolManagerImpl.java:242)
      com.sun.enterprise.resource.pool.PoolManagerImpl.getResource(PoolManagerImpl.java:167)
      com.sun.enterprise.connectors.ConnectionManagerImpl.getResource(ConnectionManagerImpl.java:338)
      com.sun.enterprise.connectors.ConnectionManagerImpl.internalGetConnection(ConnectionManagerImpl.java:301)
      com.sun.enterprise.connectors.ConnectionManagerImpl.allocateConnection(ConnectionManagerImpl.java:190)
      com.sun.enterprise.connectors.ConnectionManagerImpl.allocateConnection(ConnectionManagerImpl.java:165)
      com.sun.enterprise.connectors.ConnectionManagerImpl.allocateConnection(ConnectionManagerImpl.java:160)
      com.sun.gjc.spi.base.DataSource.getConnection(DataSource.java:113)
      org.eclipse.persistence.sessions.JNDIConnector.connect(JNDIConnector.java:123)
      org.eclipse.persistence.sessions.DatasourceLogin.connectToDatasource(DatasourceLogin.java:162)
      org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.connectInternal(DatasourceAccessor.java:330)
      org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.connectInternal(DatabaseAccessor.java:293)
      org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.reconnect(DatasourceAccessor.java:565)
      org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.reconnect(DatabaseAccessor.java:1508)
      org.eclipse.persistence.internal.databaseaccess.DatasourceAccessor.incrementCallCount(DatasourceAccessor.java:305)
      org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.basicExecuteCall(DatabaseAccessor.java:579)
      org.eclipse.persistence.internal.databaseaccess.DatabaseAccessor.executeCall(DatabaseAccessor.java:535)
      org.eclipse.persistence.internal.sessions.AbstractSession.basicExecuteCall(AbstractSession.java:1717)
      org.eclipse.persistence.sessions.server.ServerSession.executeCall(ServerSession.java:566)
      org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:207)
      org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.executeCall(DatasourceCallQueryMechanism.java:193)
      org.eclipse.persistence.internal.queries.DatasourceCallQueryMechanism.selectOneRow(DatasourceCallQueryMechanism.java:666)
      org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectOneRowFromTable(ExpressionQueryMechanism.java:2656)
      org.eclipse.persistence.descriptors.InheritancePolicy.selectOneRowUsingDefaultMultipleTableSubclassRead(InheritancePolicy.java:1462)
      org.eclipse.persistence.descriptors.InheritancePolicy.selectOneRowUsingMultipleTableSubclassRead(InheritancePolicy.java:1492)
      org.eclipse.persistence.internal.queries.ExpressionQueryMechanism.selectOneRow(ExpressionQueryMechanism.java:2624)
      org.eclipse.persistence.queries.ReadObjectQuery.executeObjectLevelReadQuery(ReadObjectQuery.java:450)
      org.eclipse.persistence.queries.ObjectLevelReadQuery.executeDatabaseQuery(ObjectLevelReadQuery.java:1081)
      org.eclipse.persistence.queries.DatabaseQuery.execute(DatabaseQuery.java:844)
      org.eclipse.persistence.queries.ObjectLevelReadQuery.execute(ObjectLevelReadQuery.java:1040)
      org.eclipse.persistence.queries.ReadObjectQuery.execute(ReadObjectQuery.java:418)
      org.eclipse.persistence.queries.ObjectLevelReadQuery.executeInUnitOfWork(ObjectLevelReadQuery.java:1128)
      org.eclipse.persistence.internal.sessions.UnitOfWorkImpl.internalExecuteQuery(UnitOfWorkImpl.java:2871)
      org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1516)
      org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1498)
      org.eclipse.persistence.internal.sessions.AbstractSession.executeQuery(AbstractSession.java:1449)
      org.eclipse.persistence.internal.jpa.EntityManagerImpl.executeQuery(EntityManagerImpl.java:820)
      org.eclipse.persistence.internal.jpa.EntityManagerImpl.findInternal(EntityManagerImpl.java:760)
      org.eclipse.persistence.internal.jpa.EntityManagerImpl.find(EntityManagerImpl.java:653)
      org.eclipse.persistence.internal.jpa.EntityManagerImpl.find(EntityManagerImpl.java:532)
      com.sun.enterprise.container.common.impl.EntityManagerWrapper.find(EntityManagerWrapper.java:320)
      org.ancoron.movie.jpa.impl.MovieJPAServiceImpl.get(MovieJPAServiceImpl.java:65)
      org.ancoron.movie.jpa.impl.MovieJPAServiceImpl.getVideo(MovieJPAServiceImpl.java:82)
      sun.reflect.GeneratedMethodAccessor171.invoke(Unknown Source)
      sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      java.lang.reflect.Method.invoke(Method.java:616)
      org.glassfish.ejb.security.application.EJBSecurityManager.runMethod(EJBSecurityManager.java:1052)
      org.glassfish.ejb.security.application.EJBSecurityManager.invoke(EJBSecurityManager.java:1124)
      com.sun.ejb.containers.BaseContainer.invokeBeanMethod(BaseContainer.java:5388)
      com.sun.ejb.EjbInvocation.invokeBeanMethod(EjbInvocation.java:619)
      com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:800)
      com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:571)
      com.sun.ejb.containers.interceptors.SystemInterceptorProxy.doAround(SystemInterceptorProxy.java:162)
      com.sun.ejb.containers.interceptors.SystemInterceptorProxy.aroundInvoke(SystemInterceptorProxy.java:144)
      sun.reflect.GeneratedMethodAccessor49.invoke(Unknown Source)
      sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      java.lang.reflect.Method.invoke(Method.java:616)
      com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:861)
      com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:800)
      com.sun.ejb.containers.interceptors.InterceptorManager.intercept(InterceptorManager.java:370)
      com.sun.ejb.containers.BaseContainer.__intercept(BaseContainer.java:5360)
      com.sun.ejb.containers.BaseContainer.intercept(BaseContainer.java:5348)
      com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:214)
      com.sun.ejb.containers.EJBLocalObjectInvocationHandlerDelegate.invoke(EJBLocalObjectInvocationHandlerDelegate.java:88)
      $Proxy111.getVideo(Unknown Source)
      sun.reflect.GeneratedMethodAccessor165.invoke(Unknown Source)
      sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      java.lang.reflect.Method.invoke(Method.java:616)
      org.glassfish.osgicdi.impl.OSGiServiceFactory$DynamicInvocationHandler.invoke(OSGiServiceFactory.java:234)
      $Proxy164.getVideo(Unknown Source)
      org.ancoron.movie.ejb.MovieEJBImpl.getVideo(MovieEJBImpl.java:70)
      sun.reflect.GeneratedMethodAccessor147.invoke(Unknown Source)
      sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      java.lang.reflect.Method.invoke(Method.java:616)
      org.glassfish.ejb.security.application.EJBSecurityManager.runMethod(EJBSecurityManager.java:1052)
      org.glassfish.ejb.security.application.EJBSecurityManager.invoke(EJBSecurityManager.java:1124)
      com.sun.ejb.containers.BaseContainer.invokeBeanMethod(BaseContainer.java:5388)
      com.sun.ejb.EjbInvocation.invokeBeanMethod(EjbInvocation.java:619)
      com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:800)
      com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:571)
      org.jboss.weld.ejb.SessionBeanInterceptor.aroundInvoke(SessionBeanInterceptor.java:49)
      sun.reflect.GeneratedMethodAccessor53.invoke(Unknown Source)
      sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      java.lang.reflect.Method.invoke(Method.java:616)
      com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:861)
      com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:800)
      com.sun.ejb.EjbInvocation.proceed(EjbInvocation.java:571)
      com.sun.ejb.containers.interceptors.SystemInterceptorProxy.doAround(SystemInterceptorProxy.java:162)
      com.sun.ejb.containers.interceptors.SystemInterceptorProxy.aroundInvoke(SystemInterceptorProxy.java:144)
      sun.reflect.GeneratedMethodAccessor49.invoke(Unknown Source)
      sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      java.lang.reflect.Method.invoke(Method.java:616)
      com.sun.ejb.containers.interceptors.AroundInvokeInterceptor.intercept(InterceptorManager.java:861)
      com.sun.ejb.containers.interceptors.AroundInvokeChainImpl.invokeNext(InterceptorManager.java:800)
      com.sun.ejb.containers.interceptors.InterceptorManager.intercept(InterceptorManager.java:370)
      com.sun.ejb.containers.BaseContainer.__intercept(BaseContainer.java:5360)
      com.sun.ejb.containers.BaseContainer.intercept(BaseContainer.java:5348)
      com.sun.ejb.containers.EJBLocalObjectInvocationHandler.invoke(EJBLocalObjectInvocationHandler.java:214)
      com.sun.ejb.containers.EJBLocalObjectInvocationHandlerDelegate.invoke(EJBLocalObjectInvocationHandlerDelegate.java:88)
      $Proxy162.getVideo(Unknown Source)
      sun.reflect.GeneratedMethodAccessor48.invoke(Unknown Source)
      sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      java.lang.reflect.Method.invoke(Method.java:616)
      org.glassfish.osgicdi.impl.OSGiServiceFactory$DynamicInvocationHandler.invoke(OSGiServiceFactory.java:234)
      $Proxy157.getVideo(Unknown Source)
      org.ancoron.movie.stresstest.StressTestBean$1.run(StressTestBean.java:71)
      java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
      java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
      java.lang.Thread.run(Thread.java:679)
      
      Monitoring Statistics :
      
       Monitoring Statistics for 
      DerbyPool|#]
      
      [#|2011-12-11T23:52:10.450+0100|INFO|glassfish3.1.2|javax.enterprise.resource.resourceadapter.com.sun.enterprise.resource.pool|_ThreadID=1114;_ThreadName=Thread-2;|Reclaiming the leaked connection of pool [ DerbyPool ] and destroying it so as to avoid both the application that leaked the connection and any other request that can potentially acquire the same connection from the pool end up using the connection at the same time|#]
      


      Running the tests without the "max-connection-usage-count" is totally fine and not a single connection leak is detected, nor do other problems occur.

      1. server-increased-timeout.log.gz
        189 kB
        chaoslayer
      2. server-thread43.log
        20 kB
        chaoslayer
      3. server-usage-count-10.log.gz
        4.66 MB
        chaoslayer
      4. server-validate-fine-b14.log.gz
        3.73 MB
        ancoron
      5. server-validation.log.gz
        247 kB
        ancoron
      6. server-validation-fine.log.gz
        6.87 MB
        ancoron
      7. stress-test-bundles.tar.gz
        44 kB
        chaoslayer
      8. test-connection-leaks.sh
        7 kB
        ancoron

        Activity

        Hide
        ancoron added a comment -

        Thank you.

        Show
        ancoron added a comment - Thank you.
        Hide
        prasads added a comment -

        Changing component to JDBC and adding 3_1_2-review tag as per discussion with Shalini

        Show
        prasads added a comment - Changing component to JDBC and adding 3_1_2-review tag as per discussion with Shalini
        Hide
        Shalini added a comment -

        Fixed in trunk.

        The max connection usage operation is modified to remove a resource handle from the pool when its usage count is more than max connection usage count directly.

        Sending appserver/connectors/connectors-runtime/src/main/java/com/sun/enterprise/resource/pool/AssocWithThreadResourcePool.java
        Sending appserver/connectors/connectors-runtime/src/main/java/com/sun/enterprise/resource/pool/ConnectionPool.java
        Sending appserver/connectors/connectors-runtime/src/main/resources/com/sun/logging/enterprise/resource/resourceadapter/LogStrings.properties
        Transmitting file data ...
        Committed revision 51959.

        Show
        Shalini added a comment - Fixed in trunk. The max connection usage operation is modified to remove a resource handle from the pool when its usage count is more than max connection usage count directly. Sending appserver/connectors/connectors-runtime/src/main/java/com/sun/enterprise/resource/pool/AssocWithThreadResourcePool.java Sending appserver/connectors/connectors-runtime/src/main/java/com/sun/enterprise/resource/pool/ConnectionPool.java Sending appserver/connectors/connectors-runtime/src/main/resources/com/sun/logging/enterprise/resource/resourceadapter/LogStrings.properties Transmitting file data ... Committed revision 51959.
        Hide
        Shalini added a comment -

        Fixed in 3.1.2 branch :

        Sending connectors/connectors-runtime/src/main/java/com/sun/enterprise/resource/pool/AssocWithThreadResourcePool.java
        Sending connectors/connectors-runtime/src/main/java/com/sun/enterprise/resource/pool/ConnectionPool.java
        Sending connectors/connectors-runtime/src/main/resources/com/sun/logging/enterprise/resource/resourceadapter/LogStrings.properties
        Transmitting file data ...
        Committed revision 51962.

        Show
        Shalini added a comment - Fixed in 3.1.2 branch : Sending connectors/connectors-runtime/src/main/java/com/sun/enterprise/resource/pool/AssocWithThreadResourcePool.java Sending connectors/connectors-runtime/src/main/java/com/sun/enterprise/resource/pool/ConnectionPool.java Sending connectors/connectors-runtime/src/main/resources/com/sun/logging/enterprise/resource/resourceadapter/LogStrings.properties Transmitting file data ... Committed revision 51962.
        Hide
        chaoslayer added a comment -

        Thank you very much for the fix.

        I'm also glad to see this fix landed in the 3.1.2 branch.

        Show
        chaoslayer added a comment - Thank you very much for the fix. I'm also glad to see this fix landed in the 3.1.2 branch.

          People

          • Assignee:
            Shalini
            Reporter:
            chaoslayer
          • Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: