How to time the speed of execution of a java program in milliseconds?

How do I get a method's execution time? Is there a Timer utility class for things like timing how long a task takes, etc?

Most of the searches on Google return results for timers that schedule threads and tasks, which is not what I want.

Replay

There is always the old-fashioned way:

long startTime = System.nanoTime();
methodToTime();
long endTime = System.nanoTime();

long duration = (endTime - startTime);  //divide by 1000000 to get milliseconds.

I go with the simple answer. Works for me.

long startTime = System.currentTimeMillis();

doReallyLongThing();

long endTime = System.currentTimeMillis();

System.out.println("That took " + (endTime - startTime) + " milliseconds");

It works quite well. The resolution is obviously only to the millisecond, you can do better with System.nanoTime(). There are some limitations to both (operating system schedule slices, etc.) but this works pretty well.

Average across a couple of runs (the more the better) and you'll get a decent idea.

Come on guys! Nobody mentioned the Guava way to do that (which is arguably awesome):

import com.google.common.base.Stopwatch;

Stopwatch timer = Stopwatch.createStarted();
//method invocation
LOG.info("Method took: " + timer.stop());

The nice thing is that Stopwatch.toString() does a good job of selecting time units for the measurement. I.e. if the value is small, it'll output 38 ns, if it's long, it'll show 5m 3s

Even nicer:

Stopwatch timer = Stopwatch.createUnstarted();
for (...) {
   timer.start();
   methodToTrackTimeFor();
   timer.stop();
   methodNotToTrackTimeFor();
}
LOG.info("Method took: " + timer);

Note: Google Guava requires Java 1.6+

Use a profiler (JProfiler, Netbeans Profiler, Visual VM, Eclipse Profiler, etc). You'll get the most accurate results and is the least intrusive. They use the built-in JVM mechanism for profiling which can also give you extra information like stack traces, execution paths, and more comprehensive results if necessary.

When using a fully integrated profiler, it's faily trivial to profile a method. Right click, Profiler -> Add to Root Methods. Then run the profiler just like you were doing a test run or debugger.

Using Instant and Duration from Java 8's new API,

Instant start = Instant.now();
Thread.sleep(5000);
Instant end = Instant.now();
System.out.println(Duration.between(start, end));

outputs,

PT5S

This probably isn't what you wanted me to say, but this is a good use of AOP. Whip an proxy interceptor around your method, and do the timing in there.

The what, why and how of AOP is rather beyond the scope of this answer, sadly, but that's how I'd likely do it.

Edit: Here's a link to Spring AOP to get you started, if you're keen. This is the most accessible implementation of AOP that Iive come across for java.

Also, given everyone else's very simple suggestions, I should add that AOP is for when you don't want stuff like timing to invade your code. But in many cases, that sort of simple and easy approach is fine.

You might also want to look at the Apache Commons Lang StopWatch class. A simple but useful utility class.

System.currentTimeMillis(); IS NOT a good approach for measuring performance of your logarithms. It meassures the total time you experience as a user watching the computer screen, waiting till the program finishes. It includes even time consumed by everything else ruining on your computer in the background. This could make a huge difference in case you have a lot of programs running on your workstation.

Proper approach is using java.lang.management package.

From http://nadeausoftware.com/articles/2008/03/java_tip_how_get_cpu_and_user_time_benchmarking website:

  • "User time" is the time spent running your application's own code.
  • "System time" is the time spent running OS code on behalf of your application (such as for I/O).

getCpuTime() method gives you sum of those:

import java.lang.management.ManagementFactory;
import java.lang.management.ThreadMXBean;

public class CPUUtils {

    /** Get CPU time in nanoseconds. */
    public static long getCpuTime( ) {
        ThreadMXBean bean = ManagementFactory.getThreadMXBean( );
        return bean.isCurrentThreadCpuTimeSupported( ) ?
            bean.getCurrentThreadCpuTime( ) : 0L;
    }

