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
        Mitesh Meswani added a comment -

        Can you please try bumping up connection-leak-timeout-in-seconds and see whether the "leaks" are still detected?

        Show
        Mitesh Meswani added a comment - Can you please try bumping up connection-leak-timeout-in-seconds and see whether the "leaks" are still detected?
        Hide
        chaoslayer added a comment -

        Of course I can and will do.

        However, this simple test with very short timeout values has been established because I saw
        the same behavior in another application where timeouts are much higher, e.g.:

        max-wait-time-in-millis="60000"
        init-sql="SET statement_timeout TO 30000"
        idle-timeout-in-seconds="300"
        connection-leak-reclaim="true"
        connection-leak-timeout-in-seconds="3600"
        connection-creation-retry-interval-in-seconds="10"
        fail-all-connections="true"
        statement-leak-reclaim="true"
        statement-leak-timeout-in-seconds="60"
        statement-cache-size="0"
        steady-pool-size="10"
        max-pool-size="100"
        


        As the result is the same in terms of warnings and leaks and also the stacktraces look identical
        up to the application layer I don't think it will yield different results, but I'll do it anyways.

        P.S.: can someone edit the issue description and shorten the line length of the embedded log excerpt?
        Seems like I don't have the permission to do so. Thanx

        Show
        chaoslayer added a comment - Of course I can and will do. However, this simple test with very short timeout values has been established because I saw the same behavior in another application where timeouts are much higher, e.g.: max-wait-time-in-millis="60000" init-sql="SET statement_timeout TO 30000" idle-timeout-in-seconds="300" connection-leak-reclaim="true" connection-leak-timeout-in-seconds="3600" connection-creation-retry-interval-in-seconds="10" fail-all-connections="true" statement-leak-reclaim="true" statement-leak-timeout-in-seconds="60" statement-cache-size="0" steady-pool-size="10" max-pool-size="100" As the result is the same in terms of warnings and leaks and also the stacktraces look identical up to the application layer I don't think it will yield different results, but I'll do it anyways. P.S.: can someone edit the issue description and shorten the line length of the embedded log excerpt? Seems like I don't have the permission to do so. Thanx
        Hide
        chaoslayer added a comment -

        Just made another run with increased connection leak timeout (600 seconds).

        Results:

        $ egrep 'Running task #[0-9]+' logs/server.log* | wc -l
        10000
        $ egrep 'task #[0-9]+ was successful' logs/server.log* | wc -l
        10000
        $ egrep 'task #[0-9]+ failed' logs/server.log* | wc -l
        0
        $ grep 'A potential connection leak' logs/server.log* | wc -l
        3
        $ grep 'Communication failure detected' logs/server.log* | wc -l
        6
        $ grep 'RAR5114' logs/server.log* | wc -l
        4
        $ grep 'RAR5117' logs/server.log* | wc -l
        4
        $ grep 'RAR7113' logs/server.log* | wc -l
        934
        
        Show
        chaoslayer added a comment - Just made another run with increased connection leak timeout (600 seconds). Results: $ egrep 'Running task #[0-9]+' logs/server.log* | wc -l 10000 $ egrep 'task #[0-9]+ was successful' logs/server.log* | wc -l 10000 $ egrep 'task #[0-9]+ failed' logs/server.log* | wc -l 0 $ grep 'A potential connection leak' logs/server.log* | wc -l 3 $ grep 'Communication failure detected' logs/server.log* | wc -l 6 $ grep 'RAR5114' logs/server.log* | wc -l 4 $ grep 'RAR5117' logs/server.log* | wc -l 4 $ grep 'RAR7113' logs/server.log* | wc -l 934
        Hide
        chaoslayer added a comment -

        Attached server-increased-timeout.log.gz containing the full run with connection-leak-timeout-in-seconds set to 600 seconds.

        Show
        chaoslayer added a comment - Attached server-increased-timeout.log.gz containing the full run with connection-leak-timeout-in-seconds set to 600 seconds.
        Hide
        Shalini added a comment -

        From the logs, the connection leak tracing happens when a particular connection
        that is got from the pool is not closed within the specified time (600 seconds). Could you
        observe at random points of time, the number of connection made to the database
        using netstat or some other mechanism?

        There are also some connection failure messages, to track this, the connection
        validation could be turned on with table as the validation-method and a valid
        connection-validation-table-name could be provided. This will detect the connection
        failures and a FINE log would display the stacktrace of this failure.

        The configuration fail-all-connections=true works when connection validation is turned on
        and if there is a connection validation failure.

        From the logs, i understand that your application spawns multiple threads around 10000,
        each getting and closing a connection. Does each task do anything else with the
        connection got from the pool? It would be great if you could describe more about your application.

        I would also like to know if this behavior is seen only when you use eclipselink. A default
        installation of glassfish with these same pool settings, goes through fine?

        Show
        Shalini added a comment - From the logs, the connection leak tracing happens when a particular connection that is got from the pool is not closed within the specified time (600 seconds). Could you observe at random points of time, the number of connection made to the database using netstat or some other mechanism? There are also some connection failure messages, to track this, the connection validation could be turned on with table as the validation-method and a valid connection-validation-table-name could be provided. This will detect the connection failures and a FINE log would display the stacktrace of this failure. The configuration fail-all-connections=true works when connection validation is turned on and if there is a connection validation failure. From the logs, i understand that your application spawns multiple threads around 10000, each getting and closing a connection. Does each task do anything else with the connection got from the pool? It would be great if you could describe more about your application. I would also like to know if this behavior is seen only when you use eclipselink. A default installation of glassfish with these same pool settings, goes through fine?
        Hide
        ancoron added a comment -

        OK, here we go:

        The test "application" being used consists of 3 main parts:

        • a Stateless EJB using CMP (JPA) as a data access layer
        • a Stateless EJB providing business logic and using the data access SLSB
        • a "client" Singleton EJB used as an automatic test starter

        The code for the test client Singleton is here:

        @Singleton
        @Startup
        public class StressTestBean {
        
            private static final Logger log = Logger.getLogger(StressTestBean.class.getName());
            private static final ExecutorService exec = Executors.newCachedThreadPool();
            
            @Inject
            @OSGiService(dynamic=true)
            private MovieService svc;
            
            @Resource
            private TimerService timers;
        
            @PostConstruct
            protected void init() {
                timers.createSingleActionTimer(3000, new TimerConfig());
            }
            
            @Timeout
            protected void timeout() {
                final int num = 10000;
                log.log(Level.INFO,
                        "Starting in-container stress test with {0} tasks...",
                        String.valueOf(num));
                
                for(int i=0; i<num; i++) {
                    final int tmp = i;
                    exec.execute(new Runnable() {
        
                        @Override
                        public void run() {
                            log.log(Level.INFO,
                                    "Running task #{0}",
                                    String.valueOf(tmp));
                            try {
                                svc.getVideo(Long.valueOf(
                                        Math.round(Math.random() * Long.MAX_VALUE)
                                        ));
                                
                                log.log(Level.INFO,
                                        "... task #{0} was successful",
                                        String.valueOf(tmp));
                            } catch(MovieServiceException msx) {
                                log.log(Level.INFO,
                                        "... task #" + tmp + " failed",
                                        msx);
                            }
                        }
                    });
                }
                
            }
        }
        


        For the test itself there are no entries in the tables (or at least it doesn't matter).

        I have re-configured the datasource with validation, increased the max-wait-time and enabled
        basically anything GlassFish offers for datasource/connection/statement validation/checking/recovery:

        <jdbc-connection-pool validation-table-name="mov_video"
                              steady-pool-size="1"
                              statement-timeout-in-seconds="60"
                              connection-leak-reclaim="true"
                              idle-timeout-in-seconds="120"
                              max-wait-time-in-millis="120000"
                              connection-creation-retry-attempts="10"
                              validate-atmost-once-period-in-seconds="30"
                              statement-leak-timeout-in-seconds="90"
                              connection-creation-retry-interval-in-seconds="5"
                              max-pool-size="10"
                              datasource-classname="org.apache.derby.jdbc.ClientDataSource"
                              res-type="javax.sql.DataSource"
                              max-connection-usage-count="10"
                              connection-leak-timeout-in-seconds="600"
                              statement-leak-reclaim="true"
                              name="DerbyPool"
                              init-sql="SELECT COUNT(*) FROM mov_video"
                              transaction-isolation-level="read-committed"
                              ping="true"
                              fail-all-connections="true"
                              >
            <property name="PortNumber" value="1527"></property>
            <property name="Password" value="APP"></property>
            <property name="User" value="APP"></property>
            <property name="serverName" value="localhost"></property>
            <property name="DatabaseName" value="sun-appserv-samples"></property>
            <property name="connectionAttributes" value=";create=true"></property>
            <property name="prefer-validate-over-recreate" value="true"></property>
        </jdbc-connection-pool>
        


        All the rest is default and apart from the bundles and logging there is no
        modification of the tested GlassFish 3.1.2-b13.

        For testing I've written a little script to ease getting results and tracking things.

        Note that I used the monitoring for collecting some data.

        • jdbc-connection-pool="HIGH"
        • accessing the REST API using curl

        Please note the values for "current-conns" in the following outputs. Those are exactly
        what the monitoring via REST API reports (may be another bug - only happens when under
        heavy load - when that monitoring data is most needed to be exact).

        Here is the output for a test run with logging kept at INFO:

        Starting database in the background.
        Log redirected to /srv/servers/glassfish/3.1.2-b13/glassfish/databases/derby.log.
        Command start-database executed successfully.
        Waiting for domain1 to start .....
        Successfully started the domain : domain1
        domain  Location: /srv/servers/glassfish/3.1.2-b13/glassfish/domains/domain1
        Log File: /srv/servers/glassfish/3.1.2-b13/glassfish/domains/domain1/logs/server.log
        Admin Port: 4848
        Command start-domain executed successfully.
        [2011-12-16T01:31:58.610] ...waiting for deployment to finish...
        [2011-12-16T01:32:13.829] Deployment successful :)
        Command enable-monitoring executed successfully.
        Command enable-monitoring executed successfully.
        [2011-12-16T01:32:20.191] tasks=81, current-conns=9
        [2011-12-16T01:32:22.002] tasks=150, current-conns=6
        [2011-12-16T01:32:23.065] tasks=227, current-conns=7
        [2011-12-16T01:32:24.150] tasks=292, current-conns=8
        [2011-12-16T01:32:25.244] tasks=358, current-conns=7
        [2011-12-16T01:32:26.334] tasks=419, current-conns=8
        [2011-12-16T01:32:27.435] tasks=519, current-conns=8
        [2011-12-16T01:32:28.539] tasks=635, current-conns=8
        [2011-12-16T01:32:29.657] tasks=710, current-conns=5
        [2011-12-16T01:32:32.344] tasks=779, current-conns=7
        [2011-12-16T01:32:33.594] tasks=1051, current-conns=8
        [2011-12-16T01:32:34.793] tasks=1534, current-conns=9
        [2011-12-16T01:32:35.969] tasks=2024, current-conns=8
        [2011-12-16T01:32:37.143] tasks=2569, current-conns=4
        [2011-12-16T01:32:38.427] tasks=3290, current-conns=5
        [2011-12-16T01:32:39.712] tasks=3958, current-conns=5
        [2011-12-16T01:32:41.001] tasks=4600, current-conns=3
        [2011-12-16T01:32:42.236] tasks=5364, current-conns=2
        [2011-12-16T01:32:43.427] tasks=6330, current-conns=5
        [2011-12-16T01:32:44.618] tasks=7330, current-conns=1
        [2011-12-16T01:32:45.858] tasks=8467, current-conns=6
        [2011-12-16T01:32:47.138] tasks=9736, current-conns=4
        [2011-12-16T01:32:48.349] tasks=10000, current-conns=-3
        [2011-12-16T01:32:48.361] Waiting for connection leak timeout (600 seconds)...
        [2011-12-16T01:42:49.764] Test results: statement-leaks=4, connection-leaks=9
        Waiting for the domain to stop .....
        Command stop-domain executed successfully.
        Fri Dec 16 01:42:58 CET 2011 : Connection obtained for host: 0.0.0.0, port number 1527.
        Fri Dec 16 01:42:58 CET 2011 : Apache Derby Network Server - 10.8.1.2 - (1095077) shutdown
        Command stop-database executed successfully.
        


        And here is the output for logging set to FINE:

        Starting database in the background.
        Log redirected to /srv/servers/glassfish/3.1.2-b13/glassfish/databases/derby.log.
        Command start-database executed successfully.
        Waiting for domain1 to start ...
        Successfully started the domain : domain1
        domain  Location: /srv/servers/glassfish/3.1.2-b13/glassfish/domains/domain1
        Log File: /srv/servers/glassfish/3.1.2-b13/glassfish/domains/domain1/logs/server.log
        Admin Port: 4848
        Command start-domain executed successfully.
        [2011-12-16T02:03:37.115] ...waiting for deployment to finish...
        [2011-12-16T02:03:51.353] Deployment successful :)
        Command enable-monitoring executed successfully.
        Command enable-monitoring executed successfully.
        [2011-12-16T02:04:03.034] tasks=0, current-conns=4
        [2011-12-16T02:04:04.156] tasks=0, current-conns=4
        [2011-12-16T02:04:05.279] tasks=0, current-conns=5
        [2011-12-16T02:04:06.409] tasks=0, current-conns=5
        [2011-12-16T02:04:07.584] tasks=0, current-conns=5
        [2011-12-16T02:04:08.719] tasks=0, current-conns=5
        [2011-12-16T02:04:09.866] tasks=0, current-conns=5
        [2011-12-16T02:04:11.039] tasks=0, current-conns=5
        [2011-12-16T02:04:12.218] tasks=0, current-conns=5
        [2011-12-16T02:04:13.367] tasks=0, current-conns=5
        [2011-12-16T02:04:14.544] tasks=0, current-conns=5
        [2011-12-16T02:04:15.717] tasks=0, current-conns=5
        [2011-12-16T02:04:16.874] tasks=0, current-conns=5
        [2011-12-16T02:04:18.072] tasks=0, current-conns=5
        [2011-12-16T02:04:19.254] tasks=0, current-conns=6
        [2011-12-16T02:04:22.071] tasks=0, current-conns=6
        [2011-12-16T02:04:23.279] tasks=0, current-conns=6
        [2011-12-16T02:04:24.466] tasks=0, current-conns=6
        [2011-12-16T02:04:25.657] tasks=0, current-conns=6
        [2011-12-16T02:04:26.854] tasks=0, current-conns=7
        [2011-12-16T02:04:28.210] tasks=0, current-conns=7
        [2011-12-16T02:04:29.373] tasks=0, current-conns=7
        [2011-12-16T02:04:30.567] tasks=0, current-conns=7
        [2011-12-16T02:04:31.759] tasks=0, current-conns=9
        [2011-12-16T02:04:32.978] tasks=0, current-conns=9
        [2011-12-16T02:04:34.177] tasks=0, current-conns=9
        [2011-12-16T02:04:35.414] tasks=0, current-conns=10
        [2011-12-16T02:04:36.634] tasks=0, current-conns=10
        [2011-12-16T02:04:37.856] tasks=0, current-conns=10
        [2011-12-16T02:04:39.051] tasks=0, current-conns=10
        [2011-12-16T02:04:40.280] tasks=0, current-conns=10
        [2011-12-16T02:04:41.514] tasks=6, current-conns=10
        [2011-12-16T02:04:42.952] tasks=23, current-conns=8
        [2011-12-16T02:04:44.209] tasks=30, current-conns=8
        [2011-12-16T02:04:45.427] tasks=57, current-conns=6
        [2011-12-16T02:04:46.772] tasks=70, current-conns=8
        [2011-12-16T02:04:47.986] tasks=88, current-conns=7
        [2011-12-16T02:04:49.629] tasks=154, current-conns=6
        [2011-12-16T02:04:50.825] tasks=273, current-conns=5
        [2011-12-16T02:04:52.074] tasks=383, current-conns=2
        [2011-12-16T02:04:53.406] tasks=491, current-conns=0
        [2011-12-16T02:04:54.631] tasks=570, current-conns=-3
        [2011-12-16T02:04:55.897] tasks=669, current-conns=0
        [2011-12-16T02:04:57.166] tasks=775, current-conns=0
        [2011-12-16T02:04:58.445] tasks=888, current-conns=-1
        [2011-12-16T02:04:59.669] tasks=994, current-conns=1
        [2011-12-16T02:05:00.978] tasks=1124, current-conns=-1
        [2011-12-16T02:05:02.207] tasks=1234, current-conns=-3
        [2011-12-16T02:05:03.482] tasks=1352, current-conns=-5
        [2011-12-16T02:05:04.733] tasks=1477, current-conns=-4
        [2011-12-16T02:05:05.964] tasks=1585, current-conns=-4
        [2011-12-16T02:05:07.231] tasks=1714, current-conns=-8
        [2011-12-16T02:05:08.499] tasks=1838, current-conns=-7
        [2011-12-16T02:05:09.751] tasks=1962, current-conns=-9
        [2011-12-16T02:05:11.042] tasks=2088, current-conns=-10
        [2011-12-16T02:05:12.339] tasks=2206, current-conns=-13
        [2011-12-16T02:05:13.642] tasks=2325, current-conns=-13
        [2011-12-16T02:05:14.975] tasks=2465, current-conns=-14
        [2011-12-16T02:05:16.308] tasks=2606, current-conns=-15
        [2011-12-16T02:05:17.610] tasks=2750, current-conns=-18
        [2011-12-16T02:05:18.893] tasks=2885, current-conns=-16
        [2011-12-16T02:05:20.228] tasks=3016, current-conns=-18
        [2011-12-16T02:05:21.519] tasks=3149, current-conns=-23
        [2011-12-16T02:05:22.993] tasks=3312, current-conns=-21
        [2011-12-16T02:05:24.336] tasks=3452, current-conns=-21
        [2011-12-16T02:05:25.638] tasks=3579, current-conns=-21
        [2011-12-16T02:05:27.028] tasks=3725, current-conns=-23
        [2011-12-16T02:05:28.367] tasks=3933, current-conns=-28
        [2011-12-16T02:05:29.674] tasks=4127, current-conns=-25
        [2011-12-16T02:05:30.984] tasks=4356, current-conns=-28
        [2011-12-16T02:05:32.303] tasks=4613, current-conns=-32
        [2011-12-16T02:05:33.599] tasks=4742, current-conns=-31
        [2011-12-16T02:05:34.930] tasks=4930, current-conns=-31
        [2011-12-16T02:05:36.257] tasks=5143, current-conns=-34
        [2011-12-16T02:05:37.584] tasks=5372, current-conns=-37
        [2011-12-16T02:05:38.907] tasks=5596, current-conns=-39
        [2011-12-16T02:05:40.247] tasks=5845, current-conns=-39
        [2011-12-16T02:05:41.600] tasks=6088, current-conns=-40
        [2011-12-16T02:05:43.001] tasks=6349, current-conns=-42
        [2011-12-16T02:05:44.397] tasks=6624, current-conns=-43
        [2011-12-16T02:05:46.177] tasks=6719, current-conns=-44
        [2011-12-16T02:05:47.562] tasks=6999, current-conns=-48
        [2011-12-16T02:05:48.952] tasks=7267, current-conns=-44
        [2011-12-16T02:05:50.309] tasks=7542, current-conns=-45
        [2011-12-16T02:05:51.738] tasks=7903, current-conns=-49
        [2011-12-16T02:05:53.128] tasks=8208, current-conns=-50
        [2011-12-16T02:05:54.528] tasks=8514, current-conns=-48
        [2011-12-16T02:05:55.944] tasks=8820, current-conns=-49
        [2011-12-16T02:05:57.336] tasks=9119, current-conns=-50
        [2011-12-16T02:05:58.744] tasks=9454, current-conns=-50
        [2011-12-16T02:06:00.180] tasks=9805, current-conns=-54
        [2011-12-16T02:06:01.567] tasks=10000, current-conns=-62
        [2011-12-16T02:06:01.585] Waiting for connection leak timeout (600 seconds)...
        [2011-12-16T02:16:02.992] Test results: statement-leaks=1, connection-leaks=14
        Waiting for the domain to stop .....
        Command stop-domain executed successfully.
        Fri Dec 16 02:16:12 CET 2011 : Connection obtained for host: 0.0.0.0, port number 1527.
        Fri Dec 16 02:16:12 CET 2011 : Apache Derby Network Server - 10.8.1.2 - (1095077) shutdown
        Command stop-database executed successfully.
        


        For using a different JPA implementation inside GlassFish I don't have much
        experience (it has to work with OSGi, too).

        Can you recommend some how-to?

        Show
        ancoron added a comment - OK, here we go: The test "application" being used consists of 3 main parts: a Stateless EJB using CMP (JPA) as a data access layer a Stateless EJB providing business logic and using the data access SLSB a "client" Singleton EJB used as an automatic test starter The code for the test client Singleton is here: @Singleton @Startup public class StressTestBean { private static final Logger log = Logger.getLogger(StressTestBean.class.getName()); private static final ExecutorService exec = Executors.newCachedThreadPool(); @Inject @OSGiService(dynamic= true ) private MovieService svc; @Resource private TimerService timers; @PostConstruct protected void init() { timers.createSingleActionTimer(3000, new TimerConfig()); } @Timeout protected void timeout() { final int num = 10000; log.log(Level.INFO, "Starting in-container stress test with {0} tasks..." , String .valueOf(num)); for ( int i=0; i<num; i++) { final int tmp = i; exec.execute( new Runnable () { @Override public void run() { log.log(Level.INFO, "Running task #{0}" , String .valueOf(tmp)); try { svc.getVideo( Long .valueOf( Math .round( Math .random() * Long .MAX_VALUE) )); log.log(Level.INFO, "... task #{0} was successful" , String .valueOf(tmp)); } catch (MovieServiceException msx) { log.log(Level.INFO, "... task #" + tmp + " failed" , msx); } } }); } } } For the test itself there are no entries in the tables (or at least it doesn't matter). I have re-configured the datasource with validation, increased the max-wait-time and enabled basically anything GlassFish offers for datasource/connection/statement validation/checking/recovery: <jdbc-connection-pool validation-table-name="mov_video" steady-pool-size="1" statement-timeout-in-seconds="60" connection-leak-reclaim="true" idle-timeout-in-seconds="120" max-wait-time-in-millis="120000" connection-creation-retry-attempts="10" validate-atmost-once-period-in-seconds="30" statement-leak-timeout-in-seconds="90" connection-creation-retry-interval-in-seconds="5" max-pool-size="10" datasource-classname="org.apache.derby.jdbc.ClientDataSource" res-type="javax.sql.DataSource" max-connection-usage-count="10" connection-leak-timeout-in-seconds="600" statement-leak-reclaim="true" name="DerbyPool" init-sql="SELECT COUNT(*) FROM mov_video" transaction-isolation-level="read-committed" ping="true" fail-all-connections="true" > <property name="PortNumber" value="1527"></property> <property name="Password" value="APP"></property> <property name="User" value="APP"></property> <property name="serverName" value="localhost"></property> <property name="DatabaseName" value="sun-appserv-samples"></property> <property name="connectionAttributes" value=";create=true"></property> <property name="prefer-validate-over-recreate" value="true"></property> </jdbc-connection-pool> All the rest is default and apart from the bundles and logging there is no modification of the tested GlassFish 3.1.2-b13. For testing I've written a little script to ease getting results and tracking things. Note that I used the monitoring for collecting some data. jdbc-connection-pool="HIGH" accessing the REST API using curl Please note the values for "current-conns" in the following outputs. Those are exactly what the monitoring via REST API reports (may be another bug - only happens when under heavy load - when that monitoring data is most needed to be exact). Here is the output for a test run with logging kept at INFO: Starting database in the background. Log redirected to /srv/servers/glassfish/3.1.2-b13/glassfish/databases/derby.log. Command start-database executed successfully. Waiting for domain1 to start ..... Successfully started the domain : domain1 domain Location: /srv/servers/glassfish/3.1.2-b13/glassfish/domains/domain1 Log File: /srv/servers/glassfish/3.1.2-b13/glassfish/domains/domain1/logs/server.log Admin Port: 4848 Command start-domain executed successfully. [2011-12-16T01:31:58.610] ...waiting for deployment to finish... [2011-12-16T01:32:13.829] Deployment successful :) Command enable-monitoring executed successfully. Command enable-monitoring executed successfully. [2011-12-16T01:32:20.191] tasks=81, current-conns=9 [2011-12-16T01:32:22.002] tasks=150, current-conns=6 [2011-12-16T01:32:23.065] tasks=227, current-conns=7 [2011-12-16T01:32:24.150] tasks=292, current-conns=8 [2011-12-16T01:32:25.244] tasks=358, current-conns=7 [2011-12-16T01:32:26.334] tasks=419, current-conns=8 [2011-12-16T01:32:27.435] tasks=519, current-conns=8 [2011-12-16T01:32:28.539] tasks=635, current-conns=8 [2011-12-16T01:32:29.657] tasks=710, current-conns=5 [2011-12-16T01:32:32.344] tasks=779, current-conns=7 [2011-12-16T01:32:33.594] tasks=1051, current-conns=8 [2011-12-16T01:32:34.793] tasks=1534, current-conns=9 [2011-12-16T01:32:35.969] tasks=2024, current-conns=8 [2011-12-16T01:32:37.143] tasks=2569, current-conns=4 [2011-12-16T01:32:38.427] tasks=3290, current-conns=5 [2011-12-16T01:32:39.712] tasks=3958, current-conns=5 [2011-12-16T01:32:41.001] tasks=4600, current-conns=3 [2011-12-16T01:32:42.236] tasks=5364, current-conns=2 [2011-12-16T01:32:43.427] tasks=6330, current-conns=5 [2011-12-16T01:32:44.618] tasks=7330, current-conns=1 [2011-12-16T01:32:45.858] tasks=8467, current-conns=6 [2011-12-16T01:32:47.138] tasks=9736, current-conns=4 [2011-12-16T01:32:48.349] tasks=10000, current-conns=-3 [2011-12-16T01:32:48.361] Waiting for connection leak timeout (600 seconds)... [2011-12-16T01:42:49.764] Test results: statement-leaks=4, connection-leaks=9 Waiting for the domain to stop ..... Command stop-domain executed successfully. Fri Dec 16 01:42:58 CET 2011 : Connection obtained for host: 0.0.0.0, port number 1527. Fri Dec 16 01:42:58 CET 2011 : Apache Derby Network Server - 10.8.1.2 - (1095077) shutdown Command stop-database executed successfully. And here is the output for logging set to FINE: Starting database in the background. Log redirected to /srv/servers/glassfish/3.1.2-b13/glassfish/databases/derby.log. Command start-database executed successfully. Waiting for domain1 to start ... Successfully started the domain : domain1 domain Location: /srv/servers/glassfish/3.1.2-b13/glassfish/domains/domain1 Log File: /srv/servers/glassfish/3.1.2-b13/glassfish/domains/domain1/logs/server.log Admin Port: 4848 Command start-domain executed successfully. [2011-12-16T02:03:37.115] ...waiting for deployment to finish... [2011-12-16T02:03:51.353] Deployment successful :) Command enable-monitoring executed successfully. Command enable-monitoring executed successfully. [2011-12-16T02:04:03.034] tasks=0, current-conns=4 [2011-12-16T02:04:04.156] tasks=0, current-conns=4 [2011-12-16T02:04:05.279] tasks=0, current-conns=5 [2011-12-16T02:04:06.409] tasks=0, current-conns=5 [2011-12-16T02:04:07.584] tasks=0, current-conns=5 [2011-12-16T02:04:08.719] tasks=0, current-conns=5 [2011-12-16T02:04:09.866] tasks=0, current-conns=5 [2011-12-16T02:04:11.039] tasks=0, current-conns=5 [2011-12-16T02:04:12.218] tasks=0, current-conns=5 [2011-12-16T02:04:13.367] tasks=0, current-conns=5 [2011-12-16T02:04:14.544] tasks=0, current-conns=5 [2011-12-16T02:04:15.717] tasks=0, current-conns=5 [2011-12-16T02:04:16.874] tasks=0, current-conns=5 [2011-12-16T02:04:18.072] tasks=0, current-conns=5 [2011-12-16T02:04:19.254] tasks=0, current-conns=6 [2011-12-16T02:04:22.071] tasks=0, current-conns=6 [2011-12-16T02:04:23.279] tasks=0, current-conns=6 [2011-12-16T02:04:24.466] tasks=0, current-conns=6 [2011-12-16T02:04:25.657] tasks=0, current-conns=6 [2011-12-16T02:04:26.854] tasks=0, current-conns=7 [2011-12-16T02:04:28.210] tasks=0, current-conns=7 [2011-12-16T02:04:29.373] tasks=0, current-conns=7 [2011-12-16T02:04:30.567] tasks=0, current-conns=7 [2011-12-16T02:04:31.759] tasks=0, current-conns=9 [2011-12-16T02:04:32.978] tasks=0, current-conns=9 [2011-12-16T02:04:34.177] tasks=0, current-conns=9 [2011-12-16T02:04:35.414] tasks=0, current-conns=10 [2011-12-16T02:04:36.634] tasks=0, current-conns=10 [2011-12-16T02:04:37.856] tasks=0, current-conns=10 [2011-12-16T02:04:39.051] tasks=0, current-conns=10 [2011-12-16T02:04:40.280] tasks=0, current-conns=10 [2011-12-16T02:04:41.514] tasks=6, current-conns=10 [2011-12-16T02:04:42.952] tasks=23, current-conns=8 [2011-12-16T02:04:44.209] tasks=30, current-conns=8 [2011-12-16T02:04:45.427] tasks=57, current-conns=6 [2011-12-16T02:04:46.772] tasks=70, current-conns=8 [2011-12-16T02:04:47.986] tasks=88, current-conns=7 [2011-12-16T02:04:49.629] tasks=154, current-conns=6 [2011-12-16T02:04:50.825] tasks=273, current-conns=5 [2011-12-16T02:04:52.074] tasks=383, current-conns=2 [2011-12-16T02:04:53.406] tasks=491, current-conns=0 [2011-12-16T02:04:54.631] tasks=570, current-conns=-3 [2011-12-16T02:04:55.897] tasks=669, current-conns=0 [2011-12-16T02:04:57.166] tasks=775, current-conns=0 [2011-12-16T02:04:58.445] tasks=888, current-conns=-1 [2011-12-16T02:04:59.669] tasks=994, current-conns=1 [2011-12-16T02:05:00.978] tasks=1124, current-conns=-1 [2011-12-16T02:05:02.207] tasks=1234, current-conns=-3 [2011-12-16T02:05:03.482] tasks=1352, current-conns=-5 [2011-12-16T02:05:04.733] tasks=1477, current-conns=-4 [2011-12-16T02:05:05.964] tasks=1585, current-conns=-4 [2011-12-16T02:05:07.231] tasks=1714, current-conns=-8 [2011-12-16T02:05:08.499] tasks=1838, current-conns=-7 [2011-12-16T02:05:09.751] tasks=1962, current-conns=-9 [2011-12-16T02:05:11.042] tasks=2088, current-conns=-10 [2011-12-16T02:05:12.339] tasks=2206, current-conns=-13 [2011-12-16T02:05:13.642] tasks=2325, current-conns=-13 [2011-12-16T02:05:14.975] tasks=2465, current-conns=-14 [2011-12-16T02:05:16.308] tasks=2606, current-conns=-15 [2011-12-16T02:05:17.610] tasks=2750, current-conns=-18 [2011-12-16T02:05:18.893] tasks=2885, current-conns=-16 [2011-12-16T02:05:20.228] tasks=3016, current-conns=-18 [2011-12-16T02:05:21.519] tasks=3149, current-conns=-23 [2011-12-16T02:05:22.993] tasks=3312, current-conns=-21 [2011-12-16T02:05:24.336] tasks=3452, current-conns=-21 [2011-12-16T02:05:25.638] tasks=3579, current-conns=-21 [2011-12-16T02:05:27.028] tasks=3725, current-conns=-23 [2011-12-16T02:05:28.367] tasks=3933, current-conns=-28 [2011-12-16T02:05:29.674] tasks=4127, current-conns=-25 [2011-12-16T02:05:30.984] tasks=4356, current-conns=-28 [2011-12-16T02:05:32.303] tasks=4613, current-conns=-32 [2011-12-16T02:05:33.599] tasks=4742, current-conns=-31 [2011-12-16T02:05:34.930] tasks=4930, current-conns=-31 [2011-12-16T02:05:36.257] tasks=5143, current-conns=-34 [2011-12-16T02:05:37.584] tasks=5372, current-conns=-37 [2011-12-16T02:05:38.907] tasks=5596, current-conns=-39 [2011-12-16T02:05:40.247] tasks=5845, current-conns=-39 [2011-12-16T02:05:41.600] tasks=6088, current-conns=-40 [2011-12-16T02:05:43.001] tasks=6349, current-conns=-42 [2011-12-16T02:05:44.397] tasks=6624, current-conns=-43 [2011-12-16T02:05:46.177] tasks=6719, current-conns=-44 [2011-12-16T02:05:47.562] tasks=6999, current-conns=-48 [2011-12-16T02:05:48.952] tasks=7267, current-conns=-44 [2011-12-16T02:05:50.309] tasks=7542, current-conns=-45 [2011-12-16T02:05:51.738] tasks=7903, current-conns=-49 [2011-12-16T02:05:53.128] tasks=8208, current-conns=-50 [2011-12-16T02:05:54.528] tasks=8514, current-conns=-48 [2011-12-16T02:05:55.944] tasks=8820, current-conns=-49 [2011-12-16T02:05:57.336] tasks=9119, current-conns=-50 [2011-12-16T02:05:58.744] tasks=9454, current-conns=-50 [2011-12-16T02:06:00.180] tasks=9805, current-conns=-54 [2011-12-16T02:06:01.567] tasks=10000, current-conns=-62 [2011-12-16T02:06:01.585] Waiting for connection leak timeout (600 seconds)... [2011-12-16T02:16:02.992] Test results: statement-leaks=1, connection-leaks=14 Waiting for the domain to stop ..... Command stop-domain executed successfully. Fri Dec 16 02:16:12 CET 2011 : Connection obtained for host: 0.0.0.0, port number 1527. Fri Dec 16 02:16:12 CET 2011 : Apache Derby Network Server - 10.8.1.2 - (1095077) shutdown Command stop-database executed successfully. For using a different JPA implementation inside GlassFish I don't have much experience (it has to work with OSGi, too). Can you recommend some how-to?
        Hide
        ancoron added a comment -

        Attached server-validation.log.gz, which is the server.log for the latest test run with logging kept at INFO.

        Attached server-validation-fine.log.gz, which is the server.log for the latest test run with logging kept at FINE.

        Show
        ancoron added a comment - Attached server-validation.log.gz , which is the server.log for the latest test run with logging kept at INFO. Attached server-validation-fine.log.gz , which is the server.log for the latest test run with logging kept at FINE.
        Hide
        ancoron added a comment -

        Attached the test script test-connection-leaks.sh, which should be put directly into .../glassfish/.

        This script just starts GlassFish, observes various things during the test run and shuts down everything afterwards. So you still have to provide a configured GlassFish first including the test OSGi bundles.

        Show
        ancoron added a comment - Attached the test script test-connection-leaks.sh , which should be put directly into .../glassfish/ . This script just starts GlassFish, observes various things during the test run and shuts down everything afterwards. So you still have to provide a configured GlassFish first including the test OSGi bundles.
        Hide
        Shalini added a comment -

        You could take a glassfish installation from http://dlc.sun.com.edgesuite.net/glassfish/3.1.2/promoted/ and then deploy this application (war/war file) after starting the domain. I still see that connection validation is not turned on. The "is-connection-validation-required" attribute should be set to true and "connection-validation-method" attribute should be set to "table" along with the validation-table-name attribute.

        The log level of resourceadapter could be set to FINE to observe the connection validation failure messages.

        Show
        Shalini added a comment - You could take a glassfish installation from http://dlc.sun.com.edgesuite.net/glassfish/3.1.2/promoted/ and then deploy this application (war/war file) after starting the domain. I still see that connection validation is not turned on. The "is-connection-validation-required" attribute should be set to true and "connection-validation-method" attribute should be set to "table" along with the validation-table-name attribute. The log level of resourceadapter could be set to FINE to observe the connection validation failure messages.
        Hide
        Mitesh Meswani added a comment -

        Assigning to Shalini as the current discussions on this issue are around jdbc connector functionality.

        Show
        Mitesh Meswani added a comment - Assigning to Shalini as the current discussions on this issue are around jdbc connector functionality.
        Hide
        ancoron added a comment -

        I always take the GlassFish binaries from there, anyway...

        I've attached a new version of the test script that now also includes the
        real number of connections established to derby.

        Additionally I've included the database setup into the script prior to
        starting GlassFish to avoid the connection failures at first start.

        With that I've made a new run:

        1. download 3.1.2 promoted b14
        2. copy bundles into .../autodeploy/bundles/
        3. reconfigure default derby connection pool:
          <jdbc-connection-pool name="DerbyPool"
                                datasource-classname="org.apache.derby.jdbc.ClientDataSource"
                                res-type="javax.sql.DataSource"
                                steady-pool-size="1"
                                max-pool-size="10"
                                ping="true"
                                max-wait-time-in-millis="120000"
                                transaction-isolation-level="read-committed"
                                is-connection-validation-required="true"
                                connection-validation-method="table"
                                validation-table-name="mov_video"
                                validate-atmost-once-period-in-seconds="30"
                                fail-all-connections="true"
                                init-sql="SELECT COUNT(*) FROM mov_video"
                                connection-creation-retry-attempts="10"
                                connection-creation-retry-interval-in-seconds="5"
                                max-connection-usage-count="10"
                                idle-timeout-in-seconds="120"
                                connection-leak-timeout-in-seconds="600"
                                connection-leak-reclaim="true"
                                statement-timeout-in-seconds="60"
                                statement-leak-timeout-in-seconds="90"
                                statement-leak-reclaim="true"
                                >
              <property name="PortNumber" value="1527"></property>
              <property name="Password" value="APP"></property>
              <property name="User" value="APP"></property>
              <property name="serverName" value="localhost"></property>
              <property name="DatabaseName" value="sun-appserv-samples"></property>
              <property name="connectionAttributes" value=";create=true"></property>
              <property name="prefer-validate-over-recreate" value="true"></property>
          </jdbc-connection-pool>
          
        4. reconfigure logging to not rotate and set the following:
          javax.enterprise.resource.resourceadapter.level=FINE
          
        5. run the test script inside .../glassfish/:
          ...
          Successfully started the domain : domain1
          domain  Location: /srv/servers/glassfish/3.1.2-b14/glassfish/domains/domain1
          Log File: /srv/servers/glassfish/3.1.2-b14/glassfish/domains/domain1/logs/server.log
          Admin Port: 4848
          Command start-domain executed successfully.
          [2011-12-16T11:17:27.264] ...waiting for deployment to finish...
          [2011-12-16T11:17:35.354] Deployment successful :)
          Command enable-monitoring executed successfully.
          Command enable-monitoring executed successfully.
          [2011-12-16T11:17:40.256] tasks=0, current-conns=10, active-derby-conns=10
          [2011-12-16T11:17:41.339] tasks=0, current-conns=10, active-derby-conns=10
          [2011-12-16T11:17:42.410] tasks=1, current-conns=10, active-derby-conns=10
          [2011-12-16T11:17:43.496] tasks=1, current-conns=5, active-derby-conns=9
          [2011-12-16T11:17:44.565] tasks=1, current-conns=5, active-derby-conns=9
          [2011-12-16T11:17:45.651] tasks=1, current-conns=9, active-derby-conns=9
          [2011-12-16T11:17:46.760] tasks=1, current-conns=10, active-derby-conns=10
          [2011-12-16T11:17:47.873] tasks=1, current-conns=9, active-derby-conns=11
          [2011-12-16T11:17:49.011] tasks=1, current-conns=10, active-derby-conns=10
          [2011-12-16T11:17:51.654] tasks=1, current-conns=9, active-derby-conns=9
          [2011-12-16T11:17:59.728] tasks=1, current-conns=9, active-derby-conns=9
          [2011-12-16T11:18:00.847] tasks=1, current-conns=9, active-derby-conns=10
          [2011-12-16T11:18:01.975] tasks=1, current-conns=9, active-derby-conns=10
          [2011-12-16T11:18:22.888] tasks=1, current-conns=9, active-derby-conns=10
          [2011-12-16T11:18:32.313] tasks=1, current-conns=9, active-derby-conns=10
          [2011-12-16T11:18:33.465] tasks=1, current-conns=9, active-derby-conns=10
          [2011-12-16T11:18:44.495] tasks=1, current-conns=9, active-derby-conns=10
          [2011-12-16T11:18:47.382] tasks=1, current-conns=10, active-derby-conns=10
          [2011-12-16T11:18:48.555] tasks=2, current-conns=10, active-derby-conns=10
          [2011-12-16T11:18:49.962] tasks=3, current-conns=10, active-derby-conns=10
          [2011-12-16T11:18:51.238] tasks=7, current-conns=10, active-derby-conns=10
          [2011-12-16T11:18:52.384] tasks=32, current-conns=7, active-derby-conns=10
          [2011-12-16T11:18:54.027] tasks=56, current-conns=8, active-derby-conns=10
          [2011-12-16T11:18:55.217] tasks=65, current-conns=7, active-derby-conns=10
          [2011-12-16T11:18:56.392] tasks=96, current-conns=7, active-derby-conns=10
          [2011-12-16T11:18:57.572] tasks=132, current-conns=6, active-derby-conns=10
          [2011-12-16T11:18:58.963] tasks=180, current-conns=0, active-derby-conns=6
          [2011-12-16T11:19:00.211] tasks=316, current-conns=-1, active-derby-conns=10
          [2011-12-16T11:19:01.378] tasks=368, current-conns=2, active-derby-conns=9
          [2011-12-16T11:19:02.532] tasks=368, current-conns=2, active-derby-conns=9
          [2011-12-16T11:19:03.897] tasks=449, current-conns=2, active-derby-conns=10
          [2011-12-16T11:19:05.185] tasks=579, current-conns=0, active-derby-conns=10
          [2011-12-16T11:19:06.357] tasks=733, current-conns=-2, active-derby-conns=10
          [2011-12-16T11:19:07.546] tasks=866, current-conns=-2, active-derby-conns=10
          [2011-12-16T11:19:08.756] tasks=1004, current-conns=-2, active-derby-conns=10
          [2011-12-16T11:19:09.945] tasks=1126, current-conns=-3, active-derby-conns=10
          [2011-12-16T11:19:11.141] tasks=1239, current-conns=-6, active-derby-conns=10
          [2011-12-16T11:19:12.422] tasks=1372, current-conns=-7, active-derby-conns=11
          [2011-12-16T11:19:13.648] tasks=1508, current-conns=-6, active-derby-conns=10
          [2011-12-16T11:19:14.872] tasks=1666, current-conns=-6, active-derby-conns=10
          [2011-12-16T11:19:16.110] tasks=1813, current-conns=-9, active-derby-conns=11
          [2011-12-16T11:19:17.327] tasks=1946, current-conns=-11, active-derby-conns=9
          [2011-12-16T11:19:18.578] tasks=2096, current-conns=-9, active-derby-conns=9
          [2011-12-16T11:19:19.797] tasks=2237, current-conns=-11, active-derby-conns=10
          [2011-12-16T11:19:21.024] tasks=2376, current-conns=-14, active-derby-conns=9
          [2011-12-16T11:19:22.288] tasks=2522, current-conns=-15, active-derby-conns=9
          [2011-12-16T11:19:23.772] tasks=2706, current-conns=-17, active-derby-conns=10
          [2011-12-16T11:19:25.151] tasks=2852, current-conns=-19, active-derby-conns=10
          [2011-12-16T11:19:26.404] tasks=2990, current-conns=-23, active-derby-conns=9
          [2011-12-16T11:19:27.664] tasks=3136, current-conns=-23, active-derby-conns=10
          [2011-12-16T11:19:28.894] tasks=3277, current-conns=-26, active-derby-conns=9
          [2011-12-16T11:19:30.193] tasks=3429, current-conns=-27, active-derby-conns=10
          [2011-12-16T11:19:31.461] tasks=3590, current-conns=-27, active-derby-conns=10
          [2011-12-16T11:19:32.867] tasks=3788, current-conns=-30, active-derby-conns=9
          [2011-12-16T11:19:34.132] tasks=3991, current-conns=-37, active-derby-conns=7
          [2011-12-16T11:19:35.437] tasks=4257, current-conns=-33, active-derby-conns=10
          [2011-12-16T11:19:36.729] tasks=4510, current-conns=-33, active-derby-conns=10
          [2011-12-16T11:19:38.026] tasks=4772, current-conns=-34, active-derby-conns=10
          [2011-12-16T11:19:39.314] tasks=4999, current-conns=-36, active-derby-conns=10
          [2011-12-16T11:19:40.712] tasks=5230, current-conns=-34, active-derby-conns=10
          [2011-12-16T11:19:42.032] tasks=5428, current-conns=-34, active-derby-conns=10
          [2011-12-16T11:19:43.331] tasks=5691, current-conns=-35, active-derby-conns=10
          [2011-12-16T11:19:44.629] tasks=5962, current-conns=-37, active-derby-conns=9
          [2011-12-16T11:19:45.929] tasks=6204, current-conns=-41, active-derby-conns=9
          [2011-12-16T11:19:47.243] tasks=6443, current-conns=-40, active-derby-conns=11
          [2011-12-16T11:19:48.558] tasks=6655, current-conns=-42, active-derby-conns=10
          [2011-12-16T11:19:49.884] tasks=6872, current-conns=-41, active-derby-conns=10
          [2011-12-16T11:19:51.260] tasks=7250, current-conns=-49, active-derby-conns=10
          [2011-12-16T11:19:52.618] tasks=7746, current-conns=-43, active-derby-conns=10
          [2011-12-16T11:19:53.964] tasks=8160, current-conns=-43, active-derby-conns=11
          [2011-12-16T11:19:55.326] tasks=8543, current-conns=-47, active-derby-conns=9
          [2011-12-16T11:19:56.734] tasks=8777, current-conns=-46, active-derby-conns=10
          [2011-12-16T11:19:58.132] tasks=9159, current-conns=-47, active-derby-conns=10
          [2011-12-16T11:19:59.555] tasks=9671, current-conns=-50, active-derby-conns=10
          [2011-12-16T11:20:00.898] tasks=9997, current-conns=-58, active-derby-conns=9
          [2011-12-16T11:20:02.260] tasks=9997, current-conns=-58, active-derby-conns=9
          [2011-12-16T11:20:03.606] tasks=9998, current-conns=-58, active-derby-conns=8
          [2011-12-16T11:20:04.968] tasks=9999, current-conns=-58, active-derby-conns=7
          [2011-12-16T11:20:06.336] tasks=10000, current-conns=-58, active-derby-conns=6
          [2011-12-16T11:20:06.348] Waiting for connection leak timeout (600 seconds)...
          [2011-12-16T11:20:56.362] ...550 seconds left...
          [2011-12-16T11:21:56.383] ...490 seconds left...
          [2011-12-16T11:22:56.404] ...430 seconds left...
          [2011-12-16T11:23:56.425] ...370 seconds left...
          [2011-12-16T11:24:56.446] ...310 seconds left...
          [2011-12-16T11:25:56.467] ...250 seconds left...
          [2011-12-16T11:26:56.488] ...190 seconds left...
          [2011-12-16T11:27:56.509] ...130 seconds left...
          [2011-12-16T11:28:56.528] ...70 seconds left...
          [2011-12-16T11:29:56.549] ...10 seconds left...
          [2011-12-16T11:30:06.608] Test results: statement-leaks=0, connection-leaks=10
          ...
          


        I've also attached a new server.log: server-validate-fine-b14.log.gz

        I hope I now did everything correctly to get connection validation.

        If you want to have a look at the full code of the test bundles, just go here:

        Show
        ancoron added a comment - I always take the GlassFish binaries from there, anyway... I've attached a new version of the test script that now also includes the real number of connections established to derby. Additionally I've included the database setup into the script prior to starting GlassFish to avoid the connection failures at first start. With that I've made a new run: download 3.1.2 promoted b14 copy bundles into .../autodeploy/bundles/ reconfigure default derby connection pool: <jdbc-connection-pool name="DerbyPool" datasource-classname="org.apache.derby.jdbc.ClientDataSource" res-type="javax.sql.DataSource" steady-pool-size="1" max-pool-size="10" ping="true" max-wait-time-in-millis="120000" transaction-isolation-level="read-committed" is-connection-validation-required="true" connection-validation-method="table" validation-table-name="mov_video" validate-atmost-once-period-in-seconds="30" fail-all-connections="true" init-sql="SELECT COUNT(*) FROM mov_video" connection-creation-retry-attempts="10" connection-creation-retry-interval-in-seconds="5" max-connection-usage-count="10" idle-timeout-in-seconds="120" connection-leak-timeout-in-seconds="600" connection-leak-reclaim="true" statement-timeout-in-seconds="60" statement-leak-timeout-in-seconds="90" statement-leak-reclaim="true" > <property name="PortNumber" value="1527"></property> <property name="Password" value="APP"></property> <property name="User" value="APP"></property> <property name="serverName" value="localhost"></property> <property name="DatabaseName" value="sun-appserv-samples"></property> <property name="connectionAttributes" value=";create=true"></property> <property name="prefer-validate-over-recreate" value="true"></property> </jdbc-connection-pool> reconfigure logging to not rotate and set the following: javax.enterprise.resource.resourceadapter.level=FINE run the test script inside .../glassfish/ : ... Successfully started the domain : domain1 domain Location: /srv/servers/glassfish/3.1.2-b14/glassfish/domains/domain1 Log File: /srv/servers/glassfish/3.1.2-b14/glassfish/domains/domain1/logs/server.log Admin Port: 4848 Command start-domain executed successfully. [2011-12-16T11:17:27.264] ...waiting for deployment to finish... [2011-12-16T11:17:35.354] Deployment successful :) Command enable-monitoring executed successfully. Command enable-monitoring executed successfully. [2011-12-16T11:17:40.256] tasks=0, current-conns=10, active-derby-conns=10 [2011-12-16T11:17:41.339] tasks=0, current-conns=10, active-derby-conns=10 [2011-12-16T11:17:42.410] tasks=1, current-conns=10, active-derby-conns=10 [2011-12-16T11:17:43.496] tasks=1, current-conns=5, active-derby-conns=9 [2011-12-16T11:17:44.565] tasks=1, current-conns=5, active-derby-conns=9 [2011-12-16T11:17:45.651] tasks=1, current-conns=9, active-derby-conns=9 [2011-12-16T11:17:46.760] tasks=1, current-conns=10, active-derby-conns=10 [2011-12-16T11:17:47.873] tasks=1, current-conns=9, active-derby-conns=11 [2011-12-16T11:17:49.011] tasks=1, current-conns=10, active-derby-conns=10 [2011-12-16T11:17:51.654] tasks=1, current-conns=9, active-derby-conns=9 [2011-12-16T11:17:59.728] tasks=1, current-conns=9, active-derby-conns=9 [2011-12-16T11:18:00.847] tasks=1, current-conns=9, active-derby-conns=10 [2011-12-16T11:18:01.975] tasks=1, current-conns=9, active-derby-conns=10 [2011-12-16T11:18:22.888] tasks=1, current-conns=9, active-derby-conns=10 [2011-12-16T11:18:32.313] tasks=1, current-conns=9, active-derby-conns=10 [2011-12-16T11:18:33.465] tasks=1, current-conns=9, active-derby-conns=10 [2011-12-16T11:18:44.495] tasks=1, current-conns=9, active-derby-conns=10 [2011-12-16T11:18:47.382] tasks=1, current-conns=10, active-derby-conns=10 [2011-12-16T11:18:48.555] tasks=2, current-conns=10, active-derby-conns=10 [2011-12-16T11:18:49.962] tasks=3, current-conns=10, active-derby-conns=10 [2011-12-16T11:18:51.238] tasks=7, current-conns=10, active-derby-conns=10 [2011-12-16T11:18:52.384] tasks=32, current-conns=7, active-derby-conns=10 [2011-12-16T11:18:54.027] tasks=56, current-conns=8, active-derby-conns=10 [2011-12-16T11:18:55.217] tasks=65, current-conns=7, active-derby-conns=10 [2011-12-16T11:18:56.392] tasks=96, current-conns=7, active-derby-conns=10 [2011-12-16T11:18:57.572] tasks=132, current-conns=6, active-derby-conns=10 [2011-12-16T11:18:58.963] tasks=180, current-conns=0, active-derby-conns=6 [2011-12-16T11:19:00.211] tasks=316, current-conns=-1, active-derby-conns=10 [2011-12-16T11:19:01.378] tasks=368, current-conns=2, active-derby-conns=9 [2011-12-16T11:19:02.532] tasks=368, current-conns=2, active-derby-conns=9 [2011-12-16T11:19:03.897] tasks=449, current-conns=2, active-derby-conns=10 [2011-12-16T11:19:05.185] tasks=579, current-conns=0, active-derby-conns=10 [2011-12-16T11:19:06.357] tasks=733, current-conns=-2, active-derby-conns=10 [2011-12-16T11:19:07.546] tasks=866, current-conns=-2, active-derby-conns=10 [2011-12-16T11:19:08.756] tasks=1004, current-conns=-2, active-derby-conns=10 [2011-12-16T11:19:09.945] tasks=1126, current-conns=-3, active-derby-conns=10 [2011-12-16T11:19:11.141] tasks=1239, current-conns=-6, active-derby-conns=10 [2011-12-16T11:19:12.422] tasks=1372, current-conns=-7, active-derby-conns=11 [2011-12-16T11:19:13.648] tasks=1508, current-conns=-6, active-derby-conns=10 [2011-12-16T11:19:14.872] tasks=1666, current-conns=-6, active-derby-conns=10 [2011-12-16T11:19:16.110] tasks=1813, current-conns=-9, active-derby-conns=11 [2011-12-16T11:19:17.327] tasks=1946, current-conns=-11, active-derby-conns=9 [2011-12-16T11:19:18.578] tasks=2096, current-conns=-9, active-derby-conns=9 [2011-12-16T11:19:19.797] tasks=2237, current-conns=-11, active-derby-conns=10 [2011-12-16T11:19:21.024] tasks=2376, current-conns=-14, active-derby-conns=9 [2011-12-16T11:19:22.288] tasks=2522, current-conns=-15, active-derby-conns=9 [2011-12-16T11:19:23.772] tasks=2706, current-conns=-17, active-derby-conns=10 [2011-12-16T11:19:25.151] tasks=2852, current-conns=-19, active-derby-conns=10 [2011-12-16T11:19:26.404] tasks=2990, current-conns=-23, active-derby-conns=9 [2011-12-16T11:19:27.664] tasks=3136, current-conns=-23, active-derby-conns=10 [2011-12-16T11:19:28.894] tasks=3277, current-conns=-26, active-derby-conns=9 [2011-12-16T11:19:30.193] tasks=3429, current-conns=-27, active-derby-conns=10 [2011-12-16T11:19:31.461] tasks=3590, current-conns=-27, active-derby-conns=10 [2011-12-16T11:19:32.867] tasks=3788, current-conns=-30, active-derby-conns=9 [2011-12-16T11:19:34.132] tasks=3991, current-conns=-37, active-derby-conns=7 [2011-12-16T11:19:35.437] tasks=4257, current-conns=-33, active-derby-conns=10 [2011-12-16T11:19:36.729] tasks=4510, current-conns=-33, active-derby-conns=10 [2011-12-16T11:19:38.026] tasks=4772, current-conns=-34, active-derby-conns=10 [2011-12-16T11:19:39.314] tasks=4999, current-conns=-36, active-derby-conns=10 [2011-12-16T11:19:40.712] tasks=5230, current-conns=-34, active-derby-conns=10 [2011-12-16T11:19:42.032] tasks=5428, current-conns=-34, active-derby-conns=10 [2011-12-16T11:19:43.331] tasks=5691, current-conns=-35, active-derby-conns=10 [2011-12-16T11:19:44.629] tasks=5962, current-conns=-37, active-derby-conns=9 [2011-12-16T11:19:45.929] tasks=6204, current-conns=-41, active-derby-conns=9 [2011-12-16T11:19:47.243] tasks=6443, current-conns=-40, active-derby-conns=11 [2011-12-16T11:19:48.558] tasks=6655, current-conns=-42, active-derby-conns=10 [2011-12-16T11:19:49.884] tasks=6872, current-conns=-41, active-derby-conns=10 [2011-12-16T11:19:51.260] tasks=7250, current-conns=-49, active-derby-conns=10 [2011-12-16T11:19:52.618] tasks=7746, current-conns=-43, active-derby-conns=10 [2011-12-16T11:19:53.964] tasks=8160, current-conns=-43, active-derby-conns=11 [2011-12-16T11:19:55.326] tasks=8543, current-conns=-47, active-derby-conns=9 [2011-12-16T11:19:56.734] tasks=8777, current-conns=-46, active-derby-conns=10 [2011-12-16T11:19:58.132] tasks=9159, current-conns=-47, active-derby-conns=10 [2011-12-16T11:19:59.555] tasks=9671, current-conns=-50, active-derby-conns=10 [2011-12-16T11:20:00.898] tasks=9997, current-conns=-58, active-derby-conns=9 [2011-12-16T11:20:02.260] tasks=9997, current-conns=-58, active-derby-conns=9 [2011-12-16T11:20:03.606] tasks=9998, current-conns=-58, active-derby-conns=8 [2011-12-16T11:20:04.968] tasks=9999, current-conns=-58, active-derby-conns=7 [2011-12-16T11:20:06.336] tasks=10000, current-conns=-58, active-derby-conns=6 [2011-12-16T11:20:06.348] Waiting for connection leak timeout (600 seconds)... [2011-12-16T11:20:56.362] ...550 seconds left... [2011-12-16T11:21:56.383] ...490 seconds left... [2011-12-16T11:22:56.404] ...430 seconds left... [2011-12-16T11:23:56.425] ...370 seconds left... [2011-12-16T11:24:56.446] ...310 seconds left... [2011-12-16T11:25:56.467] ...250 seconds left... [2011-12-16T11:26:56.488] ...190 seconds left... [2011-12-16T11:27:56.509] ...130 seconds left... [2011-12-16T11:28:56.528] ...70 seconds left... [2011-12-16T11:29:56.549] ...10 seconds left... [2011-12-16T11:30:06.608] Test results: statement-leaks=0, connection-leaks=10 ... I've also attached a new server.log: server-validate-fine-b14.log.gz I hope I now did everything correctly to get connection validation. If you want to have a look at the full code of the test bundles, just go here: https://github.com/ancoron/osgi-tests
        Hide
        Shalini added a comment -

        Looks like this is an issue with the max-connection-usage count attribute only. When i executed the test case without leak tracing
        off, i could reproduce this issue. Will put in a fix for this issue soon.

        Show
        Shalini added a comment - Looks like this is an issue with the max-connection-usage count attribute only. When i executed the test case without leak tracing off, i could reproduce this issue. Will put in a fix for this issue soon.
        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: