How to detect leaked datasource connections using the cached connection manager (CCM) debug facility in JBoss EAP

Solution Verified - Updated -

Environment

  • Red Hat JBoss Enterprise Application Platform (EAP)
    • 6
    • 7

Issue

  • How can I detect leaked datasource connections?
  • How to detect leaked JMS connections?
  • How can I identify code which leaks datasource connections?
  • "IJ000453: Unable to get managed connection for ..."
  • "IJ000655: No managed connections available within configured blocking timeout ..."
  • Application is not able to obtain a new connection from a connection pool but INACTIVE session count (reported by the database server) is increasing.
  • Does JBoss close a connection leak automatically?

Resolution

To enable the cached connection manager (CCM) to identify a connection leak:

  • Verify that <cached-connection-manager> exists in the jca subsystem and set debug="true".

           <subsystem xmlns="urn:jboss:domain:jca:1.1">
          ...
          <cached-connection-manager debug="true" error="false"/>
          ...
       </subsystem>

    • CLI commands

      • NOTE : while CLI may be run to configure running servers, a restart should be performed for the server where debug is required to ensure the debug setting is applied to the CCM
      • Standalone Mode
      /subsystem=jca/cached-connection-manager=cached-connection-manager:write-attribute(name=debug,value=true)
      • Domain Mode
      /profile=<your_profile_here>/subsystem=jca/cached-connection-manager=cached-connection-manager:write-attribute(name=debug,value=true)`

    • For scenarios where connections are not returned to the pool at the end of the context in which they were initially taken from the pool, setting debug="true" will:

      • Log an INFO message indicating that JBoss is "Closing a connection for you. Please close them yourself"
      • Generate and log a stacktrace for the code where the leaked connection was first opened.
      • Close the leaked connection

  • Re-enable CCM for the datasource if it has been disabled1. Note that use-ccm defaults to true for each pool (and is expected to be enabled for production pools) so this step should not not normally be required.

        <subsystem xmlns="urn:jboss:domain:datasources:1.1">
       <datasources>
          <datasource ... enabled="true" use-ccm="true">
             ...
          </datasource>
       </datasources>
    </subsystem>

    • CLI commands (Note: these commands are required only if use-ccm has been disabled1 for the pool)

      • Standalone Mode
       /subsystem=datasources/data-source=<your_pool_name_here>:write-attribute(name=use-ccm,value=true)
      • Domain Mode
      /profile=<your_profile_here>/subsystem=datasources/data-source=<your_pool_name_here>:write-attribute(name=use-ccm,value=true)

    • When turning off/disabling CCM debug (after troubleshooting), use-ccm should NOT be set to false - use-ccm is expected to remain enabled for production pools and only the debug flag requires change.

  • The additional property error may be used to raise a RuntimeException and generate an ERROR message in the log when it is set to true.

  • NOTE : For EAP releases earlier than EAP 7.1, jta MUST also be set to true for the datasource in order for cached connection manager debug to work.
  • Restart JBoss to ensure that the changes are applied.

Log Examples

Example with debug="true" without error="true" (i.e. <cached-connection-manager debug="true" /> or <cached-connection-manager debug="true" error="false" />):

... INFO  [org.jboss.jca.core.api.connectionmanager.ccm.CachedConnectionManager] (http-/127.0.0.1:8080-1) IJ000100: Closing a connection for you. Please close them yourself: org.jboss.jca.adapters.jdbc.jdk6.WrappedConnectionJDK6@6f1170a9: java.lang.Throwable: STACKTRACE
    at org.jboss.jca.core.connectionmanager.ccm.CachedConnectionManagerImpl.registerConnection(CachedConnectionManagerImpl.java:269)
    at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:495)
    at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:139)
        ...

Example with debug="true" and error="true" (i.e. <cached-connection-manager debug="true" error="true"/>):

... INFO  [org.jboss.jca.core.api.connectionmanager.ccm.CachedConnectionManager] (http-/127.0.0.1:8080-1) IJ000100: Closing a connection for you. Please close them yourself: org.jboss.jca.adapters.jdbc.jdk6.WrappedConnectionJDK6@27c94e11: java.lang.Throwable: STACKTRACE
    at org.jboss.jca.core.connectionmanager.ccm.CachedConnectionManagerImpl.registerConnection(CachedConnectionManagerImpl.java:269)
    at org.jboss.jca.core.connectionmanager.AbstractConnectionManager.allocateConnection(AbstractConnectionManager.java:495)
    at org.jboss.jca.adapters.jdbc.WrapperDataSource.getConnection(WrapperDataSource.java:139)
        ...
ERROR [org.apache.catalina.connector.CoyoteAdapter] (http-/127.0.0.1:8080-1) An exception or error occurred in the container during the request processing: java.lang.RuntimeException: java.lang.RuntimeException: javax.resource.ResourceException: IJ000151: Some connections were not closed, see the log for the allocation stacktraces
    at org.jboss.as.web.ThreadSetupBindingListener.unbind(ThreadSetupBindingListener.java:67) [jboss-as-web-7.1.3.Final-redhat-4.jar:7.1.3.Final-redhat-4]
        ...
Caused by: java.lang.RuntimeException: javax.resource.ResourceException: IJ000151: Some connections were not closed, see the log for the allocation stacktraces
    at org.jboss.as.connector.deployers.ra.processors.CachedConnectionManagerSetupProcessor$CachedConnectionManagerSetupAction.teardown(CachedConnectionManagerSetupProcessor.java:85)
    at org.jboss.as.web.ThreadSetupBindingListener.unbind(ThreadSetupBindingListener.java:61) [jboss-as-web-7.1.3.Final-redhat-4.jar:7.1.3.Final-redhat-4]
    ... 8 more
Caused by: javax.resource.ResourceException: IJ000151: Some connections were not closed, see the log for the allocation stacktraces
    at org.jboss.jca.core.connectionmanager.ccm.CachedConnectionManagerImpl.popMetaAwareObject(CachedConnectionManagerImpl.java:249)
    at org.jboss.as.connector.deployers.ra.processors.CachedConnectionManagerSetupProcessor$CachedConnectionManagerSetupAction.teardown(CachedConnectionManagerSetupProcessor.java:83)
    ... 9 more

Example of leaked JMS connection report:

... INFO  [org.jboss.jca.core.api.connectionmanager.ccm.CachedConnectionManager] (Thread-1 (ActiveMQ-client-global-threads)) IJ000100: Closing a connection for you. Please close them yourself: org.apache.activemq.artemis.ra.ActiveMQRASession@325565b3: java.lang.Throwable: STACKTRACE
    at org.jboss.jca.core.connectionmanager.ccm.CachedConnectionManagerImpl.registerConnection(CachedConnectionManagerImpl.java:308)
        ...

Additional Notes

  • If leaks are believed to be present but nothing is reported by the CCM verify the following:
    • The datasource must not be configured with use-ccm="false" (the value will default to "true" if not set explicitly)
    • The datasource must not be configured with jta="false" in versions prior to EAP 7.1.
      • In EAP 7.1 and later, this limitation (inability to perform leak detection using the cached connection manager debug facility for non-JTA-enabled pools) has been removed and cached connection manager debug may be used with both JTA and non-JTA pools. However, in most cases, JTA should not be disabled for production datasources.
      • For non-JTA-enabled pools, in JBoss EAP 6.4 and 7.0, the LeakDumperManagedConnectionPool may be used to work around the cached connection manager debug facility's limitation.
    • The minimum logging level must be INFO for org.jboss.jca (verify that other logging settings - e.g. log level thresholds may be set at "destination" level for the FILE or other loggers - do not override this).
  • Activating debug will have some impact on performance and log file size and it is, therefore, recommended that the debug configuration be used only during development or test cycles.
    • See also What causes 'Closing a connection for you... which demonstrates proper closure of connection resources.
    • After verifying that no leaks exist/remain, restore the configuration by removing the debug="true" setting or using <cached-connection-manager debug="false"/> (before deploying in production).
    • Failure to return connections obtained from the pool is a defect in code (whether application layer or 3rd party components) that uses the datasource pool. The cached connection manager debug facility is intended to be used to identify leaks in application code (using the stack traces reported with the IJ000100 messages) so that they can be corrected. The side effect (forced closure of leaked connections) of the debug facility is not meant to be relied upon as a workaround for application or 3rd party component defects.
  • To track the usage of datasource connections you can also enable datasource logging
  • Setting error to true is not recommended for production deployment. Where debug is required in production deployments, setting debug="true" should provide adequate information to diagnose the issue.
  • In addition to providing support for debugging, the CCM is also used to support lazy enlistment of connections in transactions.
    • The CCM (without debug enabled) is enabled by default and its use is normal for production systems
  • To detect leaked JMS pool connections only the jca subsystem configuration detailed above is required.

  1. use-ccm is not expected to be disabled in most production environments - there are no known advantages to disabling CCM ↩︎ ↩︎

Diagnostic Steps

Byteman Based Tracking of Connection Usage

It is also possible to dynamically enable Byteman trace and deploy the two rules below to trace connection request and release (back to the pool). The internal pooledId can be correlated with org.jboss.jca tracing which reports on the population of in-use (reserved by application logic) and unused (but pooled) connections. The maxFrames parameter (i.e. the last parameter) in the traceStack(...) calls may be adjusted to increase context to include additional application and JBoss stack frames.

# When using JBoss EAP 6 or 7
RULE ConnectionManagerRegisterAssociation
CLASS AbstractConnectionManager
METHOD registerAssociation
AT ENTRY
IF callerEquals("WrapperDataSource.getConnection", true, 3)
# Change the frame count (last parameter below) to refine the size of the stack trace - e.g. change 20 to 4
DO traceStack("CONNECTION TRACE - getConnection(pool=" + $1.getPool().getName()
   + ") => " + $2 + "(pooledId=" + Integer.toHexString(System.identityHashCode($1)) + ")\n", 20);
ENDRULE

# When using JBoss EAP 6
RULE ConnectionManagerUnregisterAssociation
CLASS AbstractConnectionManager
METHOD unregisterAssociation
AT ENTRY
IF callerEquals("WrappedConnection.close", true, 5)
# Change the frame count (last parameter below) to refine the size of the stack trace - e.g. change 20 to 6
DO traceStack("CONNECTION TRACE - closeConnection(" + $2
   + "(pooledId=" + Integer.toHexString(System.identityHashCode($1)) + ")) => pool="
   + $1.getPool().getName() + "\n", 20);
ENDRULE

# When using JBoss EAP 7
RULE ConnectionManagerUnregisterConnection
INTERFACE ^CachedConnectionManager
METHOD unregisterConnection
AT ENTRY
BIND listener:org.jboss.jca.core.connectionmanager.listener.ConnectionListener = $2;
IF callerEquals("WrappedConnection.close", true, 5)
# Change the frame count (last parameter below) to refine the size of the stack trace - e.g. change 20 to 6
DO traceStack("CONNECTION TRACE - closeConnection(" + $3
   + "(pooledId=" + Integer.toHexString(System.identityHashCode($3)) + ")) => pool="
   + listener.getPool().getName() + "\n", 20);
ENDRULE

Heap Examination

In looking at heap dumps, use the OQL below (adapt the from class to the pool type used) to examine key details of connection pools

-- active shows the number of open/established connections (including inUse and idle)
-- checkedOut shows the reserved connections (owned by application components/clients of the pool)

-- Default pool for EAP 7 (note that it tracks active rather than idle)
-- SemaphoreConcurrentLinkedDequeManagedConnectionPool type
select p.pool.poolName.toString() AS poolName,
    p.checkedOutSize.value AS inUse,
    p.cls.baseCount AS active,
    p.poolConfiguration.maxSize.value.toString() AS maxSize,
    p.poolConfiguration.minSize.value.toString() AS minSize,
    p.poolConfiguration.strictMin.value.toString() AS useStrictMin,
    p.poolConfiguration.prefill.value.toString() AS prefill
from org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreConcurrentLinkedDequeManagedConnectionPool p

-- Default pool for EAP 6 (note that it tracks idle rather than active)
-- SemaphoreArrayListManagedConnectionPool type
select p.pool.poolName.toString() AS poolName,
    p.checkedOut.size AS inUse,
    p.cls.size AS idle,
    p.poolConfiguration.maxSize.value.toString() AS maxSize,
    p.poolConfiguration.minSize.value.toString() AS minSize,
    p.poolConfiguration.strictMin.value.toString() AS useStrictMin,
    p.poolConfiguration.prefill.value.toString() AS prefill
from org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool p

-- Debug pool (note that it tracks idle rather than active)
-- LeakDumperManagedConnectionPool type
select p.pool.poolName.toString() AS poolName,
    p.checkedOut.size AS inUse,
    p.cls.size AS idle,
    p.poolConfiguration.maxSize.value.toString() AS maxSize,
    p.poolConfiguration.minSize.value.toString() AS minSize,
    p.poolConfiguration.strictMin.value.toString() AS useStrictMin,
    p.poolConfiguration.prefill.value.toString() AS prefill
from org.jboss.jca.core.connectionmanager.pool.mcp.LeakDumperManagedConnectionPool p

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.

Comments