User Guide

User Guide

Original User Guide

Please refer to the original user guide at http://code.google.com/p/jdbcdslog/wiki/UserGuide for basic usage.

You may also want to look into user guide of jdbcdslog-exp for reference. However most features of jdbcdslog-exp should have been covered in this user guide.

Vendor Interface Support

There should be no special configuration required. With this feature, Proxies of Connection, Statement and ResultSet returned will not only implement the standard JDBC interfaces, but also "compatible" interfaces. For example, if the Connection object returned is implementing Connection and OracleConnection, and if OracleConnection is extending Connection, the proxy will implement both interface. In short, the following code should work:

Connection conn = dataSource.getConnection();
OracleConnection oraConn = (OracleConnection) conn;         // Not possible in old JDBC DS Log
oraConn.oracleSpecificMethod();
PreparedStatement stmt = oraConn.prepareStatement(....);    // will still be logged

JDK6+ has introduced unwrap() method to access underlying implementation. It is also supported

Connection conn = dataSource.getConnection();
OracleConnection oraConn = conn.unwrap(OracleConnection.class); // Not possible in old JDBC DS Log
oraConn.oracleSpecificMethod();
PreparedStatement stmt = oraConn.prepareStatement(....);        // will still be logged

Logging Before and After Statement

By default, we log after statement is executed.

With

jdbcdslog.logBeforeStatement=true

Log will look like

2014-09-28 00:00:00,000 [INFO ] o.j.StatementLogger: START: java.sql.PreparedStatement.executeQuery: select * from foo where bar='bar1';
2014-09-28 00:00:03,200 [INFO ] o.j.StatementLogger: END:   java.sql.PreparedStatement.executeQuery: select * from foo where bar='bar1';
Elapsed Time: 3.14159 s.

As you can link up before and after log message, you can turn off the statement in after message by

jdbcdslog.logBeforeStatement=true
jdbcdslog.logDetailAfterStatement=false

Log will look like

2014-09-28 00:00:00,000 [INFO ] Thread1 - o.j.StatementLogger: START: java.sql.PreparedStatement.executeQuery: select * from foo where bar='bar1';
2014-09-28 00:00:03,200 [INFO ] Thread1 - o.j.StatementLogger: END: 
Elapsed Time: 3.14159 s.

Parameter display style

With

jdbcdslog.inlineQueryParams=true    // default

Logs looks like the jdbcdslog-exp inline style

2014-09-28 00:00:00,000 [INFO ] o.j.StatementLogger: END:   java.sql.PreparedStatement.execute: select * from foo where bar='bar1';
Elapsed Time: 3.14159 s.

With

jdbcdslog.inlineQueryParams=false

Logs looks like the jdbcdslog style, with parameters displayed separately

2014-09-28 00:00:00,000 [INFO ] o.j.StatementLogger: END: java.sql.PreparedStatement.execute: select * from foo where bar=? parameters: {1=bar1}
Elapsed Time: 3.14159 s.

Improved Stack Trace

Warning: Adding stack trace information will slow down the logging.

We can include stack trace information by turning on

jdbcdslog.printStackTrace=true

JDBC DS Log Exp2 will try to find out first call stack out of JDBC DS Log Exp2 and log it

2014-09-28 00:00:00,000 [INFO ] o.j.StatementLogger: END: java.sql.PreparedStatement.execute: select * from foo where bar=? parameters: {1=bar1}
at com.foo.FooServiceImpl.foo(FooServiceImpl.java:928)
Elapsed Time: 3.14159 s.

In a lot of case, DB access is done through an underlying library (e.g. Hibernate, Spring JDBC Template etc). The default behavior of choosing stack frame for display is not giving much information. In such case you can define the pattern the class name should match by:

jdbcdslog.printStackTracePattern=^com\.foo\..*

First stack frame with class name matching the regex will be displayed.

You may even print the whole stack trace (excluding JdbcDsLog-related stacks) by

jdbcdslog.printFullStackTrace=true

Improved ResultSet Logging

Normal logging for each record in ResultSet (when calling next()) is now changed to DEBUG level, because of its large volume and comparatively low in value during tuning. Row number is also displayed.

Last call of ResultSet#next() after the last row will trigger a summary log message which contains total fetch time and total number of records. Such information is useful to give you hints of fetch size being too small when dealing with large number of result.

Better handling in Batch Operations

Batch operations logging are now improved.

jdbcdslog.logAddBatchDetail=false

will turn off detailed statement in addBatch(). (By default it will log detail statement in addBatch())

jdbcdslog.logExecuteBatchDetail=true

will shows all statements/parameters in batch when doing execute (By default executeBatch() will not show detailed statements). This give you the actual time in DB access (because addBatch() is not triggering any DB access) for tuning.

Connection ID Logging

Each connection is now having a unique identifier. All subsequent log originated from the connection will have the MDC entry (with key jdbcdslog.connectionId) populated with the connection ID. It is useful if your application is working against more than 1 DB (so that correlating using thread ID is not enough).

With log pattern like %d [%-5p] [Connection ID: %X{jdbcdslog.connectionId}] %t - %c{20}: %m%n (Logback) will give you message looks like

2015-01-27 10:17:47,959 [INFO ] [Connection ID: 1] main - o.j.StatementLogger: java.sql.PreparedStatement.execute: select * from foo where f1 = ? and f2 = ? parameters: {1=6, 2=4}