How to log Tomcat 7 JDBC connection pool, connection creation

Question

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?

Boiling

Oh wow, I never knew Tomcat had it's own CP. Anyway, why do you want to do it client side? It's so much easier to do DB side in most cases – Enmity

Are you looking for a tomcat config or a normal logging? – Mum

I prefer client side. There are many different clients that could connect to the DB using the same credentials. I'm trying to diagnose client side problems, possibly with the pool. Whatever helps understand when a new connection is open and why. Thanks! – Boiling

Answer 1

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.

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]

Gadhelic

This is a really useful snippet. Thanks for taking the time to post this. – Arvind

Answer 2

I have faced a similar case today. I log through slf4j, and my problem was caused by hibernate.

What I've done is setting up in the log configuration the space where the JDBC connection getter is called. Fortunately, for hibernate there are logs at debug level there.

<logger name="org.hibernate.engine.jdbc">
    <level value="debug"/>
</logger>

My guess is that for your case you can attempt to do something equivalent with the namespace where your JDBC pool getter is invoked. It could be something like this:

<logger name="org.apache.tomcat.jdbc.pool">
    <level value="debug"/>
</logger>

I hope this helps. With hibernate I get something like this as a result:

DEBUG 02.07.2015 16:36:50,571 http-bio-8080-exec-33 (org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection():212) [] - Obtaining JDBC connection
DEBUG 02.07.2015 16:36:50,601 http-bio-8080-exec-6 (org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection():218) [] - Obtained JDBC connection
DEBUG 02.07.2015 16:36:50,627 http-bio-8080-exec-10 (org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection():218) [] - Obtained JDBC connection
DEBUG 02.07.2015 16:36:50,643 http-bio-8080-exec-32 (org.hibernate.engine.jdbc.spi.SqlExceptionHelper.logExceptions():139) [] - Could not open connection [n/a]
org.apache.tomcat.dbcp.dbcp.SQLNestedException: Cannot get a connection, pool error Timeout waiting for idle object
    at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:114)
    at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044)

...

Premier