Multithreaded program to measure the performance of service

Question

I am in the process of measuing the performance of our service. So I have a URL that will make the call to our service. So what I did is that before making the call to the service, I make a note of the time and after the response came back from the service, I measure the response time. I wrote a program that was making the call to my service and measuring the performance by putting the numbers in a HashMap-

    while (runs > 0) {

        long start_time = System.currentTimeMillis();
        result = restTemplate.getForObject("Some URL", String.class);
        long difference = (System.currentTimeMillis() - start_time);

        Long count = histogram.get(difference);
        if (count != null) {
            count++;
            histogram.put(Long.valueOf(difference), count);
        } else {
            histogram.put(Long.valueOf(difference), Long.valueOf(1L));
        }
        runs--;
    }

So output I will be getting from the histogram map will be- X number of calls came back in Y ms

Now what I was thinking instead of making a single call at a time, why not I should parallelize the calls to our service, like in my previous program, I am hitting the service one by one. So I wrote a multithreading program below which will make a call to my service simultaneously. So the below program will be able to measure the time difference accurately or not?

Like one thread is taking this much time, second thread is taking this much time, third thread is taking this much time and so on? Is it possible to do this?

If yes, can anyone tell me how to do it if my below program doesn't work very well?

public static void main(String[] args) {

    ExecutorService service = Executors.newFixedThreadPool(10);

    for (int i = 0; i < 1 * 2; i++) {
        service.submit(new ThreadTask(i));
    }
    service.shutdown();
    try {
        service.awaitTermination(Long.MAX_VALUE, TimeUnit.DAYS);
    } catch (InterruptedException e) {

    }
}


class ThreadTask implements Runnable {
    private int id;
    private RestTemplate restTemplate = new RestTemplate();
    private String result;
    private HashMap<Long, Long> histogram;

    public ThreadTask(int id) {
        this.id = id;
    }

    @Override
    public void run() {

        long start_time = System.currentTimeMillis();

        result = restTemplate.getForObject("Some URL",String.class);
        long difference = (System.currentTimeMillis() - start_time);

        Long count = histogram.get(difference);
        if (count != null) {
            count++;
            histogram.put(Long.valueOf(difference), count);
        } else {
            histogram.put(Long.valueOf(difference), Long.valueOf(1L));
        }

        System.out.println(histogram);
    }
}

Because whenever I run the program, the numbers I am getting from this multithreading program looks very weird.

Output I got from Non Multithreading Program

168=1
41=1
43=3

1 call came back in 168 ms and so on...

And output I got from Multithreading program

{119=1}
{179=1}
{150=1}
{202=1}
{149=1}

1 call came back in 119 ms and so on... So in the multithreaded program, it is taking lot more time I guess?

Answer 1

I do not understand what you mean by getting weird numbers. My wild guess is that it is because output from different threads is getting interspersed.

One way to solve it is to not print the histogram from the run method at all. It is already an instance variable (though it currently does not need to be) so you can:

1. Instead of submitting unnamed instances of ThreadTask store them in a list/array.

2. Create a method ThreadTask.report that prints the histogram

3. After all the threads have completed, call ThreadTask.report on each in sequence.

Answer 2

I think you are accounting for the same time multiple times. If your threads do not execute this part of the code within a synchronized block:

long start_time = System.currentTimeMillis();

result = restTemplate.getForObject("Some URL",String.class);
long difference = (System.currentTimeMillis() - start_time);

then it is possible for this to happen:

1. Thread1: long start_time ...
2. Thread1: result = ...
3. Thread2: long start_time ...
4. Thread2: result = ...
5. Thread2: long difference ...
6. Thread1: long difference ...

So your accounting will not work properly. You could use synchronized blocks or look into Java's java.lang.management (e.g., ThreadMXBean and ThreadInfo), for timing functionality in threaded environments.

Update:

Also see the answer to this related SO question for more details on the problem and how to go around it.