Delay between RequestTimeout and ListenableFuture's completion

[xiaofud]

Hi, I find the delay between RequestTimeout and the time corresponding future completes by a timeout exception is quite long. Below is my test.

version:

<dependency>
	<groupId>org.asynchttpclient</groupId>
	<artifactId>async-http-client</artifactId>
	<version>2.10.4</version>
</dependency>

test code:

@RequestMapping("/api/timeout_test")
public BaseApiResponse<Long> timeoutTest() {
    long timeout = 1000;
    try {
        Thread.sleep(timeout);
    } catch (InterruptedException e) {
        e.printStackTrace();
    }
    BaseApiResponse<Long> objectBaseApiResponse = new BaseApiResponse<>();
    objectBaseApiResponse.setData(timeout);
    return objectBaseApiResponse;
}

@RequestMapping("/api/timeout")
public BaseApiResponse<String> timeout() {

    DefaultAsyncHttpClientConfig.Builder builder = new DefaultAsyncHttpClientConfig.Builder();
    builder.setConnectTimeout(5);
    AsyncHttpClient client = asyncHttpClient(builder);
    int timeout = 20;
    String url = "http://localhost:8080/api/timeout_test";

    BaseApiResponse<String> response = new BaseApiResponse<>();
    RequestBuilder requestBuilder = new RequestBuilder();
    Request request = requestBuilder.setUrl(url).setRequestTimeout(timeout).build();

    long beforeFutureCreated = System.currentTimeMillis();
    ListenableFuture<Response> responseListenableFuture = client.executeRequest(request);
    long futureCreated = System.currentTimeMillis();

    responseListenableFuture.addListener(() -> {
        long futureComplete = System.currentTimeMillis();
        String msg = String.format("future creation: %s, future complete: %s", futureCreated - beforeFutureCreated, futureComplete - beforeFutureCreated);
        response.setMessage(msg);
    }, Runnable::run);
    try {
        responseListenableFuture.get();
    } catch (Exception e) {
        e.printStackTrace();
    }
    return response;
}

result:

I tried many times, and the future complete time is always much longer than 20ms. It doesn't matter if I use a pre-created AsyncHttpClient or create a new one on each request.

{"code":0,"message":"future creation: 0, future complete: 103","data":null}
{"code":0,"message":"future creation: 0, future complete: 85","data":null}
{"code":0,"message":"future creation: 1, future complete: 87","data":null}
{"code":0,"message":"future creation: 1, future complete: 113","data":null}

log:

java.util.concurrent.TimeoutException: Request timeout to localhost/127.0.0.1:8080 after 20 ms

[slandelle]

AHC uses Netty's HashedWheelTimer to trade accuracy for the ability to schedule tens of thousands of event.

AHC currently uses the default settings, ie 100ms tick duration, meaning you will get timeouts rounded up to the closest 100ms (after first execution once all classes are properly loaded).

If you feel like you need a lower accuracy, feel free to contribute.

[xiaofud]

Thanks for your reply. Right now, I'll just limit the time on Future#get().

[mpantelimon]

Two questions here:

1. Why is this issue still open? Wasn't it resolved in v2.12.0 by pull request #1686 configure accuracy in HashedTimerWheel #1705? Or is there something still missing?
2. The TimeoutException spawned by the RequestTimeoutTimerTask carries the following message: "Request timeout to <remote_address> after <configured_request_timeout> ms". What's the reason for displaying the configured timeout instead of the real one (i.e. the age of the Future)? There are a couple of unit tests which verify specifically that the error message contains the configured timeout, so there must be a valid reason for that, but I fail to see it.

Thanks.