java - How to log JDBC connection activity?

Question

How can I see when my pooling library (C3P0) is creating and closing JDBC connections?

Note: I have done research on this and already found a solution. I'm posting it here so that it may be useful to others and I can refer back to it in case I forget it in future.

Other approaches/answers are welcome.

Answer 1

log4jdbc library can be used to log JDBC connections. Add this library to POM -

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-log4j12</artifactId>
    <version>1.6.4</version>
</dependency>

<dependency>
    <groupId>org.lazyluke</groupId>
    <artifactId>log4jdbc-remix</artifactId>
    <version>0.2.7</version>
</dependency>

Configure log4j.properties. Modify logging options to adjust the level of details as per your own needs.

log4j.rootLogger=INFO,R, FILE
log4j.appender.R=org.apache.log4j.ConsoleAppender
log4j.appender.R.layout=org.apache.log4j.PatternLayout
log4j.appender.R.layout.ConversionPattern=%d{ISO8601} %5p %t %c - %m%n

log4j.appender.FILE=org.apache.log4j.DailyRollingFileAppender
log4j.appender.FILE.layout=org.apache.log4j.PatternLayout
log4j.appender.FILE.layout.ConversionPattern=%d{ISO8601} %5p %t %c - %m%n
log4j.appender.FILE.File=/home/kshitiz/Documents/tomcat.log
log4j.appender.FILE.DatePattern='.'yyyy-MM-dd

# Application logging options
log4j.logger.org.apache=ERROR
log4j.logger.org.springframework.jdbc.core.JdbcTemplate=DEBUG
log4j.logger.MySQL=ERROR
log4j.logger.org.springframework=DEBUG
log4j.logger.jdbc.sqlonly=OFF
log4j.logger.jdbc.sqltiming=ERROR
log4jdbc.sqltiming.error.threshold=10
log4j.logger.jdbc.audit=OFF
log4j.logger.jdbc.resultset=ERROR
log4j.logger.jdbc.connection=ALL
log4j.logger.jdbc.resultsettable=OFF


# Setup vm levels
log4j.logger.vm.none=FATAL
log4j.logger.vm.error=ERROR
log4j.logger.vm.warn=WARN
log4j.logger.vm.info=INFO
log4j.logger.vm.debug=DEBUG

Configure a data source.

<bean id="dataSource" class="com.mchange.v2.c3p0.ComboPooledDataSource"
          destroy-method="close">
        <property name="driverClass" value="net.sf.log4jdbc.DriverSpy" />
        <property name="jdbcUrl" value="${db.jdbc.url}" />
        <property name="user" value="${db.user}" />
        <property name="password" value="${db.password}" /> 
    <!--         these are C3P0 properties -->
        <property name="acquireIncrement" value="3" />
        <property name="minPoolSize" value="10" />
        <property name="maxPoolSize" value="30" />
        <property name="maxIdleTime" value="600" />
</bean>

Notes on the above data source config:

1. Your usual driver class name should be replaced with net.sf.log4jdbc.DriverSpy
2. Your JDBC URL must now start with jdbc:log4jdbc. So if you use Oracle, your JDBC URL will now begin with jdbc:log4jdbc:oracle.

Now the log messages would appear on screen -

2013-01-29 15:52:21,549 DEBUG http-bio-8080-exec-3 org.springframework.jdbc.core.JdbcTemplate - Executing SQL query [SELECT id from emp]
2013-01-29 15:52:21,558 DEBUG http-bio-8080-exec-3 org.springframework.jdbc.datasource.DataSourceUtils - Fetching JDBC Connection from DataSource
2013-01-29 15:52:31,878  INFO http-bio-8080-exec-3 jdbc.connection - 1. Connection opened  org.apache.commons.dbcp.DriverConnectionFactory.createConnection(DriverConnectionFactory.java:38)
2013-01-29 15:52:31,878 DEBUG http-bio-8080-exec-3 jdbc.connection - open connections:  1 (1)
2013-01-29 15:52:31,895  INFO http-bio-8080-exec-3 jdbc.connection - 1. Connection closed  org.apache.commons.dbcp.DelegatingConnection.close(DelegatingConnection.java:247)
2013-01-29 15:52:31,895 DEBUG http-bio-8080-exec-3 jdbc.connection - open connections:  none
2013-01-29 15:52:41,950  INFO http-bio-8080-exec-3 jdbc.connection - 2. Connection opened  org.apache.commons.dbcp.DriverConnectionFactory.createConnection(DriverConnectionFactory.java:38)
2013-01-29 15:52:41,950 DEBUG http-bio-8080-exec-3 jdbc.connection - open connections:  2 (1)
2013-01-29 15:52:52,001  INFO http-bio-8080-exec-3 jdbc.connection - 3. Connection opened  org.apache.commons.dbcp.DriverConnectionFactory.createConnection(DriverConnectionFactory.java:38)
2013-01-29 15:52:52,002 DEBUG http-bio-8080-exec-3 jdbc.connection - open connections:  2 3 (2)
2013-01-29 15:53:02,058  INFO http-bio-8080-exec-3 jdbc.connection - 4. Connection opened  org.apache.commons.dbcp.DriverConnectionFactory.createConnection(DriverConnectionFactory.java:38)
2013-01-29 15:53:02,058 DEBUG http-bio-8080-exec-3 jdbc.connection - open connections:  2 3 4 (3)
2013-01-29 15:53:03,403 DEBUG http-bio-8080-exec-3 org.springframework.jdbc.core.BeanPropertyRowMapper - Mapping column 'id' to property 'id' of type int
2013-01-29 15:53:04,494 DEBUG http-bio-8080-exec-3 org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource

Some Mysql commands to show connection details -

> show variables like '%timeout%';
> show status like '%onn%';
> show full processlist;