Tuesday, August 14, 2012

How to Measure Response Times in Java

This post describes how to measure response time in Java.  You can use either System.currentTimeMillis() or System.nanoTime() depending on what response times you will be recording.

System.currentTimeMillis is accurate to 1 millisecond, so is typically appropriate if you have response times on the order of magnitude of 1 second or more.  Using currentTimeMillis, you could report results in seconds with three decimals of precision, such as 1.205 seconds, or results in milliseconds with zero decimals of precision, such as 1205 milliseconds. 

nanoTime is typically appropriate if you want to report response times with greater precision than milliseconds, useful in cases in which differences of a fraction of a millisecond or microsecond are needed.

The following java code sample shows how to capture the response time of a transaction using both currentTimeMillis and nanoTime, showing the results in milliseconds with three decimals of precision.

Code Sample


/**
 * Created with IntelliJ IDEA.
 * User: ehammer
 */

import java.net.*;
import java.io.*;

public class TimerTest
{
    public static final Double NANO_TO_MILLIS = 1000000.0;
    public static void main(String[] args) throws MalformedURLException, IOException
    {
        // start timer
        long nanoStart = System.nanoTime();
        long milliStart = System.currentTimeMillis();

        // do work to be timed
        doWork();

        // stop timer
        long nanoEnd = System.nanoTime();
        long milliEnd = System.currentTimeMillis();

        // report response times
        long nanoTime = nanoEnd - nanoStart;
        long milliTime = milliEnd - milliStart;
        reportResponseTimes(nanoTime, milliTime);
    }

    private static void reportResponseTimes(long nanoTime, long milliTime)
    {
        // convert nanoseconds to milliseconds and display both times with three digits of precision (microsecond)
        String nanoFormatted = String.format("%,.3f", nanoTime / NANO_TO_MILLIS);
        String milliFormatted = String.format("%,.3f", milliTime / 1.0 );

        System.out.println("Milliseconds using nanoTime(): " + nanoFormatted);
        System.out.println("Milliseconds using currentTimeMillis: " + milliFormatted);
    }

    private static void doWork() throws MalformedURLException, IOException
    {
        URL url = new URL("http://www.google.com/");
        URLConnection conn = url.openConnection();
        BufferedReader in = new BufferedReader(new InputStreamReader(conn.getInputStream()));
        while (in.readLine() != null) {}
        in.close();
    }
}


Sample Output


Milliseconds using nanoTime(): 277.913
Milliseconds using currentTimeMillis: 278.000

Process finished with exit code 0

Walk Through

Timer is started as follows:
        long nanoStart = System.nanoTime();
        long milliStart = System.currentTimeMillis();

The transaction to be timed is then run.

The timer is stopped:
        long nanoEnd = System.nanoTime();
        long milliEnd = System.currentTimeMillis();

The difference between end and start is taken:
        long nanoTime = nanoEnd - nanoStart;
        long milliTime = milliEnd - milliStart;

Results are formatted in the desired precision, in this case as milliseconds with three decimals of precision (microsecond precision):
        String nanoFormatted = String.format("%,.3f", nanoTime / NANO_TO_MILLIS);
        String milliFormatted = String.format("%,.3f", milliTime / 1.0 );

Note that nanoTime results show microsecond precision, while currentTimeMillis shows results in 1 millisecond increments.

No comments:

Post a Comment