    /** Get user time in nanoseconds. */
    public static long getUserTime( ) {
        ThreadMXBean bean = ManagementFactory.getThreadMXBean( );
        return bean.isCurrentThreadCpuTimeSupported( ) ?
            bean.getCurrentThreadUserTime( ) : 0L;
    }

    /** Get system time in nanoseconds. */
    public static long getSystemTime( ) {
        ThreadMXBean bean = ManagementFactory.getThreadMXBean( );
        return bean.isCurrentThreadCpuTimeSupported( ) ?
            (bean.getCurrentThreadCpuTime( ) - bean.getCurrentThreadUserTime( )) : 0L;
    }

}

JAMon API is a free, simple, high performance, thread safe, Java API that allows developers to easily monitor the performance and scalability of production applications. JAMon tracks hits, execution times (total, avg, min, max, std dev), and more.

http://jamonapi.sourceforge.net/

download : http://sourceforge.net/project/showfiles.php?group_id=96550

Also We can use StopWatch class of Apache commons for measuring the time.

Sample code

org.apache.commons.lang.time.StopWatch sw = new org.apache.commons.lang.time.StopWatch();

System.out.println("getEventFilterTreeData :: Start Time : " + sw.getTime());
sw.start();

// Method execution code

sw.stop();
System.out.println("getEventFilterTreeData :: End Time : " + sw.getTime());

Just a small twist, if you don't use tooling and want to time methods with low execution time: execute it many times, each time doubling the number of times it is executed until you reach a second, or so. Thus, the time of the Call to System.nanoTime and so forth, nor the accuracy of System.nanoTime does affect the result much.

    int runs = 0, runsPerRound = 10;
    long begin = System.nanoTime(), end;
    do {
        for (int i=0; i<runsPerRound; ++i) timedMethod();
        end = System.nanoTime();
        runs += runsPerRound;
        runsPerRound *= 2;
    } while (runs < Integer.MAX_VALUE / 2 && 1000000000L > end - begin);
    System.out.println("Time for timedMethod() is " +
        0.000000001 * (end-begin) / runs + " seconds");

Of course, the caveats about using the wall clock apply: influences of JIT-compilation, multiple threads / processes etc. Thus, you need to first execute the method a lot of times first, such that the JIT compiler does its work, and then repeat this test multiple times and take the lowest execution time.

We are using AspectJ and Java annotations for this purpose. If we need to know to execution time for a method, we simple annotate it. A more advanced version could use an own log level that can enabled and disabled at runtime.

public @interface Trace {
  boolean showParameters();
}

@Aspect
public class TraceAspect {
  [...]
  @Around("tracePointcut() && @annotation(trace) && !within(TraceAspect)")
  public Object traceAdvice ( ProceedingJintPoint jP, Trace trace ) {

    Object result;
    // initilize timer

    try {
      result = jp.procced();
    } finally {
      // calculate execution time
    }

    return result;
  }
  [...]
}

Really good code.

http://www.rgagnon.com/javadetails/java-0585.html

import java.util.concurrent.TimeUnit;

long startTime = System.currentTimeMillis();
........
........
........
long finishTime = System.currentTimeMillis();

String diff = millisToShortDHMS(finishTime - startTime);

  /**
   * converts time (in milliseconds) to human-readable format
   *  "<dd:>hh:mm:ss"
   */
  public static String millisToShortDHMS(long duration) {
    String res = "";
    long days  = TimeUnit.MILLISECONDS.toDays(duration);
    long hours = TimeUnit.MILLISECONDS.toHours(duration)
                   - TimeUnit.DAYS.toHours(TimeUnit.MILLISECONDS.toDays(duration));
    long minutes = TimeUnit.MILLISECONDS.toMinutes(duration)
                     - TimeUnit.HOURS.toMinutes(TimeUnit.MILLISECONDS.toHours(duration));
    long seconds = TimeUnit.MILLISECONDS.toSeconds(duration)
                   - TimeUnit.MINUTES.toSeconds(TimeUnit.MILLISECONDS.toMinutes(duration));
    if (days == 0) {
      res = String.format("%02d:%02d:%02d", hours, minutes, seconds);
    }
    else {
      res = String.format("%dd%02d:%02d:%02d", days, hours, minutes, seconds);
    }
    return res;
  }

