Build your own Java stopwatch
Premature optimization
I'm a strict follower of the premature optimization maxim: first make it right, then make it fast; thus my code is prone to speedups of even 10000% once I discover the bottleneck and introduce a cache or a specialized data structure. For example, I always implement Java objects hashCode() as:return 0;
and only return on it after a performance test is failing. I don't want the mathematics of hash generation to get in the way of solving a business or mathematical problem the first time. This is the perfect example of premature optimization as we can easily return to hashCode() methods and implement them in an however fancy way in the future.
Another strict rule that enables future optimization is the avoidance of primitive obsession: never pass around language data structures like arrays or ArrayLists, but only Plain Old Java Objects wrapping them. There are domain considerations to Primitive Obsession - referring to a UserProfile (or another domain term) in an OO environment is usually better than to an ArrayList of strings, because the new type is an attractor for new logic in the form of methods; however, wrapping not only allows you to add a name, an interface or methods, but also to change the inner data structure for functional or non-functional reasons. A set works better than a list when you want to borrow code for duplicate removal - but also for O(1) contains() executions.
Profiling
To find out where to substitute data structures or cache results or reimplementing an algorithm, you need to profile the code and find out the bottleneck of your typical use case. This is a dynamic operation - it consists of running the code and track where time is spent - during that object search or when accessing the database?
There are automated tools for profiling, but depending on how complex they are to install and use, you may want to roll out your own. Another use case where I would favor a custom solution is in case profiling is an important aspect of your application - you want to measure times in production or report them through some network channel. The complex your needs, the better a custom solution will be able to fit with respect to an external tool.
In the case of Eclipse TPTP, I quickly gave up downloading and installing it; this is not always the case for some Eclipse tools, like the code coverage one which takes two clicks to install and run on your projects.
I then created my own StopWatch objects, which can be injected or accessed wherever there is a need for measuring the execution time. I usually remove the StopWatch object after reaching an acceptable execution time, just like I would do with an abstraction that has outlived its usefulness.
The StopWatch
What do we want from a StopWatch? Well, it should be able to:
- measure different intervals, even when they overlap with each other (for example one being contained in a larger one).
- It should accept the start and stop messages.
- It should accept the pause message: in case we are in a loop we want to sum up all the times relative to a certain operation, with a sequence of start/pause pairs.
- It should report the total elapsed time for an operation when we send it a measure message.
These requirements produce the following interface:
public interface StopWatch {
StopWatch start(String label);
StopWatch pause(String label);
StopWatch measure(String label);
StopWatch reset(String label);
}A simple implementation may just report to the standard output, but in principle it can even send you email messages:
import java.util.HashMap;
public class LoggingStopWatch implements StopWatch {
private HashMap<String, Long> startingTimes;
private HashMap<String, Long> measures;
public static StopWatch lastCreated = new LoggingStopWatch();
public LoggingStopWatch() {
this.startingTimes = new HashMap<String,Long>();
this.measures = new HashMap<String,Long>();
lastCreated = this;
}
@Override
public StopWatch start(String label) {
startingTimes.put(label, System.currentTimeMillis());
if (measures.get(label) == null) {
measures.put(label, 0L);
}
return this;
}
@Override
public StopWatch pause(String label) {
Long start = startingTimes.get(label);
if (start == null) {
throw new RuntimeException("Calling pause(\"" + label + "\" without calling start() at least once.");
}
long newMeasure = System.currentTimeMillis() - startingTimes.get(label);
measures.put(label, measures.get(label) + newMeasure);
startingTimes.remove(label);
return this;
}
@Override
public StopWatch measure(String label) {
if (startingTimes.containsKey(label)) {
pause(label);
}
System.out.println("STOPWATCH " + label + ": " + measures.get(label));
return this;
}
@Override
public StopWatch reset(String label) {
measures.remove(label);
return this;
}
}
I've added a static field to make the last created stopwatch accessible even where you haven't injected it. This is not a long-term solution, but acceptable while performing manual tests and searching for that problematic method that takes 90% of the total execution time (maybe some hashCode() :). In fact, the next paragraph requires the injection of StopWatch to work.
I also have another implementation, a SilentStopWatch, that is created as a Test Double for Stopwatch and instantiated whenever (like in tests) there is no need for profiling and we don't want to touch the standard output at all.
public final class SilentStopWatch implements StopWatch {
@Override
public StopWatch start(String label) { return this; }
@Override
public StopWatch pause(String label) { return this; }
@Override
public StopWatch measure(String label) { return this; }
@Override
public StopWatch reset(String label) { return this; }
}
Objects supporting both the profiling and non-profiling use cases have multiple constructors, defaulting to SilentStopWatch where one is not provided.
private int[] thresholds;
private StopWatch stopWatch;
public AgglomerativeHierarchicalClustering(int[] thresholds) {
this.thresholds = thresholds;
this.stopWatch = new SilentStopWatch();
}
public AgglomerativeHierarchicalClustering(int[] thresholds, StopWatch stopWatch) {
this.thresholds = thresholds;
this.stopWatch = stopWatch;
}
Conclusion
A custom solution for profiling may fit your context - either because the application is simple enough you're able to inject StopWatch objects, or because your needs for profiling go further than what your platform provides. The concepts of Premature Optimization and Primitive Obsessions have to be taken present to postpone the introduction of profiling and fancy algorithms and data structures.






