Hierarchical stopwatch measuring code performance

While developing software it is a good habit to keep an eye on performance of specific parts of code. There are obviously many ways to do it – we can for instance benchmark specific methods or modules as part of unit tests, we can use tools like JMeter to simulate larger number of users, we can run a profiler from time to time etc. Despite having all these advanced approaches in reach, sometimes the most convenient (or lazy) way to measure performance is to wrap code with something like this:

long t = System.currentTimeMillis();
doSomething();
System.out.println("took " + (System.currentTimeMillis() - t) + "ms");

There are definitely many cons to this approach – it’s not elegant, the results are scattered all over the log file, it can not be turned off and so on. If you happen to be using Spring Framework or Apache Commons, you might use one of their implementations of StopWatch class (here and here), which is a wrapper with some additional capabilities, like report formatting, providing of statistics etc.

Some time ago I was in a need to use a stop watch for a web application based on Spring. After spending some time with mentioned implementations it became obvious that what I needed was a slightly different mechanism – one that would allow me to see a hierarchical structure of time consumption of individual pieces of code. Something like:

run() : 2753 ms
	foo() : 2753 ms
		bar() : 417 ms
			bang() : 60 ms
			bang() : 119 ms
			bang() : 238 ms
		bar() : 2336 ms
			bang() : 477 ms
			bang() : 953 ms
			bang() : 906 ms

At the end of this post you will find a source code of the class that I came up with. I hope that it might be useful either as it is, or as basis to a more sophisticated implementation. The output looks very much like the example above. The interesting thing about this particular implementation is that since it uses ThreadLocal under the hood, it can be accessed through its static methods. Example usage might look like that:

public class StopWatchTest {

	public static void main(String[] args) {
		StopWatch.reset();
		new StopWatchTest().run();
		System.out.println(StopWatch.prettyPrint());
	}

	public void run() {
		StopWatch.start("run()");
		foo();
		StopWatch.stop();
	}

	public void foo() {
		StopWatch.start("foo()");
		bar();
		bar();
		StopWatch.stop();
	}

	public void bar() {
		StopWatch.start("bar()");
		bang();
		bang();
		bang();
		StopWatch.stop();
	}

	public void bang() {
		StopWatch.start("bang()");
		sleepRandomly();
		StopWatch.stop();
	}

	public void sleepRandomly() {
		try {
			Thread.sleep(System.currentTimeMillis() % 1000);
		}
		catch (Exception e) {
			e.printStackTrace();
		}
	}
}

You can also easily deactivate it by setting threshold of it’s log4j logger above DEBUG level. In case of web applications it is a good idea to wrap it in a Servlet filter that will call StopWatch.reset() at the beginning of a request and StopWatch.prettyPrint() at the end. You might also easily wrap all Spring managed beans with a simple AOP advice that would transparently track performance of individual methods etc. Here’s the code:

import java.util.*;
import org.apache.log4j.Logger;

public class StopWatch {

	private static final Logger log = Logger.getLogger(StopWatch.class);
	private static ThreadLocal<StopWatch> threadLocal = null;

	private long eventIndex = 0;
	private Stack<Event> events = new Stack<Event>();
	private Set<Event> eventsDone = new TreeSet<Event>(new EventComparator());

	private StopWatch() {
	}

	public static void reset() {
		if (log.isDebugEnabled() == false) return;
		getThreadLocal().set(new StopWatch());
	}

	public static void start(String eventName) {
		if (log.isDebugEnabled() == false) return;

		StopWatch stopWatch = getInstance();
		if (stopWatch != null) {
			stopWatch.startEvent(eventName);
		}
	}

	public static void stop() {
		if (log.isDebugEnabled() == false) return;

		StopWatch stopWatch = getInstance();
		if (stopWatch != null) {
			stopWatch.stopEvent();
		}
	}

	public static String prettyPrint() {
		if (log.isDebugEnabled() == false) return null;

		StopWatch stopWatch = getInstance();
		return (stopWatch != null) ? stopWatch.internalPrettyPrint() : null;
	}

	private void startEvent(String eventName) {
		eventIndex++;
		events.push(new Event(eventIndex, events.size(), eventName));
	}

	private void stopEvent() {
		if (events.size() == 0) return;

		Event event = events.pop();
		event.stop();
		eventsDone.add(event);
	}

	private String internalPrettyPrint() {
		StringBuilder sb = new StringBuilder();
		if  (events.size() != 0) {
			sb.append("WARNING: same events have not been marked as closed, ");
			sb.append("the summary might contain wrong data...\n");
		}
		for (Event event : eventsDone) {
			sb.append(getTabs(event.getDepth()))
			.append(event.getName()).append(" : ").append(event.getTime()).append(" ms\n");
		}

		return sb.toString();
	}

	private static String getTabs(int count) {
		StringBuilder sb = new StringBuilder(count);
		for (int i = 0; i < count; i++) {
			sb.append("\t");
		}
		return sb.toString();
	}

	private static StopWatch getInstance() {
		return getThreadLocal().get();
	}

	private static ThreadLocal<StopWatch> getThreadLocal() {
		if (threadLocal == null) {
			threadLocal = new ThreadLocal<StopWatch>();
		}
		return threadLocal;
	}

	private class Event {

		private long index;
		private int depth;
		private String name;
		private long startTime;
		private long time;

		public Event(long index, int depth, String name) {
			this.index = index;
			this.depth = depth;
			this.name = name;
			startTime = System.currentTimeMillis();
		}

		public void stop() {
			time = System.currentTimeMillis() - startTime;
		}

		public long getIndex()  { return index; }
		public int getDepth()   { return depth; }
		public String getName() { return name; }
		public long getTime()   { return time; }
	}

	private class EventComparator implements Comparator<Event> {
		public int compare(Event left, Event right) {
			if (left == null && right == null) return 0;
			if (left == null) return 1;
			if (right == null) return -1;
			return (int) (left.getIndex() - right.getIndex());
		}
	}
}

If you have suggestions on how to optimize or improve it in any way, I will be happy to hear from you!