Determine timing of SQL queries with log4jdbc

Issue Description:

A proxy can be placed between our application and your jdbc driver to capture exact sql statements being sent to your server, and to log their execution time. This is helpful in determining performance, and helpful in determining final, full queries that may normally be logged in a parameterized form, hiding actual values.

Resolution:

Several JDBC proxy driver's exist that provide insight into database activity by intercepting JDBC calls and logging that information.  One example is log4jdbc, available at https://code.google.com/p/log4jdbc/.   You can use this proxy driver by downloading their jar, setting this jar as the driver for our database connections, then modifying our log4j.properties file to instruct certain values within their driver to create log statements in our own logfiles.   Try these steps:

First, download log4jdbc4-1.2.jar and add it to WEB-INF/lib (This driver has opensource dependencies, log4j and slf4j, which are already shipped within our lib).  

Second, add a statement to your WEB-INF/log4j.properties file: “log4j.logger.jdbc.sqltiming=INFO,fileout” Note that fileout is defined within our out-of-box properties file as the main jasperserver logfile.

Next you need to associate the log4jdbc driver with your connection, JNDI or JDBC:

JNDI

Modify the jndi resource in META_INF/context.xml for which you'd like enhanced sql logging.  For example, to log timing of calls to our foodmart database, modify the 'jdbc/foodmart' definition:

1. Set driverClassName="net.sf.log4jdbc.DriverSpy"
2. Add "jdbc:log4" as prefix to the pre-existing url, like url="jdbc:log4jdbc:mysql://localhost:3306/foodmart?useUnicode=true&characterEncoding=UTF-8&autoReconnect=true&autoReconnectForPools=true"

JDBC

To proxy direct jdbc connections as datasources, just modify the driver and url appropriately:

That's it.  You can restart, then look for snippets in your WEB-INF/jasperserver.log containing jdbc.sqltiming, like:

2013-Apr-26 15:09:03,330 jdbc.sqltiming INFO  insert into JIAuditEvent (username, tenant_id, event_date, resource_uri, resource_type, event_type, request_type) values ('superuser', 'organizations', '2013-04-26 15:09:02', NULL, '', 'switchUser', 'GUI') {executed in 2 msec}
2013-Apr-26 15:09:22,013 jdbc.sqltiming INFO SELECT TRIGGER_NAME, TRIGGER_GROUP, NEXT_FIRE_TIME, PRIORITY FROM QRTZ_TRIGGERS WHERE SCHED_NAME = 'quartzScheduler' AND TRIGGER_STATE = 'WAITING' AND NEXT_FIRE_TIME <= 1366988991272 AND (NEXT_FIRE_TIME >= 1366988361388) ORDER BY NEXT_FIRE_TIME ASC, PRIORITY DESC {executed in 1 msec}

Note that log4jdbc will automatically attempt to load most common jdbc drivers, but for something more obscure, please review their documentation to learn how to pass properties which define more obscure drivers (jars) which should be loaded.

Ref. Case #00032787