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.