You can use Perf4j. Very cool utility. Usage is simple

String watchTag = "target.SomeMethod";
StopWatch stopWatch = new LoggingStopWatch(watchTag);
Result result = null; // Result is a type of a return value of a method
try {
    result = target.SomeMethod();
    stopWatch.stop(watchTag + ".success");
} catch (Exception e) {
    stopWatch.stop(watchTag + ".fail", "Exception was " + e);
    throw e;
}

More information can be found in Developer Guide

new Timer(""){{
    // code to time
}}.timeMe();

public class Timer {

    private final String timerName;
    private long started;

    public Timer(String timerName) {
        this.timerName = timerName;
        this.started = System.currentTimeMillis();
    }

    public void timeMe() {
        System.out.println(
        String.format("Execution of '%s' takes %dms.",
                timerName,
                started-System.currentTimeMillis()));
    }

}

I basically do variations of this, but considering how hotspot compilation works, if you want to get accurate results you need to throw out the first few measurements and make sure you are using the method in a real world (read application specific) application.

If the JIT decides to compile it your numbers will vary heavily. so just be aware

There are a couple of ways to do that. I normally fall back to just using something like this:

long start = System.currentTimeMillis();
// ... do something ...
long end = System.currentTimeMillis();

or the same thing with System.nanoTime();

For something more on the benchmarking side of things there seems also to be this one: http://jetm.void.fm/ Never tried it though.

Of course I should mention that most Java loggers give you timing for free too. Even org.apache.commons.logging.impl.SimpleLog can write timing information into the log file, so just add some log statements and you've got timing. See for example the Commons Logging guide.

If you want wall-clock time

long start_time = System.currentTimeMillis();
object.method();
long end_time = System.currentTimeMillis();
long execution_time = end_time - start_time;

As "skaffman" said, use AOP OR you can use run time bytecode weaving, just like unit test method coverage tools use to transparently add timing info to methods invoked.

