Archive for November, 2008

Debugging SQL statements in Spring JDBC

Friday, November 28th, 2008

Spring JDBC support allows us to concentrate on the SQL code rather than on <rant>babysitting the JDBC framework and handling the checked exceptions it throws</rant>.
The trouble comes when you’re trying to debug the SQL statement itself, especially if you use a lot of positional parameters and if you have the SQL statement in several String constants.

Why parameters

The named parameters allow us to pass values to the SQL statement without having to worry about the dangers of SQL injection. Also, because the SQL statement remains the same, the RDBMS can cache the execution plan for the statement. This would not be possible if we included the (changing) parameters in the SQL statement.

Why several constants?

There is nothing stopping you from writing the SQL statement in one big String. The trouble begins when the SQL statement gets very complicated. Consider this statement:

select
	[many-columns]
from
	(select ROW_NUMBER() over (order by i.SupplierInvoiceCode) as row,
		[many-other-columns mapped to many-columns]
		from
			TableA i inner join
			TableB mo on mo.id = i.memberOutlet inner join
			TableC ma on ma.id = mo.memberAccount inner join
			TableD dc on dc.id = i.distributionChannel inner join
			TableE s on s.id = i.supplier inner join
			TableF m on m.id = ma.member
		where
			(i.supplierInvoiceCode like ?) and
			(i.invoiceDate >= ? and i.invoiceDate <= ?) and
			((i.distributionChannel = ?) or (? is null)) and
			[many-more-conditions]
			((i.collectedFromMember = ?) or (? is null)) and
			((? is null) or ((? = 1) and
				(select sum(systemDispute) from
					InvoiceLine il where il.invoice = i.id) > 0) or
			[more-and-more-conditions]
	) as InvoiceDtoWithNumbers  where row >= ? and row <= ?


In the interest of your own sanity, it would be better to split the SQL to its parts and construct its final form as

static String SELECT_SQL =
     "select " + MAPPED_COLUMNS +
     " from (select ROW_NUMBER() over (order by i.SupplierInvoiceCode) as row," +
     COLUMNS +
     " from " + FROM_SQL +
     " where " + WHERE_SQL +
     " ) as InvoiceDtoWithNumbers " +
     " where row >= ? and row <= ?";

What about those parameter pairs?

Notice in particular the ((someColumn = ?) or (? is null)) pattern. Let’s take a more concrete example ((id = ?) or (? is null)). If both positional parameters contain the same value, then supplying null will mean that the RDBMS will not apply the restriction ((id = null) or (null is null)) evaluates to true and most RDBMSs are capable of optimising tautologies. The effect of setting two nulls means that we don’t care what the value of id is. This is helpful in various searches, where null means “we don’t care”.
Conversely, if we supply some value other than null the RDBMS will eliminate the contradiction ((? is null)) and perform the requested restriction.
 

Debugging that thing?

Now, imagine there is a bug in the SQL statement: it is selecting too many or too few rows. How do you debug it? You can put a breakpoint in your IDE and copy the text of the SQL statement, but it will be full of positional parameters. If you run the SQL statement in a query runner, you will get the very helpful message:

>[Error] Script lines: 1-47 -------------------------
 Unexpected parameter marker at position 1777. 


Not good, not good at all.

PreparedStatementParameterSetter to the rescue

To debug the statement successfully, we implemented the PreparedStatementParameterSetter. It takes the PreparedStatement instance. Then, rather than calling PreparedStatement.set* methods, you call similar methods of the PreparedStatementParameterSetter. The calls map to appropriate calls on the PreparedStatement, but the setter also remembers the parameters. The PreparedStatementParameterSetter also automatically advances the parameter position. This means that your client code looks like this:

public PreparedStatement createPreparedStatement(Connection con) throws SQLException {
    PreparedStatement ps = con.prepareStatement(this.sql);
    PreparedStatementParameterSetter setter = new PreparedStatementParameterSetter(ps);
    setter.setWildcardString(argument.getSupplierInvoiceCode());
    setter.setDate(DateUtils.minDate(argument.getFromInvoiceDate()));
    setter.setDate(DateUtils.maxDate(argument.getToInvoiceDate()));
    setter.setPossibleNullLongPair(argument.getDistributionChannelId());
    setter.setPossibleNullLongPair(argument.getSupplierId());
    setter.setPossibleNullLongPair(argument.getMemberAccountId());
    setter.setPossibleNullLongPair(argument.getMemberId());
    ...
    if (logger.isDebugEnabled()) {
        logger.debug(setter.prepareSql(this.sql));
    }
}


You can see the call to the String prepareSql(String sqlWithPositionalParameters). The method will replace all positional parameters with the values you set and return the SQL statement. You can take the returned SQL statement and debug it in your favourite query analyzer.
 

Summary

Using the PreparedStatementParameterSetter in your [Spring] JDBC code simplifies the setting and debugging of complex SQL statements.
The PreparedStatementParameterSetter is one of the Spring Centre of Excellence library of code and you can download it here. You will also need to download the JdbcDaoUtils.java.

Sub-millisecond Java

Wednesday, November 19th, 2008

Imagine you had to implement (complex) code in Java that runs in sub-millisecond time. How will you know that you’ve succeeded? The traditional measurement such as this one won’t work.


long before = System.currentTimeMillis();
doSomeWork();
long elapsed = System.currentTimeMillis() - before;
// check that elapsed < 1

This is not great. It turns out that the operating system’s tick measurement greatly depends on the platform. On the Intel platform, the OS uses the default timer, which ticks 128 times a second. That means that the timer resolution will be roughly 8 ms. Not great. We need something far more accurate.
It turns out that on Intel CPUs (Pentium and above), you can use the RDTSC instruction that returns the number of processor ticks since power-up as 64bit number. “Aha!”, you say, “this is it.” The trouble is that the ticks are relevant only to the CPU on which the code is running. On a multi-processor system, the thread can run on any CPU and the CPUs do not have the same number of ticks. Dang!

OS functions

Your only option is to use the functions of the operating system. On Windows, you can call QueryPerformanceCounter(); on UNIX, you can use gettimeofday(...). These methods will give you roughly microsecond accuracy, which is usable for measuring sub-millisecond code.

Measuring critical code

The catch is that the impact of the measurement code can distort the numbers. The way around it is to calculate the measurement time overhead (per call, using compile- or load-time weaving) and then record the performance and the number of calls. Then you can subtract the expected overhead from the measured value, giving you reasonably accurate number.

AOP

Let me give you head start:


@Aspect
public class PerformanceMonitoringAspect {
    private final long THRESHOLD = 500L;  // 500 ns
    private final long callCount = 0;

    @Pointcut("execution(* net.cakesolutions.citi..handler.*.*(..))")
    private void handlerMethodExecution() { }

    @Around("handlerMethodExecution()")
    public Object performanceCollector(ProceedingJoinPoint pjp) throws Throwable {
        this.callCount++;
        long start = HighPerformanceTimer.getNanoTime();
        try {
            return pjp.proceed();
        } finally {
            long elapsed =
                (HighPerformanceTimer.getNanoTime() - start) -
                callCount * 4; // call time correction
            if (elapsed > THRESHOLD) writePoorPerformanceLogEntry(pjp);
        }
    }

    private void writePoorPerformanceLogEntry(ProceedingJoinPoint pjp) {
        System.out.println("Slow!");
    }
}

If you need any more information, contact me at Cake or come over to the next Spring User Group meeting, bring some purple cauliflower and I’ll talk.

Spring User Group November 5 Minutes

Sunday, November 16th, 2008

We tried a new ice-breaker for the Spring User Group meetings. It’s called “Ask Jan” — the attendees select two from a list of five topics they’d like me to talk about. Then I have some time to prepare short 5 – 10 minute talks on the selected subject.
At the SUG meeting on 12th November, the areas were:

  • Performance monitoring approaches
  • Top 3 Hibernate tips
  • Web application security
  • Five interesting applications
  • And one more thing that I can’t remember any more

From this list, the attendees selected the first two items; I have prepared a talk that covers the two topics. Download.

Manchester Wheelers’ 125th Anniversary

Monday, November 10th, 2008

On Saturday I went to the Manchester Wheelers’ 125th anniversary dinner and prize presentation. I was there to collect club standard certificates for 2nd class on 10 miles for time of 24:18, 2nd class on 25 miles for time of 1:02:52 and 3rd class on 50 miles for time of 2:10:00. I took the prize certificates to the office and will post pictures tomorrow.
P.S. I know the times are rubbish, but I never ventured outside the “J” courses. I hear that J2/9 and J4/16 are one of the slowest courses.

Spring User Group Meeting

Friday, November 7th, 2008

It is that time of the month again — time to meet up at the Spring User Group in London. At this meeting, you will have a chance to listen to Sam Brannen speak about the dm Server and I will give introduction to the new Spring Workflow Extension.
We’re all looking forward to seeing you on Wednesday 12th November at the Skills Matter offices — all you have to do is to register.
If you are on LinkedIn, you can join the Spring User Group.