Stopwatch class for Java

Question

Which Java class should you use for time performance measurements?

(One could use any date/time class, but the reason I'm asking is in .Net there's a designated Stopwatch class for this purpose)

Answer 1

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

Answer 2

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

Answer 3

• You can use System.nanoTime()
• Or you can use the StopWatch that is supplied in the Apache Commons Lang library.

Answer 4

Check out perf4j. Spring's stop watch is mainly for local development. Perf4j can support both your POC type timing as well as on a production environment.

Answer 5

Performetrics provides a convenient Stopwatch class. It can measure wall-clock time and more: it also measures CPU time, user time and system time, if you need more accuracy. It's small, free and you can download from Maven Central. More information and examples can be found here: https://obvj.net/performetrics

Stopwatch sw = new Stopwatch();
sw.start();

// Your code here

sw.stop();
sw.printStatistics(System.out);

This produces an output similar to the following:

+-----------------+----------------------+--------------+
| Counter         |         Elapsed time | Time unit    |
+-----------------+----------------------+--------------+
| Wall clock time |             85605718 | nanoseconds  |
| CPU time        |             78000500 | nanoseconds  |
| User time       |             62400400 | nanoseconds  |
| System time     |             15600100 | nanoseconds  |
+-----------------+----------------------+--------------+

You can convert the metrics to any time unit (nanoseconds, milliseconds, seconds, etc...) just by passing a custom parameter.

PS: I am the author of the tool.

Answer 6

You can try System.currentTimeMillis(), but also there a good profiling options under some well known IDEs, such as eclipse and netbeans. Also, away from the IDE, you can try standalone profilers in your performance measurements tasks. I think that by using profilers you will get better results than using System.currentTimeMillis().

Answer 7

If you just want to measure it, use a stopwatch class, or maybe just a stopwatch.

If you want to make it faster, consider this.

Answer 8

If you are using JDK 9+, you could use Flight Recorder. It has extremely low overhead and uses invariant TSC for timing, which is less intrusive than System.nanoTime()

@StackTrace(false)
static class StopWatch extends Event {
  int fib;
}

public static void main(String... args) throws IOException {
    Recording r = new Recording();
    r.start();
    for (int i = 0; i < 500000; i++) {
        StopWatch s = new StopWatch();
        s.begin();
        s.fib = fib(i%100);
        s.commit();
    }
    r.stop();
    Path p = Paths.get("recording.jfr");
    r.dump(p);
    for (RecordedEvent e : RecordingFile.readAllEvents(p)) {
        System.out.println(e.getValue("fib") + " " + e.getDuration().toNanos() + " ns");
    }
}

You can also start a recording from command line (-XX:StartFlightRecording) and then enable the event in a configuration file (.jfc) (if you disable it by default, @Enable(false))

That way the JIT will typically optimize away the StopWatch calls (escape analysis, inlining, deadcode elimination etc), so you only pay the penalty when you want to measure something.

Answer 9

The best is to use System.nanoTime(), however, if you want to get Ticks (elapsed Ticks) like System.Diagnostics.Stopwatch does you then need to convert nanoseconds to Ticks (1 Tick = 100 Nanoseconds) and then start converting between nanos and millis, secs, mins, hours, then finally format the output into a Time representation such as the one of the Elapsed() method (hh:mm:ss.sssssss), however, looks like Dates in Java use only 3 milliseconds (hh:mm:ss.sss), so you also need to workout the format as well.

I did one Stopwatch class for Java you can get it from: http://carlosqt.blogspot.com/2011/05/stopwatch-class-for-java.html

Example:

package stopwatchapp;
import java.math.BigInteger;
public class StopwatchApp {
    public static void main(String[] args) {

        Stopwatch timer = new Stopwatch();
        timer.start();
        Fibonacci(40);
        timer.stop();

        System.out.println("Elapsed time in ticks: " 
            + timer.getElapsedTicks());
        System.out.println("Elapsed time in milliseconds: " 
            + timer.getElapsedMilliseconds());
        System.out.println("Elapsed time in seconds: " 
            + timer.getElapsedSeconds());
        System.out.println("Elapsed time in minutes: " 
            + timer.getElapsedMinutes());
        System.out.println("Elapsed time in hours: " 
            + timer.getElapsedHours());
        System.out.println("Elapsed time with format: " 
            + timer.getElapsed());
    }

    private static BigInteger Fibonacci(int n)
    {
        if (n < 2)
            return BigInteger.ONE;
        else
            return Fibonacci(n - 1).add(Fibonacci(n - 2));
    }
}

The output:

// Elapsed time in ticks: 33432284
// Elapsed time in milliseconds: 3343
// Elapsed time in seconds: 3
// Elapsed time in minutes: 0
// Elapsed time in hours: 0
// Elapsed time with format: 00:00:03.3432284

Hope this helps.

Answer 10

private void WaitTimer(long ms)
{
    long t = 0;
    long x = System.currentTimeMillis();

    while(t < ms)
    {
       t = System.currentTimeMillis() - x;
    }
}