Code Taking Longer When Inside Java Thread

Question

I need to execute up to 10 HTTP Post operations as quickly as possible. All posts are to the same destination, and to simplify things you can assume they are all doing the same operation, for now. Every millisecond counts. Executing a single HTTP post operation typically takes 50ms when executed as part of the main code, without any threads:

long start = System.currentTimeMillis( );
response = httpClient.execute(httppost, context);
long end = System.currentTimeMillis( );
long diff = end - start;
System.out.println(Thread.currentThread().getName() + ": Difference is: " + diff);

But to do a few at a time, I create a Thread per HTTP post operation, and pass each thread the same HttpClient object, complete with PoolingHttpClientConnectionManager:

protected HttpClient createHttpClient() {
    PoolingHttpClientConnectionManager cm = new PoolingHttpClientConnectionManager();
    cm.setMaxTotal(20);
    cm.setDefaultMaxPerRoute(24);
    RequestConfig.Builder requestBuilder = RequestConfig.custom();
    requestBuilder = requestBuilder.setConnectTimeout(5000);
    requestBuilder = requestBuilder.setSocketTimeout(5000);

    HttpClientBuilder builder = HttpClientBuilder.create();
    builder.setDefaultRequestConfig(requestBuilder.build());
    builder.setConnectionManager(cm);

    return builder.build();
}

CloseableHttpClient httpClient = (CloseableHttpClient) createHttpClient();
HttpParams httpParams = new DefaultHttpClient().getParams();

Runnable threadJob = new MyRunnable(httpClient, post);

Thread one = new Thread(threadJob);
Thread two = new Thread(threadJob);
Thread three = new Thread(threadJob);
Thread four = new Thread(threadJob);
Thread five = new Thread(threadJob);
Thread six = new Thread(threadJob);
Thread seven = new Thread(threadJob);
Thread eight = new Thread(threadJob);
Thread nine = new Thread(threadJob);
Thread ten = new Thread(threadJob);
one.start();
two.start();
three.start();
four.start();
five.start();
six.start();
seven.start();
eight.start();
nine.start();
ten.start();

Within the MyRunnable class, the same 50ms operation seems to take a good bit longer. Note I am not including the overhead of creating the thread etc in my metrics – I expect that to add to the overall time, but what’s perplexing me is why the same httpclient.execute() operation takes longer inside a thread, than it would be outside it. Inside MyRunnable's run() method:

long start = System.currentTimeMillis( );
response = httpClient.execute(httppost, context);
long end = System.currentTimeMillis( );
long diff = end - start;
System.out.println(Thread.currentThread().getName() + ": Difference is: " + diff);

My machine has 2 cores but 4 logical processors.
If I execute 4 threads, the times logged are typically like this:

58ms 155ms 160ms 179ms

It is consistently like this for ‘n’ threads – the first thread to complete registers a time slightly longer than ‘par’ time of 50ms, then the remainder all take around 3 times as long. Another typical result set for 10 threads:

52ms 156ms 156ms 160ms 156ms 161ms 175ms 158ms 176ms 178ms

Questions:

1. Is my ‘before and after’ logging method a reliable method of how long it takes?

2. Is this just the way it is when executing an http post operation inside a thread, or is there anything I can do to bring the average time down? (short of buying a more powerful machine).

Answer 1

Within the MyRunnable class, the same 50ms operation seems to take a good bit longer. Note I am not including the overhead of creating the thread etc in my metrics – I expect that to add to the overall time, but what’s perplexing me is why the same httpclient.execute() operation takes longer inside a thread, than it would be outside it.

You need to understand first on how multithreading works. It is not that when you create & start a Thread simply it runs in parallel, rather it waits for it's turn to execute the run() method (when number_of_threads > processors).

In other words, when there is a single thread running (or number_of_threads < processors), you don't see any overhead as the processor(s) will be free and simply executes your request(s). Now, coming to the other scenario, where you run threads more than the processors available, obviously, threads will take some time to get their turn which is called context switching overhead, so you will notice some difference in the response times obviously.

You might be interested in knowing how threads take priority to get their turn to execute the run() method, you can look here on this. In simple words, this is actually handled by the Thread Scheduler inside the JVM.

Also, I suggest you read here and understand the basics of how multithreading works.

Is my ‘before and after’ logging method a reliable method of how long it takes?

Your System.currentTimeMillis() is fine or you can also use Instant API from Java8.

Is this just the way it is when executing an http post operation inside a thread, or is there anything I can do to bring the average time down? (short of buying a more powerful machine)?

I suggest not to create & maintain Threads manually by yourself, rather use ExecutorService API like ExecutorService.newFixedThreadPool(10). This might not reduce the average time rather it will help you to manage the threads properly as a pool.

Answer 2

You should also try to measure user and system time as well. See here for a way to do that. Right now you are measuring wall clock time, which might not show you the right time.

It seems to me like what might be happening is that you start all of your threads at once, and they all very quickly block on on httpClient.execute. Then they all finish at roughly the same time, and each of them measures how much the whole system waited for the operation to happen, which is 170ish milliseconds.

There might be other functionality in the connection manager to limit the number of active requests, connections globally or per route.