Performance Zone is brought to you in partnership with:

I am a programmer and architect (the kind that writes code) with a focus on testing and open source; I maintain the PHPUnit_Selenium project. I believe programming is one of the hardest and most beautiful jobs in the world. Giorgio is a DZone Zone Leader and has posted 572 posts at DZone. You can read more from them at their website. View Full User Profile

Build your own Java stopwatch

09.10.2012
| 6543 views |
  • submit to reddit
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.

Comments

Sam Lewis replied on Mon, 2012/09/10 - 2:26pm

I generally import org.springframework.util.StopWatch

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

"For example, I always implement Java objects return 0;" That's just stupid. If you want to turn your brain off and depend on a profiler to tell you that your hashtable/map/set is accessed in linear time (instead of O(1)), that's one thing, but don't consider this as good advice. This is the type of performance issue that you would generally detect when you try to run your program on real data. This would very possibly be detected by a teammate who would like to have a long talk with you about software engineering.

Dale Wyttenbach replied on Mon, 2012/09/10 - 9:29pm in response to: Sam Lewis

There is also one in Apache commons-lang

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

1. "return 0" hashcode fulfills contract of hashCode(): But it would be better to use equals/hashcode generator from IDE. 2. Me also, but how this is related to the subject ?  

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.

Comment viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.