As Java developers we regularly have problems with applications running slowly due to an inefficient database query. Often there is little logging to help track down which query is causing the problem. Log4jdbc can help out here. Log4jdbc is a Java library that can log your database queries and how long they take. It can also log warnings and errors when queries are too slow based on thresholds.
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.
- 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:
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:
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).
- 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.