Stopwatch class for Java
JavaPerformanceMeasurementJava Problem Overview
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)
Java Solutions
Solution 1 - Java
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
Solution 2 - Java
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
Solution 3 - Java
- You can use
System.nanoTime() - Or you can use the
StopWatchthat is supplied in the Apache Commons Lang library.
Solution 4 - Java
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.
Solution 5 - Java
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.
Solution 6 - Java
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().
Solution 7 - Java
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.
Solution 8 - Java
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.
Solution 9 - Java
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.
Solution 10 - Java
private void WaitTimer(long ms)
{
long t = 0;
long x = System.currentTimeMillis();
while(t < ms)
{
t = System.currentTimeMillis() - x;
}
}