Build Your Own Java stopwatch

After implementing some algorithms for record linkage, I found myself in the need to optimized the code for speed.

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.