如何记录 Tomcat 7 JDBC 连接池、连接创建

Question

尽管我们使用的是 Tomcat 7 JDBC 连接池，但我正在尝试调试似乎打开和关闭的数据库连接数量过多的问题。当在数据源上调用 getConnection() 导致打开新连接而不是从池中借用现有连接时，如何记录？

Answer 1

我知道查看 Tomcat 数据库连接池信息的两种方法。

1. 使用 JMX 监控

默认情况下，Tomcat 连接池会将自己注册为 MBean（JMX Bean）。可以使用 tomcat-jdbc-pool 上的 jmxEnabled 属性打开/关闭此功能。见The Tomcat JDBC Connection Pool。

您可以使用各种外部 JMX 工具来监控 DB 连接池和其他 JMX 资源。我建议从 Java 附带的 JConsole 开始。启动 JConsole，连接到您的 Tomcat (Catalina) JVM，选择 MBeans 标头，打开 Catalina/DataSource/... 见下图。

阅读更多Monitoring Tomcat。

2. 编写 JdbcInterceptor 类，记录 DB Connection Pool 信息

Tomcat 连接池允许您为 JDBC 连接注册拦截器。下面，我将展示如何编写一个记录连接使用情况的JdbcInterceptor 类。该示例适用于 Tomcat 8，但它也可能适用于 Tomcat 7。

将 tomcat-jdbc.jar 作为提供的依赖项添加到您的项目中。

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

创建一个 JdbcInterceptor 类

这个类使用公共日志，你可能想使用别的东西。

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()));
            }
        }
    }
}

在 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 类可以注册为Resource，如上所示，也可以注册为POJO。

日志样本

以下是访问连接池时来自 Tomcat 的一些示例日志

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]

Answer 2

我今天遇到了类似的情况。我通过slf4j登录，我的问题是hibernate引起的。

我所做的是在日志配置中设置调用 JDBC 连接 getter 的空间。幸运的是，对于休眠，那里有调试级别的日志。

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

我的猜测是，对于您的情况，您可以尝试对调用 JDBC 池 getter 的命名空间执行等效操作。可能是这样的：

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

我希望这会有所帮助。使用休眠我得到这样的结果：

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)

...