database logging show SQL log4jdbc tomcat JNDI log4j trace performance timing
Problem:
Given a complex web application (with many moving parts), there's performance issues that first impressions seem to point at environment-specific database latency. Is there any way to trace/profile/monitor all the SQL statements being made to the database (preferably with timings)?
Solution:
log4jdbc seamlessly lets you configure a logger between your application and the JDBC connection. Documentation on the log4jdbc site is very good and has just about all you need to know, below is a "quick start" for the impatient.
Step 1: Jar File(s)
Drop thelog4jdbc4-[version].jar file into [webapp]/WEB-INF/lib. You'll also need:
- a supported logging framework (log4j:
log4j-[version].jar) - the SLF4J API (
slf4j-api-[version].jar- already had it) - the SLF4J jar to use this logging framework (
slf4j-log4j12-[version].jar- already had it)
Step 2: Driver Class and URL
- Change the database resource definition to use the driver class
net.sf.log4jdbc.DriverSpy('spy' as it will work out the correct 'real' driver class to use).
- Simply prepend
jdbc:log4to the existing URL.
<Resource
name="jdbc/example"
type="javax.sql.DataSource"
factory="org.apache.tomcat.dbcp.dbcp.BasicDataSourceFactory"
driverClassName="net.sf.log4jdbc.DriverSpy"
url="jdbc:log4jdbc:postgresql://localhost:5432/example"
username="postgres" password="***"
maxActive="20" maxIdle="10" maxWait="-1"
removeAbandoned="true" removeAbandonedTimeout="120" logAbandoned="true"
auth="Container"
charset="UTF-8" />
Step 3: Logging Config
There's detailed notes on the five key loggers and an examplelog4j.properties is available. But if you just want to see SQL + timings, the following will log this all to console:log4j.logger.jdbc.audit=FATAL,Log4JDBC
log4j.additivity.jdbc.audit=false
log4j.logger.jdbc.resultset=FATAL,Log4JDBC
log4j.additivity.jdbc.resultset=false
log4j.logger.jdbc.sqlonly=FATAL,Log4JDBC
log4j.additivity.jdbc.sqlonly=false
log4j.logger.jdbc.sqltiming=INFO,Log4JDBC
log4j.additivity.jdbc.sqltiming=false
log4j.logger.jdbc.connection=FATAL,Log4JDBC
log4j.additivity.jdbc.connection=false
log4j.appender.Log4JDBC=org.apache.log4j.ConsoleAppender
log4j.appender.Log4JDBC.layout=org.apache.log4j.PatternLayout
log4j.appender.Log4JDBC.layout.ConversionPattern=%-5p [%d{DATE} %c]: %m%n
That's it. Start up the application and it should function exactly as it did before, but all SQL operations (made via the JNDI connection pool resource in my example) will be logged in the form:
INFO [01 Nov 2013 12:00:00,000 jdbc.sqltiming]: SELECT NAME FROM PERSON WHERE ID=54321
{executed in 1 msec}
Notes:
Bonus Step: Trace back to the Application Code
If your issue is working what part of the application code triggered the execution of a given SQL statement, a neat feature of the log4jdbc loggers is including the class & method-name of the code that invoked the JDBC driver. As there may be a few layers between your code and the JDBC driver (hibernate > application server connection pool, etc) you can tell it what level you what to capture from.- change log level to
DEBUG
log4j.logger.jdbc.sqltiming=DEBUG,Log4JDBC
- set the system property
log4jdbc.debug.stack.prefix
-Dlog4jdbc.debug.stack.prefix=com.example
DEBUG [01 Nov 2013 12:30:00,000 jdbc.sqltiming]: com.example.PersonDAO.findPerson(PersonDAO.java:111)
2. SELECT NAME FROM PERSON WHERE ID=54321
{executed in 53 msec}
NB: this extra logging adds a noticeable overhead to the database usage (and timings).