Comments
Sam Lewis replied on Mon, 2012/09/10 - 2:26pm
Wojciech Kudla replied on Mon, 2012/09/10 - 2:49pm
1. How is overriding hashCode() going to help? This method is one of Java compiler intrinsics.
2. Your StopWatch implementation is completely flawed. Apart from using objects instead of primitives it pollutes the tenured with observations you take thus distorting your results by degrading the performance of garbage collections due to prolonged old gen scanning. If you want to measure how long an operation takes you must not influence the performance by the act of taking the measurement, I hope you'll agree. You can keep individual metrics in direct ByteBuffer or even better - use sun.misc.Unsafe for direct memory access.
Stephane Vaucher replied on Mon, 2012/09/10 - 8:01pm
Dale Wyttenbach replied on Mon, 2012/09/10 - 9:29pm
in response to:
Sam Lewis
Jonathan Fisher replied on Mon, 2012/09/10 - 10:47pm
>>return 0;
Was this a joke? Hell the default Object.hashCode() would perform better far than that!
Sampsa Sohlman replied on Tue, 2012/09/11 - 3:55am
I have done similarkind of thing, but it is hierarchical and makes easily to point problems on example web applications or soa applications. Works also well during load testing.
http://code.google.com/p/java-threadlocal-profiler/
Giorgio Sironi replied on Tue, 2012/09/11 - 11:20am
in response to:
Wojciech Kudla
2. In my context, we are talking about measuring minutes or hours. It is difficult for a few calls to a StopWatch object to alter hours of execution time, and I agree that if I were measuring milliseconds this solution won't cut it. :)
1. Also @Stephane, @Jonathan:
What the article doesn't say is that I override hashCode() for classes that implement equals(). Object's contract say that when equals() returns true for a pair of objects, hashCode() must return an equal value; returning 0 is the simplest way to fulfill the contract and keeping HashSet working when you don't know if the class will exist anymore in the next hours or if it will vanish while refactoring.
Wojciech Kudla replied on Tue, 2012/09/11 - 1:18pm
in response to:
Giorgio Sironi
1. Obviously you don't understand the contract of hashCode(). The hashcode value should be the same for equal objects, not for all of them. Please read the javadoc carefully.
2. Can you imagine an application handling 10K requests per minute? I can.
Stephane Vaucher replied on Tue, 2012/09/11 - 9:12pm
@Giorgio - "returning 0 is the simplest way to fulfill the contract and keeping HashSet working when you don't know if the class will exist anymore in the next hours or if it will vanish while refactoring."
No matter how you put it, that's still stupid. If you are at the point where you want to consider equality, you can take < 1 minute to put a (possibly suboptimal) hashCode. If this code somehow survives (useful code has a tendency of surviving), you might land up debugging this. It will likely take you an order of magnitude more time debugging than adding a simple hashCode method.
Michal Steiner replied on Wed, 2012/09/12 - 3:12am
in response to:
Wojciech Kudla
Wojciech Kudla replied on Wed, 2012/09/12 - 5:43am
in response to:
Michal Steiner
Ad 1. "As much as is reasonably practical, the hashCode method defined by class Object does return distinct integers for distinct objects". I guess there's no point arguing about that. I deliberately used "should" instead of "must" because the javadoc description of the contract is not very strict on that matter. What matters here is the understanding of what hashCode is about. The autor seems to not fully get the concept.
Ad 2. The author mentioned that he would use StopWatch to measure operations for a span of minutes or hours. For most cases you'll get plenty of minor GCs within an hour with each collection degrading over time in terms of latency thus not only distorting the result but impacting the whole application performance. Unless, of course, it's an application that doesn't do much. My point was: if you need to measure something, you should not influence the result by the act of measurement. Otherwise it doesn't make much sense, does it?
Vincent DABURON replied on Tue, 2012/09/18 - 5:37am
Hi,
I prefer to use a specialized library like JAMONAPI or newer JAVA SIMON.
JAMON API : http://jamonapi.sourceforge.net/
JAVA SIMON : http://code.google.com/p/javasimon/
Regards.
Vincent D.