Showing posts with label response time. Show all posts
Showing posts with label response time. Show all posts

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.

Monday, June 4, 2012

Reporting Response Times - Percentile Distributions and Trends

Response time metrics can be very misleading.  An average of 2 seconds can mask occasional very high values that could be relevant to performance goals.  It can also mask cyclical trends.  The same is true of reporting median or specific percentiles such as 95th percentile.  An informative response time report should include two elements:
  1. Response time percentile distribution
  2. Response time trends with enough granularity to see spikes and patterns
Here is an example of these two elements:

Response Time Percentile Distribution

The distribution chart shows clearly what percentage of response times might be above the response time goal.

Response Time Trend

The trend chart shows clearly an upward trend over time, an important property that would be lost in any single response time metric.  It also includes enough granularity to show the distribution pattern of response time spikes.

Friday, January 6, 2012

How To Show Response Times in LoadRunner Vugen with Logging Disabled

Occasionally you want to see transaction response times in Loadrunner Vugen when logging is disabled, perhaps because log output is too verbose to easily see response times.  In that case, one convenient technique is to output response times using the lr_get_transaction_duration() function:

Script Example
Action()
{
  char *transactionName = "test_transaction";
  lr_start_transaction(transactionName);
  SimulateTransactionLogic();
  lr_output_message("ResponseTime,%f", lr_get_transaction_duration(transactionName));
  lr_end_transaction(transactionName, LR_AUTO);
}

SimulateTransactionLogic()
{
  lr_think_time(0.1);
}


Console Output With Logging Disabled
Action.c(9): ResponseTime,0.103419
Vuser Terminated.


Console Output With Logging Enabled
Running Vuser...
Starting iteration 1.
Starting action Action.
Action.c(5): Notify: Transaction "test_transaction" started.
Action.c(17): lr_think_time: 0.10 seconds.
Action.c(9): ResponseTime,0.106920
Action.c(10): Notify: Transaction "test_transaction" ended with "Pass" status (Duration: 0.1083 Think Time: 0.1005).
Ending action Action.
Ending iteration 1.
Ending Vuser...
Starting action vuser_end.
Ending action vuser_end.
Vuser Terminated.