Analyzing the query plans that are being executed by a slow performing database-centric Java application is often key to identifying the causes of the poor performance in the data tier. Capturing these plans however can sometimes be hard, either because the SQL is programmatically constructed, generated by a third party data access layer, or it’s hard to tie in the SQL that can be captured on the database side with the executing Java program. JDBC Tools provides support for capturing query plans at runtime from within any Java program.

JDBC Tools is an open source framework for placing monitoring code within the JDBC layer of an application. It can support custom monitoring plugins, but comes with standard Logger and Query Plan plugins. In this article we will take a look at the Query Planning plugin and see how it can be used to help diagnose application performance issues.

First you need to configure JDBC Tools and the query plan plugin module to work with your database. This is done by editing the jdbc-tools.properties file that comes with the JDBC Tools distribution. Here is an example of the key elements of these properties configured for query planning purposes.

jdbc.listener.classes=com.facdatum.jdbc.logger.JDBCLogger, \
com.facdatum.jdbc.planner.QueryPlanListener
driver.delegate=com.microsoft.sqlserver.jdbc.SQLServerDriver
driver.path=c:\\home\\user\\tools\\jdbc\\sqljdbc.jar
driver.class=com.microsoft.sqlserver.jdbc.SQLServerDriver
driver.url=jdbc:sqlserver://localhost:50679
driver.user=sa
driver.password=sa

If you ensure that this properties file and the supplied jdbc-tools.jar file are on your application’s CLASSPATH then all you need to do to activate query planning from your application is to replace the driver name you use in your application with com.facdatum.jdbc.listener.driver.DriverListener and add listener: after jdbc: in your URL connection string (e.g. jdbc:listener://localhost:50679). Run your application as normal and you will notice a jdbc-logging.log file gets produced.

Currently all calls and exits from the JDBC API are also getting logged. If you do not want this then it can be switched off by changing the log.levels entry in the properties file.

log.levels=

Or, if you want to control which parts of your application get logged then you can configure the ListenerCallFilter plugin. How to do this is explained in the JDBC Tools usage documentation.

The query plans appear in the log file as PLAN messages, where the query plan lines form the message body with each line separated by ^ symbols. These can be converted into a more readable multi-line form using the tools in your favourite editor or tools from your operating system. Here’s a sed script that does the job.

grep PLAN jdbc-logging.log | sed 's/\^/\n/g'

If the query plan contains mutliple columns then these will be bar (|) separated so can be nicely formatted in a spreadsheet.

Reviewing the generated plans you will notice that a single plan is generated for each unique SQL statement executed. Multiple executions do not generate multiple query plans. If you want more control over when plans are generated then you can use the ListenerDurationFilter. This can control output based on the execution time of the SQL queries. Here is an example configuration.

jdbc.listener.classes=com.facdatum.jdbc.logger.JDBCLogger, \
com.facdatum.jdbc.listener.filters.ListenerDurationFilter, \
com.facdatum.jdbc.planner.QueryPlanListener
jdbc.duration.filter.limit=10000
jdbc.duration.filter.change=0.25
jdbc.planner.repeat=true

You’ll see we’ve added the filter to the jdbc.listener.class property and configured some new properties. Other properties remain the same.

• The jdbc.duration.filter.limit property specifies a duration in milliseconds under which the query plan generation is filtered out.
• jdbc.duration.filter.change specifies that if the duration of a SQL query changes by the specified percentage then generate the query plan again. So in this example, queries that take over 10 seconds to execute and whose performance has degraded by 25% from the first run will have their query plans generated.
• We’ve also set the jdbc.planner.repeat to true so SQL that gets passed through the percentage change filter have a query plan generated.

Finally, it is also possible to pre-seed some execution time limits for specific SQL statements.

jdbc.duration.store.filepath=/home/user/sqltimings.store

In this example, the sqltimings.store file contains colon(:) separated <sql>:<duration> pairs which specify initial limits for query execution times.

select * from northwind..employees where FirstName = ?:200

We have seen that with JDBC Tools and it’s query planning capabilities it is possible to straightforwardly capture SQL execution plans to enable quick identification of database performance problems. It can also be as an early warning system to keep a record of the query plans that an application is using over time or to capture the right information when performance has degraded.

JDBC Tools can work with any database platform that is accessed through a JDBC driver, however the query planning capabilties currently support Oracle, Microsoft SQL Server and MySQL. The latest version of JDBC Tools can be downloaded from SourceForge or you can find out more information from http://jdbc-tools.sourceforge.net.

This entry was posted on Friday, November 7th, 2008 at 11:56 am and is filed under database, explain plans, java, jdbc, jdbc tools, logging, monitor, performance, query plans, sql. You can follow any responses to this entry through the RSS 2.0 feed. Both comments and pings are currently closed.