Profile SQL statements in Java / Spring

Wouldn’t it be nice if there were a way to time your application’s SQL statements unobtrusively? This information could give you insight into the performance of your queries and updates and help you identify slow, poorly-performing SQL. Of course, there is a way to add such SQL profiling to your Spring application, by using AspectJ.

I use Spring JDBC and wanted to identify slow SQL queries in my application so that I could tune them in order to improve overall performance.  Capturing the execution times whenever SQL is executed can be done by creating a pointcut on the methods of JdbcTemplate.  Here is what we need:

1. aspectjrt.jar and aspectjweaver.jar from here.
2. An aspect with a pointcut on the JdbcOperations interface, which JdbcTemplate implements.
3. @Around advice that times the execution of JdbcTemplate methods and stores this data for later retrieval.
4. Configuration of Spring applicationContext.xml to get it working.

The pointcut looks like this, with the String argument being the SQL statement:

execution(* org.springframework.jdbc.core.JdbcOperations.*(String, ..))

Here is the profiling java class, with imports omitted (call it SqlProfiler):

@Aspect
public class SqlProfiler {
    private final Map<String, SqlTiming> sqlTimings;

    public SqlProfiler() {
        sqlTimings = Collections.synchronizedMap(new HashMap<String, SqlTiming>());
    }

    @Pointcut("execution(* org.springframework.jdbc.core.JdbcOperations.*(String, ..))")
    public void sql() {}

    @Around("sql()")
    public Object profile(ProceedingJoinPoint pjp) throws Throwable {
        long start = System.currentTimeMillis();
        Object obj = pjp.proceed();
        long time = System.currentTimeMillis() - start;
        String statement = pjp.getArgs()[0].toString();
        SqlTiming sqlTiming = null;
        synchronized(sqlTimings) {
            sqlTiming = sqlTimings.get(statement);
            if (sqlTiming == null) {
                sqlTiming = new SqlTiming(statement);
                sqlTimings.put(statement, sqlTiming);
            }
        }
        sqlTiming.recordTiming(time);

        return obj;
    }

    public List<SqlTiming> getTimings(final SortedBy sort) {
        List<SqlTiming> timings = new ArrayList<SqlTiming>(sqlTimings.values());
        Collections.sort(timings, new Comparator<SqlTiming>() {

            public int compare(SqlTiming o1, SqlTiming o2) {
                switch(sort) {
                    case AVG_EXECUTION_TIME:
                        return Math.round(o1.getAvgExecutionTime() - o2.getAvgExecutionTime());
                    case CUMULATIVE_EXECUTION_TIME:
                        long diff = o1.getCumulativeExecutionTime() - o2.getCumulativeExecutionTime();
                        if (diff > 0l)
                            return 1;
                        else if (diff == 0)
                            return 0;
                        else
                            return -1;
                    case NUMBER_OF_EXECUTIONS:
                        return o1.getExecutionCount() - o2.getExecutionCount();
                }
                return 0;
            }

        });

        return timings;
    }
}

To explain this a bit, sqlTimings is a map where keys are the SQL statements, and values are of type SqlTiming (shown below). The @Around advice applies to all methods that execute SQL. The profile method simply times the execution and stores the result in the map. The getTimings method is how clients can retrieve the profiling data that has been gathered, with several different sort options.

Here is the SqlTiming class, each instance of which holds the data for one SQL statement:

public class SqlTiming {

    private final String statement;
    private int count;
    private long cumulativeMillis;

    SqlTiming(String statement) {
        this.statement = statement;
    }

    synchronized SqlTiming recordTiming(long time) {
        count++;
        cumulativeMillis += time;
        return this;
    }

    public String getSqlStatement() {
        return statement;
    }

    public int getExecutionCount() {
        return count;
    }

    public long getCumulativeExecutionTime() {
        return cumulativeMillis;
    }

    public float getAvgExecutionTime() {
        return (float)cumulativeMillis / (float)count;
    }
}

Finally, we need to add the following to the Spring applicationContext.xml:

<!-- enable AspectJ support -->
<aop:aspectj-autoproxy/>

<!-- declare the profiler class (shown above) as a bean -->
<bean id="sqlProfiler" class="my.profiler.SqlProfiler" /> 

<!-- JdbcTemplate must be a Spring-managed bean -->
<bean id="jdbcTemplate" class="org.springframework.jdbc.core.JdbcTemplate" p:dataSource-ref="jdbcDataSource" />

<!-- wire the JdbcTemplate into your DAO -->
<bean id="myDao" class="my.dao.ExampleDao" p:jdbcTempate-ref="jdbcTemplate" />

It’s that simple. To view the results that have been gathered (cumulative execution time, average execution time, and number of executions), call the getTimings method. Here I’ve outputted some of the data via JSP:

INSERT INTO link (link_id, url, link_date, title, exerpt, link_collection_id) VALUES (?, ?, ?, ?, ?, ?)
Avg execution: 122.26ms
Total # of executions: 34

SELECT link_id, url, link_date, title, exerpt FROM link WHERE url = ?
Avg execution: 123.39ms
Total # of executions: 690

UPDATE inner_link SET title = ?, refers_to_id = ? WHERE inner_link_id = ?
Avg execution: 124.91ms
Total # of executions: 526

And there you have it.  To review: we’ve created an Aspect to profile SQL statements in Java unobtrusively, wired up our profiler in the Spring config, and outputted the SQL timings for analysis. Please leave a comment if this code can be improved!