Stopwatch class for Java
The Spring Framework has an excellent StopWatch class:
StopWatch stopWatch = new StopWatch("My Stop Watch");
stopWatch.start("initializing");
Thread.sleep(2000); // simulated work
stopWatch.stop();
stopWatch.start("processing");
Thread.sleep(5000); // simulated work
stopWatch.stop();
stopWatch.start("finalizing");
Thread.sleep(3000); // simulated work
stopWatch.stop();
System.out.println(stopWatch.prettyPrint());
This produces:
StopWatch 'My Stop Watch': running time (millis) = 10000
-----------------------------------------
ms % Task name
-----------------------------------------
02000 020% initializing
05000 050% processing
03000 030% finalizing
This is an example how to use StopWatch to set multiple measurements by annotating dedicated methods. Very useful and very simple to use to measure e.g. Service call over multiple embedded call / operation and so on.
StopWatchHierarchy
package ch.vii.spring.aop;
import java.util.Arrays;
import org.aopalliance.intercept.MethodInterceptor;
import org.aopalliance.intercept.MethodInvocation;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
import org.springframework.util.StopWatch;
@Component
public class ProfilingMethodInterceptor implements MethodInterceptor {
private static final Logger log = LoggerFactory.getLogger(ProfilingMethodInterceptor.class);
public Object invoke(MethodInvocation invocation) throws Throwable {
if (log.isInfoEnabled()) {
String stopWatchName = invocation.getMethod().toGenericString();
StopWatchHierarchy stopWatch = StopWatchHierarchy.getStopWatchHierarchy(stopWatchName);
String taskName = invocation.getMethod().getName();
stopWatch.start(taskName);
try {
return invocation.proceed();
} finally {
stopWatch.stop();
}
} else {
return invocation.proceed();
}
}
static class StopWatchHierarchy {
private static final ThreadLocal<StopWatchHierarchy> stopwatchLocal = new ThreadLocal<StopWatchHierarchy>();
private static final IndentStack indentStack = new IndentStack();
static StopWatchHierarchy getStopWatchHierarchy(String id) {
StopWatchHierarchy stopWatch = stopwatchLocal.get();
if (stopWatch == null) {
stopWatch = new StopWatchHierarchy(id);
stopwatchLocal.set(stopWatch);
}
return stopWatch;
}
static void reset() {
stopwatchLocal.set(null);
}
final StopWatch stopWatch;
final Stack stack;
StopWatchHierarchy(String id) {
stopWatch = new StopWatch(id);
stack = new Stack();
}
void start(String taskName) {
if (stopWatch.isRunning()) {
stopWatch.stop();
}
taskName = indentStack.get(stack.size) + taskName;
stack.push(taskName);
stopWatch.start(taskName);
}
void stop() {
stopWatch.stop();
stack.pop();
if (stack.isEmpty()) {
log.info(stopWatch.prettyPrint());
StopWatchHierarchy.reset();
} else {
stopWatch.start(stack.get());
}
}
}
static class Stack {
private int size = 0;
String elements[];
public Stack() {
elements = new String[10];
}
public void push(String e) {
if (size == elements.length) {
ensureCapa();
}
elements[size++] = e;
}
public String pop() {
String e = elements[--size];
elements[size] = null;
return e;
}
public String get() {
return elements[size - 1];
}
public boolean isEmpty() {
return size == 0;
}
private void ensureCapa() {
int newSize = elements.length * 2;
elements = Arrays.copyOf(elements, newSize);
}
}
static class IndentStack {
String elements[] = new String[0];
public String get(int index) {
if (index >= elements.length) {
ensureCapa(index + 10);
}
return elements[index];
}
private void ensureCapa(int newSize) {
int oldSize = elements.length;
elements = Arrays.copyOf(elements, newSize);
for (int i = oldSize; i < elements.length; i++) {
elements[i] = new String(new char[i]).replace("\0", "| ");
}
}
}
}
Advisor
package ch.vii.spring.aop;
import java.lang.reflect.Method;
import org.aopalliance.aop.Advice;
import org.springframework.aop.Pointcut;
import org.springframework.aop.support.AbstractPointcutAdvisor;
import org.springframework.aop.support.StaticMethodMatcherPointcut;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Component;
@Component
public class ProfilingAdvisor extends AbstractPointcutAdvisor {
private static final long serialVersionUID = 1L;
private final StaticMethodMatcherPointcut pointcut = new StaticMethodMatcherPointcut() {
public boolean matches(Method method, Class<?> targetClass) {
return method.isAnnotationPresent(ProfileExecution.class);
}
};
@Autowired
private ProfilingMethodInterceptor interceptor;
public Pointcut getPointcut() {
return this.pointcut;
}
public Advice getAdvice() {
return this.interceptor;
}
}
ProfileExecution Annotation
package ch.vii.spring.aop;
import java.lang.annotation.ElementType;
import java.lang.annotation.Inherited;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;
@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
@Inherited
public @interface ProfileExecution {
}
Annotate your code
package ch.vii.spring;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Component;
import ch.vii.spring.aop.ProfileExecution;
@Component
public class Bean {
@Autowired
InnerBean innerBean;
@ProfileExecution
public void foo() {
innerBean.innerFoo();
innerBean.innerFoo2();
innerBean.innerFoo();
}
}
public class InnerBean {
@Autowired
InnerInnerBean innerInnerBean;
@ProfileExecution
public void innerFoo() {
}
@ProfileExecution
public void innerFoo2() {
innerInnerBean.innerInnerFoo();
innerInnerBean.innerInnerFoo();
innerInnerBean.innerInnerFoo();
}
}
Output
09:58:39.627 [main] INFO c.v.s.aop.ProfilingMethodInterceptor - StopWatch 'public void ch.vii.spring.Bean.foo()': running time (millis) = 215
-----------------------------------------
ms % Task name
-----------------------------------------
00018 008 % foo
00026 012 % | innerFoo
00001 000 % foo
00016 007 % | innerFoo2
00038 018 % | | innerInnerFoo
00000 000 % | innerFoo2
00024 011 % | | innerInnerFoo
00028 013 % | innerFoo2
00024 011 % | | innerInnerFoo
00029 013 % | innerFoo2
00000 000 % foo
00011 005 % | innerFoo
00000 000 % foo