You can look at code used by open source tools tools like Emma (http://downloads.sourceforge.net/emma/emma-2.0.5312-src.zip?modtime=1118607545&big_mirror=0). The other opensource coverage tool is http://prdownloads.sourceforge.net/cobertura/cobertura-1.9-src.zip?download.

If you eventually manage to do what you set out for, pls. share it back with the community here with your ant task/jars.

Using AOP/AspectJ and @Loggable annotation from jcabi-aspects you can do it easy and compact:

@Loggable(Loggable.DEBUG)
public String getSomeResult() {
  // return some value
}

Every call to this method will be sent to SLF4J logging facility with DEBUG logging level. And every log message will include execution time.

long startTime = System.currentTimeMillis();
// code goes here
long finishTime = System.currentTimeMillis();
long elapsedTime = finishTime - startTime; // elapsed time in milliseconds

I modified the code from correct answer to get result in seconds:

long startTime = System.nanoTime();

methodCode ...

long endTime = System.nanoTime();
double duration = (double)(endTime - startTime) / (Math.pow(10, 9));
Log.v(TAG, "MethodName time (s) = " + duration);

You can try this way if just want know the time.

long startTime = System.currentTimeMillis();
//@ Method call
System.out.println("Total time [ms]: " + (System.currentTimeMillis() - startTime));

Ok, this is a simple class to be used for simple simple timing of your functions. There is an example below it.

public class Stopwatch {
    static long startTime;
    static long splitTime;
    static long endTime;

    public Stopwatch() {
        start();
    }

    public void start() {
        startTime = System.currentTimeMillis();
        splitTime = System.currentTimeMillis();
        endTime = System.currentTimeMillis();
    }

    public void split() {
        split("");
    }

    public void split(String tag) {
        endTime = System.currentTimeMillis();
        System.out.println("Split time for [" + tag + "]: " + (endTime - splitTime) + " ms");
        splitTime = endTime;
    }

    public void end() {
        end("");
    }
    public void end(String tag) {
        endTime = System.currentTimeMillis();
        System.out.println("Final time for [" + tag + "]: " + (endTime - startTime) + " ms");
    }
}

Sample of use:

public static Schedule getSchedule(Activity activity_context) {
        String scheduleJson = null;
        Schedule schedule = null;
/*->*/  Stopwatch stopwatch = new Stopwatch();

        InputStream scheduleJsonInputStream = activity_context.getResources().openRawResource(R.raw.skating_times);
/*->*/  stopwatch.split("open raw resource");

        scheduleJson = FileToString.convertStreamToString(scheduleJsonInputStream);
/*->*/  stopwatch.split("file to string");

        schedule = new Gson().fromJson(scheduleJson, Schedule.class);
/*->*/  stopwatch.split("parse Json");
/*->*/  stopwatch.end("Method getSchedule");
    return schedule;
}

Sample of console output:

Split time for [file to string]: 672 ms
Split time for [parse Json]: 893 ms
Final time for [get Schedule]: 1565 ms

Spring provides a utility class org.springframework.util.StopWatch, as per JavaDoc:

Simple stop watch, allowing for timing of a number of tasks, exposing total running time and running time for each named task.

Usage:

StopWatch stopWatch = new StopWatch("Performance Test Result");

stopWatch.start("Method 1");
doSomething1();//method to test
stopWatch.stop();

stopWatch.start("Method 2");
doSomething2();//method to test
stopWatch.stop();

System.out.println(stopWatch.prettyPrint());

Output:

StopWatch 'Performance Test Result': running time (millis) = 12829
-----------------------------------------
ms     %     Task name
-----------------------------------------
11907  036%  Method 1
00922  064%  Method 2

With Aspects:

@Around("execution(* my.package..*.*(..))")
public Object logTime(ProceedingJoinPoint joinPoint) throws Throwable {
    StopWatch stopWatch = new StopWatch();
    stopWatch.start();
    Object retVal = joinPoint.proceed();
    stopWatch.stop();
    log.info(" execution time: " + stopWatch.getTotalTimeMillis() + " ms");
    return retVal;
}

With Java 8 you can do also something like this with every normal methods:

Object returnValue = TimeIt.printTime(() -> methodeWithReturnValue());
//do stuff with your returnValue

with TimeIt like:

public class TimeIt {

public static <T> T printTime(Callable<T> task) {
    T call = null;
    try {
        long startTime = System.currentTimeMillis();
        call = task.call();
        System.out.print((System.currentTimeMillis() - startTime) / 1000d + "s");
    } catch (Exception e) {
        //...
    }
    return call;
}
}

With this methode you can make easy time measurement anywhere in your code without breaking it. In this simple example i just print the time. May you add a Switch for TimeIt, e.g. to only print the time in DebugMode or something.

If you are working with Function you can do somthing like this:

Function<Integer, Integer> yourFunction= (n) -> {
        return IntStream.range(0, n).reduce(0, (a, b) -> a + b);
    };

Integer returnValue = TimeIt.printTime2(yourFunction).apply(10000);
//do stuff with your returnValue

public static <T, R> Function<T, R> printTime2(Function<T, R> task) {
    return (t) -> {
        long startTime = System.currentTimeMillis();
        R apply = task.apply(t);
        System.out.print((System.currentTimeMillis() - startTime) / 1000d
                + "s");
        return apply;
    };
}

Gathered all possible ways together into one place.

Date

Date startDate = Calendar.getInstance().getTime();
long d_StartTime = new Date().getTime();
Thread.sleep(1000 * 4);
Date endDate = Calendar.getInstance().getTime();
long d_endTime = new Date().getTime();
System.out.format("StartDate : %s, EndDate : %s \n", startDate, endDate);
System.out.format("Milli = %s, ( D_Start : %s, D_End : %s ) \n", (d_endTime - d_StartTime),d_StartTime, d_endTime);

System

long startTime = System.currentTimeMillis();
Thread.sleep(1000 * 4);
long endTime = System.currentTimeMillis();
long duration = (endTime - startTime);
System.out.format("Milli = %s, ( S_Start : %s, S_End : %s ) \n", duration, startTime, endTime );
System.out.println("Human-Readable format : "+millisToShortDHMS( duration ) );

Apache-StopWatch

org.apache.commons.lang3.time.StopWatch sw = new StopWatch();
sw.start();
Thread.sleep(1000 * 4);
sw.stop();
System.out.println("Apache StopWatch  : "+ millisToShortDHMS(sw.getTime()) );

Google-StopWatch

com.google.common.base.Stopwatch g_SW = Stopwatch.createUnstarted();
g_SW.start();
Thread.sleep(1000 * 4);
g_SW.stop();
System.out.println("Google StopWatch  : "+g_SW);

Human Readable Format

public static String millisToShortDHMS(long duration) {
    String res = "";    // java.util.concurrent.TimeUnit;
    long days       = TimeUnit.MILLISECONDS.toDays(duration);
    long hours      = TimeUnit.MILLISECONDS.toHours(duration) -
                      TimeUnit.DAYS.toHours(TimeUnit.MILLISECONDS.toDays(duration));
    long minutes    = TimeUnit.MILLISECONDS.toMinutes(duration) -
                      TimeUnit.HOURS.toMinutes(TimeUnit.MILLISECONDS.toHours(duration));
    long seconds    = TimeUnit.MILLISECONDS.toSeconds(duration) -
                      TimeUnit.MINUTES.toSeconds(TimeUnit.MILLISECONDS.toMinutes(duration));
    long millis     = TimeUnit.MILLISECONDS.toMillis(duration) -
                      TimeUnit.SECONDS.toMillis(TimeUnit.MILLISECONDS.toSeconds(duration));

    if (days == 0)      res = String.format("%02d:%02d:%02d.%04d", hours, minutes, seconds, millis);
    else                res = String.format("%dd %02d:%02d:%02d.%04d", days, hours, minutes, seconds, millis);
    return res;
}

JODA-TIME

public static void jodaTime() throws InterruptedException, ParseException{
    java.text.SimpleDateFormat ms_SDF = new SimpleDateFormat("yyyy/MM/dd HH:mm:ss.SSS");
    String start = ms_SDF.format( new Date() ); // java.util.Date

    Thread.sleep(10000);

    String end = ms_SDF.format( new Date() );
    System.out.println("Start:"+start+"\t Stop:"+end);

    Date date_1 = ms_SDF.parse(start);
    Date date_2 = ms_SDF.parse(end);
    Interval interval = new org.joda.time.Interval( date_1.getTime(), date_2.getTime() );
    Period period = interval.toPeriod(); //org.joda.time.Period

    System.out.format("%dY/%dM/%dD, %02d:%02d:%02d.%04d \n",
        period.getYears(), period.getMonths(), period.getDays(),
        period.getHours(), period.getMinutes(), period.getSeconds(), period.getMillis());
}

System.nanoTime() is a pretty precise system utility to measure execution time. But be careful, if you're running on pre-emptive scheduler mode (default), this utility actually measures wall-clock time and not CPU time. Therefore, you may notice different execution time values from run to run, depending on system loads. If you look for CPU time, I think that running your program in real-time mode will do the trick. You have to use RT linux. link: Real-time programming with Linux

Performance measurements on my machine

  • System.nanoTime() : 750ns
  • System.currentTimeMillis() : 18ns

As mentioned, System.nanoTime() is thought to measure elapsed time. Just be aware of the cost if used insied a loop or the like.

Category: java Time: 2008-10-07 Views: 1
Tags: java timing

Related post

iOS development

Android development

Python development

JAVA development

Development language

PHP development

Ruby development

search

Front-end development

Database

development tools

Open Platform

Javascript development

.NET development

cloud computing

server

Copyright (C) avrocks.com, All Rights Reserved.

processed in 0.197 (s). 12 q(s)