ExecutorFramework is adding up lot of time in performance test?

Question

I am working on a project in which I am trying to make a URL call to one of my server using RestTemplate which gives me back a JSON String as a response and it is working fine...

Now I decided to do some performance testing on that...

Below is my code which uses ExecutorService and Callables -

public class URLTest {

    private ExecutorService executor = Executors.newFixedThreadPool(10);

    public String getData() {
        Future<String> future = executor.submit(new Task());
        String response = null;

        try {
            System.out.println("Started..");
            response = future.get(200, TimeUnit.MILLISECONDS);
            System.out.println("Finished!");
        } catch (TimeoutException e) {
            System.out.println("Terminated!");
        } catch (InterruptedException e) {
            e.printStackTrace();
        } catch (ExecutionException e) {
            e.printStackTrace();
        }

        return response;
    }
}

Below is my Task class which implements Callable interface -

class Task implements Callable<String> {

    private RestTemplate restTemplate = new RestTemplate();

    public String call() throws Exception {
        String url = "some_url";
    //  TimerTest timer = TimerTest.getInstance();  // line 3
        String response = restTemplate.getForObject(url, String.class);
    //  timer.getDuration();    // line 4
        System.out.println(response);

        return response;

    }
}

And below is my code in another class DemoTest which calls the getData method in URLTest class 500 times and measure the 95th percentile of it as that's what I need to do -

public class DemoTest { 
    public static void main(String[] args) {

        URLTest bc = new URLTest();
        for (int i = 0; i <= 500; i++) {
            TimerTest timer = TimerTest.getInstance(); // line 1
            bc.getData();
            timer.getDuration(); // line 2
        }

        // this method prints out the 95th percentile
        logPercentileInfo();

    }
}   

With the above code as it is, I always see as 95th percentile as 14-15 ms (which is bad for my use case as it is end to end flow and that's what I need to measure) but if I comment out line 1 and line 2 in DemoTest class and uncomment line 3 and line 4 in Task class and then run the program again it will start giving me 95th percentile as 3 ms.

I am surprised why? Is ExectuorFramework adding all the latency here? And why if I just measure the performance of RestTemplate call, then it always gives me better performance as compared to end to end performance?

My main goal is to reduce the latency here as much as possible.. My use case is simple, Make a URL call to one of my server with a TIMEOUT feature enabled, meaning if the server is taking lot of time to response, then Timeout the whole call.

Both my client program and server are running in PRODUCTION in the same datacenter so ping time is 0.5 ms around..

I ran couple of times to do this test and still the same result..

Is there anything I am missing or some other flavors of ExecutorService I need to use? How can I improve my performance here? Any suggestions will be of great help..

UPDATE:-

Added some warmup time -

   public static void main(String[] args) {

    URLTest bc = new URLTest();

    // little bit warmup
    for (int i = 0; i <= 500; i++) {
        bc.getData();
    }

    for (int i = 0; i <= 500; i++) {
        TimerTest timer = TimerTest.getInstance();
        bc.getData();
        timer.getDuration();
    }

    logPercentileInfo();

    }

Answer 1

The ExecutorService is adding a latency, because it has to manage the worker threads and work queue.

But this should NOT be the reason for the 12ms difference.

As far as I can see, there are several issues here:

• maaartinus mentioned that you are "saturating" your pool. But for me, it seems like the opposite: Each task is submitted, and the submitting thread is waiting (via future.get) until the task is finished
• The resolution of your timer may be too low to measure <10ms time spans reliably (this depends of several factors - especially Windows systems are said to have a comparatively low timer resolution)
• In one case, you are measuring the time for System.out.println(response), and in the other case, you are not

EDIT: Upon request in the comments, an example of the ExecutorCompletionService:

import java.util.Random;
import java.util.concurrent.Callable;
import java.util.concurrent.CompletionService;
import java.util.concurrent.ExecutionException;
import java.util.concurrent.ExecutorCompletionService;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.Future;


public class ExecutorCompletionExample
{
    public static void main(String[] args) 
    {
        ExecutorService executor = Executors.newFixedThreadPool(10);
        CompletionService<String> completionService = 
            new ExecutorCompletionService<String>(executor);

        int n = 500;
        for (int i = 0; i < n; i++) 
        {
            Task task = new Task("Task"+i);
            completionService.submit(task);
        }


        for (int i = 0; i < n; ++i) 
        {
            try
            {
                Future<String> future = completionService.take();
                String response = future.get();
                System.out.println("Response: "+response);
            }
            catch (InterruptedException e)
            {
                Thread.currentThread().interrupt();
                return;
            }
            catch (ExecutionException e)
            {
                e.printStackTrace();
            }
        }
    }
}


class Task implements Callable<String> 
{
    private static Random random = new Random(0);

    private String name;
    private long delay;

    Task(String name)
    {
        this.name = name;
        this.delay = 10 + random.nextInt(10)*10;
    }
    public String call() throws Exception 
    {
        //String response = restTemplate.getForObject(url, String.class);
        Thread.sleep(delay);
        String response = "Response of "+name+" with delay "+delay;
        return response;
    }
}

The usage is rather simple, and to my understanding, the original question referred to a task that corresponds to the description of the CompletionService interface:

"A service that decouples the production of new asynchronous tasks from the consumption of the results of completed tasks. .. A CompletionService can for example be used to manage asynchronous IO, in which tasks that perform reads are submitted in one part of a program or system, and then acted upon in a different part of the program when the reads complete, possibly in a different order than they were requested."

Whether or not this really matches the intended use-case (and, of course, whether it helps to achieve the desired reduction of overall latency) could not be tested based on the given example.