Profiling With Spring's AOP

Recently, at work, I wanted to set up an easy way to get lightweight profiling information about method calls in our system. There are lots of heavyweight profilers out there that give you great features at the cost of bogging down the machine they're profiling. Fine if it's a development box; less so if it's a production machine your users are using.

Because we're using Spring, we have access to a pretty decent aspect-oriented-programming system. (AOP is basically a way to add system-wide concerns to objects without those objects having to be aware of the systems in any way: no subclassing or encapsulation.) Since profiling is a classic cross-cutting concern — something you need throughout the system but don't want any individual object to know anything about — Spring's mechanism works pretty well.

In my final system, a programmer only needs to add a @Profile annotation on a method, and it will generate profiling information in the logs. I didn't want to profile every method all the time because of the noise it would generate and the performance hit it would cause. The programmer can refine the output of the profiling system a bit, but the default is to show method name, args, return value, and timing information.(Spring's AOP framework is limited to non-private methods that are proxied by the Spring system, so private methods and intraobject calls don't get tracked. If that becomes a problem, I'll add in true AspectJ support, but that shouldn't require any real changes in my code, since Spring's support uses AspectJ syntax.)

Here are the key parts.

First, the profiling method, with a pointcut/advice combination that says "run this code around any method annotated with a @Profile annotation.

    @Around("@annotation(profileAnnotation)") 
    public Object profileMethod(ProceedingJoinPoint pjp, 
                Profile profileAnnotation) throws Throwable {
        
        StringBuilder buf = new StringBuilder("method: " + 
                               pjp.getSignature().getName());
        if (profileArgs(profileAnnotation)) {
            buf.append("; args: ");
            if (pjp.getArgs() != null && 
                pjp.getArgs().length > 0) {
                buf.append("[");
                for (Object o : pjp.getArgs()) {
                    buf.append(o.toString() + ",");
                }
                buf.append("]");
            } else {
                buf.append(" (no args)");
            }
        }

        long currentTime = System.currentTimeMillis();
        Object retVal = pjp.proceed();
        if (profileReturnValue(profileAnnotation)) {
            buf.append("; returnValue: " + 
                        String.valueOf(retVal)); // valueof prevents NPEs
        }

        if(profileTiming(profileAnnotation)) {
            buf.append("; timing: " + (System.currentTimeMillis() - currentTime));
        }
        log.info(buf.toString());
        return retVal;
}

The Profile annotation looks like this:

/** Annotation to demark methods that should be profiled. */
@Retention( RetentionPolicy.RUNTIME )
@Target( ElementType.METHOD )

public @interface Profile {
    ProfilingType[] value() default {ProfilingType.ALL};
}

And the ProfilingType enum looks like this:
public enum ProfilingType {ARGS,RETURN,TIMING,ALL}

The default output (ProfilingType.ALL) looks something like this:
method: [methodName]; args: [each arg as String]; returnValue: [returnValue]; timing: [some number of milliseconds]