Logging slow queries using log4jdbc

Set up log4jdbc to log slow queries

Let’s look at how to set up log4jdbc in an application so that slow queries are logged. Note that log4jdbc supports logging frameworks log4j and slf4j. Here we will use the logback implementation of slf4j.

1. Add this dependency to your pom.xml configuration file:

2. Add this to logback.xml file:

3. Change your JDBC URL

Insert “log4jdbc:” into the normal JDBC URL that you are using. For example, change this:

to this:

4. Set the JDBC driver class to sf.log4jdbc.sql.jdbcapi.DriverSpy in your application. Note that log4jdbc supports almost all major drivers; check the log4jdbc documentation for a list of supported drivers. For example, change:

into:

5. Log4jdbc does have a bug that we need to work around. See https://github.com/brunorozendo/log4jdbc-log4j2/issues/43 for the bug in question. The problem is that when logging just slow queries (rather than all queries) the class name and line number of the slow query are not logged. To fix that here we make a copy of class Slf4jSpyLogDelegator from the library. This class can be retrieved from https://repo1.maven.org/maven2/org/bgee/log4jdbc-log4j2/log4jdbc-log4j2-jdbc4.1/1.16/log4jdbc-log4j2-jdbc4.1-1.16-sources.jar . Rename it to jdbc.sqltiming.ModifiedSpyLogDelegator. Note that it must be in a different package than your normal application package. Method buildSqlTimingDump contains the following:

The change is to remove the if statement; so perform the out.append statements unconditionally.

Those are all of the code changes needed.

When running the application include the following three parameters:

The first parameter refers to the class that we have just modified. The second parameter represents the package structure of the application so change that to match your package structure. The third parameter is the threshold for warning about a slow query and is set here to 2 minutes (120,000 milliseconds). Change that to the desired threshold.

That’s it. Next time the application starts up and a query is too slow then a warning will be logged. For testing purposes, to see warnings being logged, set the threshold temporarily to something like 1ms.

The log message

Here is a typical log message produced by log4jdbc:

Note that the logged query is actual SQL and not Hibernate HQL. Also, the values of the query parameters are present; when Hibernate logs a query (by setting its show_sql parameter to true) it is without parameters, just a list of question marks. So, the query logged by log4jdbc is complete and can easily be executed in a SQL tool and an explain plan run on it to figure out why it is slow.

The class name and line number are also logged (in this case class EmployeeDAOImpl and line number 40). In this way it is easy to see from where in the Java code this query was executed.

Finally, the response time is logged, in this case 300,000 milliseconds (5 minutes).

Furthermore

• An additional feature of log4jdbc is an error threshold. So, log a warning about a certain lower threshold (say 2 minute) and log an error at a higher threshold (say 4 minutes) with parameter -Dlog4jdbc.sqltiming.error.threshold=240000.
• Warnings in a log file need to be noticed. A handy way to do that is to set up a Kibana board that displays the warnings and errors in your log file.

References
http://log4jdbc.brunorozendo.com/