Java – How to log Tomcat 7 JDBC connection pool, connection creation

connection-poolingjavajdbctomcattomcat7

I'm trying to debug what seems to be an excessive number of database connections being opened and closed despite the fact that we are using the Tomcat 7 JDBC connection pool. How can I log when calling getConnection() on the data source results in a new connection being opened versus an existing connection being borrowed from the pool?

Best Answer

I know of two ways to look at the Tomcat DB Connection Pool info.

1. Using JMX Monitoring

The Tomcat Connection Pool by default will register itself as an MBean (JMX Bean). This feature can be turned on/off with the jmxEnabled attribute on the tomcat-jdbc-pool. See The Tomcat JDBC Connection Pool.

You can use various external JMX tools to monitor the DB Connection Pool and other JMX resources. I would suggest starting with JConsole, which comes with Java. Launch JConsole, connect to your Tomcat (Catalina) JVM, select MBeans header, open Catalina/DataSource/... see pic below.

JConsole showing DataSource / DB Connection Pool

Read more on Monitoring Tomcat.

2. Write a JdbcInterceptor class that logs DB Connection Pool info

The Tomcat connection pool allows you to register interceptors for JDBC Connections. Below, I will show how to write a JdbcInterceptor class that logs connection usage. The example is for Tomcat 8, but it might work for Tomcat 7 as well.

Add tomcat-jdbc.jar as a provided dependency to your project.

    <dependency>
        <groupId>org.apache.tomcat</groupId>
        <artifactId>tomcat-jdbc</artifactId>
        <version>8.0.8</version>
        <scope>provided</scope>
    </dependency>

Create a JdbcInterceptor class

This class uses commons logging, you may want to use something else.

package com.acme.rest.config;

import java.lang.reflect.Method;

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.apache.tomcat.jdbc.pool.ConnectionPool;
import org.apache.tomcat.jdbc.pool.JdbcInterceptor;
import org.apache.tomcat.jdbc.pool.PooledConnection;

public class MyConnectionPoolLogger extends JdbcInterceptor {

    private static final Log log = LogFactory.getLog(MyConnectionPoolLogger.class);

    @Override
    public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {
        if (log.isDebugEnabled()) {
            String name = method.getName();
            if (CLOSE_VAL.equals(name)) {
                log.debug(String.format("Returning Connection to Pool [%s]", proxy));
            }
        }
        return super.invoke(proxy, method, args);
    }

    @Override
    public void reset(ConnectionPool connPool, PooledConnection conn) {
        if (connPool != null && conn != null) {
            if (log.isDebugEnabled()) {
                log.debug(String.format("Getting Connection [%s], Pool active=[%s], idle=[%s]", conn.toString(),
                        connPool.getActive(), connPool.getIdle()));
            }
        }
    }

    @Override
    public void disconnected(ConnectionPool connPool, PooledConnection conn, boolean finalizing) {
        if (connPool != null && conn != null) {
            if (log.isDebugEnabled()) {
                log.debug(String.format("Closing Connection [%s], Pool active=[%s], idle=[%s]", conn.toString(),
                        connPool.getActive(), connPool.getIdle()));
            }
        }
    }
}

Register this interceptor class in Context.xml

<Context>
  <Resource 
    name="jdbc/acmedb"
    auth="Container"
    type="javax.sql.DataSource"
    factory="org.apache.tomcat.jdbc.pool.DataSourceFactory"

    jdbcInterceptors="org.apache.tomcat.jdbc.pool.interceptor.ConnectionState;
      org.apache.tomcat.jdbc.pool.interceptor.StatementFinalizer; 
      com.acme.rest.config.MyConnectionPoolLogger"

  />
</Context>

JdbcInterceptor classes can be registered as either a Resource, as shown above, or as a POJO.

Log Samples

Below are some sample logs from Tomcat when accessing the Connection Pool

2017-11-04 00:15:19,389 DEBUG Getting Connection [PooledConnection[com.mysql.jdbc.JDBC4Connection@6dea96f]], Pool active=[1], idle=[0]
2017-11-04 00:15:19,393 DEBUG Returning Connection to Pool [ProxyConnection[PooledConnection[com.mysql.jdbc.JDBC4Connection@6dea96f]]]
2017-11-04 00:16:19,249 DEBUG Closing Connection [PooledConnection[com.mysql.jdbc.JDBC4Connection@6dea96f]], Pool active=[0], idle=[1]
Related Topic