Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

Apache Http Client slower than browser

Disclaimer: I know that this question has duplicates (one, two, three), BUT:

  • I tried all the answers and it doesn't solve the problem (I searched not only in SO)
  • I provide the full internal log of http client, so experienced users can analize and comment it.
  • Those questions are old (more than a year), many things has been changed.

I'm trying to get content from this URL: https://api.vk.com/method/database.getCountries

Mac OS Chrome browser gets the content in around 70-100 ms (I look at dev-tools Network tab), but my code with apache http client 4.5.2 gets it in 180-200 ms. Also I have a code with (kevinsawicki-http-request) library, witch gets this page in 70-100 ms (like in browser). This difference is critical for me, and (I think) for many other devs, who asked similar questions.

My code:

RequestConfig requestConfig = RequestConfig.custom()
        .setCookieSpec(CookieSpecs.IGNORE_COOKIES)
        .setSocketTimeout(60000)
        .setConnectTimeout(5000)
        .setConnectionRequestTimeout(5000)
        .build();
SocketConfig socketConfig = SocketConfig.custom()
        .setSoKeepAlive(false) //true - no differences in request time
        .setTcpNoDelay(true)
        .build();
PoolingHttpClientConnectionManager connManager = new PoolingHttpClientConnectionManager();
connManager.setMaxTotal(50);
connManager.setDefaultMaxPerRoute(2);

CloseableHttpClient httpClient = HttpClients.custom()
        .setDefaultSocketConfig(socketConfig)
        .setConnectionManager(connManager)
        .setDefaultRequestConfig(requestConfig)
        .setUserAgent("Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/54.0.2840.71 Safari/537.36")
        .build();

//1
long t11 = System.currentTimeMillis();
try(CloseableHttpResponse response1 = httpClient.execute(new HttpGet("https://api.vk.com/method/database.getCountries"))) {
    code1 = response1.getStatusLine().getStatusCode();
}
long t12 = System.currentTimeMillis();
long reqTime1 = t12 - t11;
//2
long t21 = System.currentTimeMillis();
try(CloseableHttpResponse response2 = httpClient.execute(new HttpGet("https://api.vk.com/method/database.getCountries"))) {
    code2 = response2.getStatusLine().getStatusCode();
}
long t22 = System.currentTimeMillis();
long reqTime2 = t22 - t21;
//3
long t31 = System.currentTimeMillis();
try(CloseableHttpResponse response3 = httpClient.execute(new HttpGet("https://api.vk.com/method/database.getCountries"))) {
    code3 = response3.getStatusLine().getStatusCode();
}
long t32 = System.currentTimeMillis();
long reqTime3 = t32 - t31;

log.trace("reqTime1: {}", reqTime1);
log.trace("reqTime2: {}", reqTime2);
log.trace("reqTime3: {}", reqTime3);

This prints:

reqTime1: 198 
reqTime2: 168 
reqTime3: 160

(all 3 requests return 200 http code)

I have JVM options:

-Djavax.net.ssl.keyStore=/path/to/my/keyStore.jks
-Djavax.net.ssl.keyStorePassword=my_password
-Dorg.apache.commons.logging.Log=org.apache.commons.logging.impl.SimpleLog
-Dorg.apache.commons.logging.simplelog.showdatetime=true
-Dorg.apache.commons.logging.simplelog.log.org.apache.http=DEBUG
-Dorg.apache.commons.logging.simplelog.log.org.apache.http.wire=ERROR

(vk.com certificate is added in my keyStore.jks)

Here is the internal log of http-client

[err] 2016/11/11 14:54:35:411 MSK [DEBUG] RequestAddCookies - CookieSpec selected: ignoreCookies
[err] 2016/11/11 14:54:35:412 MSK [DEBUG] RequestAuthCache - Auth cache not set in the context
[err] 2016/11/11 14:54:35:413 MSK [DEBUG] PoolingHttpClientConnectionManager - Connection request: [route: {s}->https://api.vk.com:443][total kept alive: 0; route allocated: 0 of 2; total allocated: 0 of 50]
[err] 2016/11/11 14:54:35:413 MSK [DEBUG] PoolingHttpClientConnectionManager - Connection leased: [id: 6][route: {s}->https://api.vk.com:443][total kept alive: 0; route allocated: 1 of 2; total allocated: 1 of 50]
[err] 2016/11/11 14:54:35:413 MSK [DEBUG] MainClientExec - Opening connection {s}->https://api.vk.com:443
[err] 2016/11/11 14:54:35:414 MSK [DEBUG] DefaultHttpClientConnectionOperator - Connecting to api.vk.com/87.240.165.75:443
[err] 2016/11/11 14:54:35:414 MSK [DEBUG] SSLConnectionSocketFactory - Connecting socket to api.vk.com/87.240.165.75:443 with timeout 5000
[err] 2016/11/11 14:54:35:494 MSK [DEBUG] SSLConnectionSocketFactory - Enabled protocols: [TLSv1, TLSv1.1, TLSv1.2]
[err] 2016/11/11 14:54:35:495 MSK [DEBUG] SSLConnectionSocketFactory - Enabled cipher suites:[TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_DSS_WITH_AES_128_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_DSS_WITH_AES_128_GCM_SHA256, TLS_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]
[err] 2016/11/11 14:54:35:495 MSK [DEBUG] SSLConnectionSocketFactory - Starting handshake
[err] 2016/11/11 14:54:35:641 MSK [DEBUG] SSLConnectionSocketFactory - Secure session established
[err] 2016/11/11 14:54:35:642 MSK [DEBUG] SSLConnectionSocketFactory -  negotiated protocol: TLSv1.2
[err] 2016/11/11 14:54:35:642 MSK [DEBUG] SSLConnectionSocketFactory -  negotiated cipher suite: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
[err] 2016/11/11 14:54:35:642 MSK [DEBUG] SSLConnectionSocketFactory -  peer principal: CN=*.vk.com, OU=Domain Control Validated
[err] 2016/11/11 14:54:35:642 MSK [DEBUG] SSLConnectionSocketFactory -  peer alternative names: [*.vk.com, vk.com]
[err] 2016/11/11 14:54:35:642 MSK [DEBUG] SSLConnectionSocketFactory -  issuer principal: CN=Go Daddy Secure Certificate Authority - G2, OU=http://certs.godaddy.com/repository/, O="GoDaddy.com, Inc.", L=Scottsdale, ST=Arizona, C=US
[err] 2016/11/11 14:54:35:643 MSK [DEBUG] DefaultHttpClientConnectionOperator - Connection established 172.20.10.2:55317<->87.240.165.75:443
[err] 2016/11/11 14:54:35:643 MSK [DEBUG] DefaultManagedHttpClientConnection - http-outgoing-6: set socket timeout to 60000
[err] 2016/11/11 14:54:35:643 MSK [DEBUG] MainClientExec - Executing request GET /method/database.getCountries HTTP/1.1
[err] 2016/11/11 14:54:35:643 MSK [DEBUG] MainClientExec - Target auth state: UNCHALLENGED
[err] 2016/11/11 14:54:35:644 MSK [DEBUG] MainClientExec - Proxy auth state: UNCHALLENGED
[err] 2016/11/11 14:54:35:644 MSK [DEBUG] headers - http-outgoing-6 >> GET /method/database.getCountries HTTP/1.1
[err] 2016/11/11 14:54:35:644 MSK [DEBUG] headers - http-outgoing-6 >> Host: api.vk.com
[err] 2016/11/11 14:54:35:644 MSK [DEBUG] headers - http-outgoing-6 >> Connection: Keep-Alive
[err] 2016/11/11 14:54:35:645 MSK [DEBUG] headers - http-outgoing-6 >> User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/54.0.2840.71 Safari/537.36
[err] 2016/11/11 14:54:35:645 MSK [DEBUG] headers - http-outgoing-6 >> Accept-Encoding: gzip,deflate
[err] 2016/11/11 14:54:35:725 MSK [DEBUG] headers - http-outgoing-6 << HTTP/1.1 200 OK
[err] 2016/11/11 14:54:35:725 MSK [DEBUG] headers - http-outgoing-6 << Server: Apache
[err] 2016/11/11 14:54:35:726 MSK [DEBUG] headers - http-outgoing-6 << Date: Fri, 11 Nov 2016 11:54:35 GMT
[err] 2016/11/11 14:54:35:726 MSK [DEBUG] headers - http-outgoing-6 << Content-Type: application/json; charset=utf-8
[err] 2016/11/11 14:54:35:726 MSK [DEBUG] headers - http-outgoing-6 << Content-Length: 286
[err] 2016/11/11 14:54:35:727 MSK [DEBUG] headers - http-outgoing-6 << Connection: keep-alive
[err] 2016/11/11 14:54:35:727 MSK [DEBUG] headers - http-outgoing-6 << X-Powered-By: PHP/3.7212
[err] 2016/11/11 14:54:35:727 MSK [DEBUG] headers - http-outgoing-6 << Set-Cookie: remixlang=0; expires=Sun, 05 Nov 2017 18:31:29 GMT; path=/; domain=.vk.com
[err] 2016/11/11 14:54:35:727 MSK [DEBUG] headers - http-outgoing-6 << Pragma: no-cache
[err] 2016/11/11 14:54:35:728 MSK [DEBUG] headers - http-outgoing-6 << Cache-control: no-store
[err] 2016/11/11 14:54:35:728 MSK [DEBUG] headers - http-outgoing-6 << Content-Encoding: gzip
[err] 2016/11/11 14:54:35:728 MSK [DEBUG] MainClientExec - Connection can be kept alive indefinitely
[err] 2016/11/11 14:54:35:729 MSK [DEBUG] DefaultManagedHttpClientConnection - http-outgoing-6: Close connection
[err] 2016/11/11 14:54:35:730 MSK [DEBUG] MainClientExec - Connection discarded
[err] 2016/11/11 14:54:35:730 MSK [DEBUG] PoolingHttpClientConnectionManager - Connection released: [id: 6][route: {s}->https://api.vk.com:443][total kept alive: 0; route allocated: 0 of 2; total allocated: 0 of 50]
[err] 2016/11/11 14:54:35:730 MSK [DEBUG] RequestAddCookies - CookieSpec selected: ignoreCookies
[err] 2016/11/11 14:54:35:731 MSK [DEBUG] RequestAuthCache - Auth cache not set in the context
[err] 2016/11/11 14:54:35:731 MSK [DEBUG] PoolingHttpClientConnectionManager - Connection request: [route: {s}->https://api.vk.com:443][total kept alive: 0; route allocated: 0 of 2; total allocated: 0 of 50]
[err] 2016/11/11 14:54:35:731 MSK [DEBUG] PoolingHttpClientConnectionManager - Connection leased: [id: 7][route: {s}->https://api.vk.com:443][total kept alive: 0; route allocated: 1 of 2; total allocated: 1 of 50]
[err] 2016/11/11 14:54:35:731 MSK [DEBUG] MainClientExec - Opening connection {s}->https://api.vk.com:443
[err] 2016/11/11 14:54:35:732 MSK [DEBUG] DefaultHttpClientConnectionOperator - Connecting to api.vk.com/87.240.165.75:443
[err] 2016/11/11 14:54:35:732 MSK [DEBUG] SSLConnectionSocketFactory - Connecting socket to api.vk.com/87.240.165.75:443 with timeout 5000
[err] 2016/11/11 14:54:35:786 MSK [DEBUG] SSLConnectionSocketFactory - Enabled protocols: [TLSv1, TLSv1.1, TLSv1.2]
[err] 2016/11/11 14:54:35:787 MSK [DEBUG] SSLConnectionSocketFactory - Enabled cipher suites:[TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_DSS_WITH_AES_128_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_DSS_WITH_AES_128_GCM_SHA256, TLS_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]
[err] 2016/11/11 14:54:35:787 MSK [DEBUG] SSLConnectionSocketFactory - Starting handshake
[err] 2016/11/11 14:54:35:909 MSK [DEBUG] SSLConnectionSocketFactory - Secure session established
[err] 2016/11/11 14:54:35:910 MSK [DEBUG] SSLConnectionSocketFactory -  negotiated protocol: TLSv1.2
[err] 2016/11/11 14:54:35:910 MSK [DEBUG] SSLConnectionSocketFactory -  negotiated cipher suite: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
[err] 2016/11/11 14:54:35:910 MSK [DEBUG] SSLConnectionSocketFactory -  peer principal: CN=*.vk.com, OU=Domain Control Validated
[err] 2016/11/11 14:54:35:911 MSK [DEBUG] SSLConnectionSocketFactory -  peer alternative names: [*.vk.com, vk.com]
[err] 2016/11/11 14:54:35:911 MSK [DEBUG] SSLConnectionSocketFactory -  issuer principal: CN=Go Daddy Secure Certificate Authority - G2, OU=http://certs.godaddy.com/repository/, O="GoDaddy.com, Inc.", L=Scottsdale, ST=Arizona, C=US
[err] 2016/11/11 14:54:35:911 MSK [DEBUG] DefaultHttpClientConnectionOperator - Connection established 172.20.10.2:55318<->87.240.165.75:443
[err] 2016/11/11 14:54:35:912 MSK [DEBUG] DefaultManagedHttpClientConnection - http-outgoing-7: set socket timeout to 60000
[err] 2016/11/11 14:54:35:912 MSK [DEBUG] MainClientExec - Executing request GET /method/database.getCountries HTTP/1.1
[err] 2016/11/11 14:54:35:912 MSK [DEBUG] MainClientExec - Target auth state: UNCHALLENGED
[err] 2016/11/11 14:54:35:913 MSK [DEBUG] MainClientExec - Proxy auth state: UNCHALLENGED
[err] 2016/11/11 14:54:35:913 MSK [DEBUG] headers - http-outgoing-7 >> GET /method/database.getCountries HTTP/1.1
[err] 2016/11/11 14:54:35:913 MSK [DEBUG] headers - http-outgoing-7 >> Host: api.vk.com
[err] 2016/11/11 14:54:35:913 MSK [DEBUG] headers - http-outgoing-7 >> Connection: Keep-Alive
[err] 2016/11/11 14:54:35:914 MSK [DEBUG] headers - http-outgoing-7 >> User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/54.0.2840.71 Safari/537.36
[err] 2016/11/11 14:54:35:914 MSK [DEBUG] headers - http-outgoing-7 >> Accept-Encoding: gzip,deflate
[err] 2016/11/11 14:54:35:989 MSK [DEBUG] headers - http-outgoing-7 << HTTP/1.1 200 OK
[err] 2016/11/11 14:54:35:989 MSK [DEBUG] headers - http-outgoing-7 << Server: Apache
[err] 2016/11/11 14:54:35:990 MSK [DEBUG] headers - http-outgoing-7 << Date: Fri, 11 Nov 2016 11:54:35 GMT
[err] 2016/11/11 14:54:35:990 MSK [DEBUG] headers - http-outgoing-7 << Content-Type: application/json; charset=utf-8
[err] 2016/11/11 14:54:35:990 MSK [DEBUG] headers - http-outgoing-7 << Content-Length: 286
[err] 2016/11/11 14:54:35:990 MSK [DEBUG] headers - http-outgoing-7 << Connection: keep-alive
[err] 2016/11/11 14:54:35:991 MSK [DEBUG] headers - http-outgoing-7 << X-Powered-By: PHP/3.7212
[err] 2016/11/11 14:54:35:991 MSK [DEBUG] headers - http-outgoing-7 << Set-Cookie: remixlang=0; expires=Wed, 08 Nov 2017 21:16:16 GMT; path=/; domain=.vk.com
[err] 2016/11/11 14:54:35:991 MSK [DEBUG] headers - http-outgoing-7 << Pragma: no-cache
[err] 2016/11/11 14:54:35:991 MSK [DEBUG] headers - http-outgoing-7 << Cache-control: no-store
[err] 2016/11/11 14:54:35:992 MSK [DEBUG] headers - http-outgoing-7 << Content-Encoding: gzip
[err] 2016/11/11 14:54:35:992 MSK [DEBUG] MainClientExec - Connection can be kept alive indefinitely
[err] 2016/11/11 14:54:35:992 MSK [DEBUG] DefaultManagedHttpClientConnection - http-outgoing-7: Close connection
[err] 2016/11/11 14:54:35:993 MSK [DEBUG] MainClientExec - Connection discarded
[err] 2016/11/11 14:54:35:993 MSK [DEBUG] PoolingHttpClientConnectionManager - Connection released: [id: 7][route: {s}->https://api.vk.com:443][total kept alive: 0; route allocated: 0 of 2; total allocated: 0 of 50]
[err] 2016/11/11 14:54:35:994 MSK [DEBUG] RequestAddCookies - CookieSpec selected: ignoreCookies
[err] 2016/11/11 14:54:35:994 MSK [DEBUG] RequestAuthCache - Auth cache not set in the context
[err] 2016/11/11 14:54:35:994 MSK [DEBUG] PoolingHttpClientConnectionManager - Connection request: [route: {s}->https://api.vk.com:443][total kept alive: 0; route allocated: 0 of 2; total allocated: 0 of 50]
[err] 2016/11/11 14:54:35:995 MSK [DEBUG] PoolingHttpClientConnectionManager - Connection leased: [id: 8][route: {s}->https://api.vk.com:443][total kept alive: 0; route allocated: 1 of 2; total allocated: 1 of 50]
[err] 2016/11/11 14:54:35:995 MSK [DEBUG] MainClientExec - Opening connection {s}->https://api.vk.com:443
[err] 2016/11/11 14:54:35:996 MSK [DEBUG] DefaultHttpClientConnectionOperator - Connecting to api.vk.com/87.240.165.75:443
[err] 2016/11/11 14:54:35:996 MSK [DEBUG] SSLConnectionSocketFactory - Connecting socket to api.vk.com/87.240.165.75:443 with timeout 5000
[err] 2016/11/11 14:54:36:050 MSK [DEBUG] SSLConnectionSocketFactory - Enabled protocols: [TLSv1, TLSv1.1, TLSv1.2]
[err] 2016/11/11 14:54:36:050 MSK [DEBUG] SSLConnectionSocketFactory - Enabled cipher suites:[TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_DSS_WITH_AES_128_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_DSS_WITH_AES_128_GCM_SHA256, TLS_ECDHE_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_ECDSA_WITH_3DES_EDE_CBC_SHA, TLS_ECDH_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]
[err] 2016/11/11 14:54:36:050 MSK [DEBUG] SSLConnectionSocketFactory - Starting handshake
[err] 2016/11/11 14:54:36:117 MSK [DEBUG] SSLConnectionSocketFactory - Secure session established
[err] 2016/11/11 14:54:36:118 MSK [DEBUG] SSLConnectionSocketFactory -  negotiated protocol: TLSv1.2
[err] 2016/11/11 14:54:36:118 MSK [DEBUG] SSLConnectionSocketFactory -  negotiated cipher suite: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
[err] 2016/11/11 14:54:36:118 MSK [DEBUG] SSLConnectionSocketFactory -  peer principal: CN=*.vk.com, OU=Domain Control Validated
[err] 2016/11/11 14:54:36:118 MSK [DEBUG] SSLConnectionSocketFactory -  peer alternative names: [*.vk.com, vk.com]
[err] 2016/11/11 14:54:36:118 MSK [DEBUG] SSLConnectionSocketFactory -  issuer principal: CN=Go Daddy Secure Certificate Authority - G2, OU=http://certs.godaddy.com/repository/, O="GoDaddy.com, Inc.", L=Scottsdale, ST=Arizona, C=US
[err] 2016/11/11 14:54:36:119 MSK [DEBUG] DefaultHttpClientConnectionOperator - Connection established 172.20.10.2:55331<->87.240.165.75:443
[err] 2016/11/11 14:54:36:119 MSK [DEBUG] DefaultManagedHttpClientConnection - http-outgoing-8: set socket timeout to 60000
[err] 2016/11/11 14:54:36:119 MSK [DEBUG] MainClientExec - Executing request GET /method/database.getCountries HTTP/1.1
[err] 2016/11/11 14:54:36:119 MSK [DEBUG] MainClientExec - Target auth state: UNCHALLENGED
[err] 2016/11/11 14:54:36:119 MSK [DEBUG] MainClientExec - Proxy auth state: UNCHALLENGED
[err] 2016/11/11 14:54:36:120 MSK [DEBUG] headers - http-outgoing-8 >> GET /method/database.getCountries HTTP/1.1
[err] 2016/11/11 14:54:36:120 MSK [DEBUG] headers - http-outgoing-8 >> Host: api.vk.com
[err] 2016/11/11 14:54:36:120 MSK [DEBUG] headers - http-outgoing-8 >> Connection: Keep-Alive
[err] 2016/11/11 14:54:36:120 MSK [DEBUG] headers - http-outgoing-8 >> User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/54.0.2840.71 Safari/537.36
[err] 2016/11/11 14:54:36:120 MSK [DEBUG] headers - http-outgoing-8 >> Accept-Encoding: gzip,deflate
[err] 2016/11/11 14:54:36:188 MSK [DEBUG] headers - http-outgoing-8 << HTTP/1.1 200 OK
[err] 2016/11/11 14:54:36:189 MSK [DEBUG] headers - http-outgoing-8 << Server: Apache
[err] 2016/11/11 14:54:36:189 MSK [DEBUG] headers - http-outgoing-8 << Date: Fri, 11 Nov 2016 11:54:36 GMT
[err] 2016/11/11 14:54:36:189 MSK [DEBUG] headers - http-outgoing-8 << Content-Type: application/json; charset=utf-8
[err] 2016/11/11 14:54:36:189 MSK [DEBUG] headers - http-outgoing-8 << Content-Length: 286
[err] 2016/11/11 14:54:36:190 MSK [DEBUG] headers - http-outgoing-8 << Connection: keep-alive
[err] 2016/11/11 14:54:36:190 MSK [DEBUG] headers - http-outgoing-8 << X-Powered-By: PHP/3.7212
[err] 2016/11/11 14:54:36:190 MSK [DEBUG] headers - http-outgoing-8 << Set-Cookie: remixlang=0; expires=Thu, 16 Nov 2017 00:20:15 GMT; path=/; domain=.vk.com
[err] 2016/11/11 14:54:36:190 MSK [DEBUG] headers - http-outgoing-8 << Pragma: no-cache
[err] 2016/11/11 14:54:36:190 MSK [DEBUG] headers - http-outgoing-8 << Cache-control: no-store
[err] 2016/11/11 14:54:36:190 MSK [DEBUG] headers - http-outgoing-8 << Content-Encoding: gzip
[err] 2016/11/11 14:54:36:191 MSK [DEBUG] MainClientExec - Connection can be kept alive indefinitely
[err] 2016/11/11 14:54:36:191 MSK [DEBUG] DefaultManagedHttpClientConnection - http-outgoing-8: Close connection
[err] 2016/11/11 14:54:36:192 MSK [DEBUG] MainClientExec - Connection discarded
[err] 2016/11/11 14:54:36:192 MSK [DEBUG] PoolingHttpClientConnectionManager - Connection released: [id: 8][route: {s}->https://api.vk.com:443][total kept alive: 0; route allocated: 0 of 2; total allocated: 0 of 50]
[14:54:36.193] TRACE [proliker.utils.TestService.hc(TestService.java:300)]: reqTime1:    319 
[14:54:36.193] TRACE [proliker.utils.TestService.hc(TestService.java:301)]: reqTime2:    264 
[14:54:36.194] TRACE [proliker.utils.TestService.hc(TestService.java:302)]: reqTime3:    198 

Of course, the above tests were performed with internal logging turned OFF because it adds additional ~50 ms to each request.

I have read ALL apache http-client site docs thrice, I have no idea where to look and where I have mistake. I hope so much, that some geek can help me increase request speed.

like image 989
Alex Torson Avatar asked Nov 11 '16 12:11

Alex Torson


1 Answers

[err] 2016/11/11 14:54:36:191 MSK [DEBUG] MainClientExec - Connection can be kept alive indefinitely
[err] 2016/11/11 14:54:36:191 MSK [DEBUG] DefaultManagedHttpClientConnection - http-outgoing-8: Close connection
[err] 2016/11/11 14:54:36:192 MSK [DEBUG] MainClientExec - Connection discarded

If this is not intentional then the simplest way to make HttpClient faster is by re-using connections (especially when using SSL/TLS transport security).

Always make sure that response content has been fully consumed (by reading from the content stream until end of the stream or by closing the stream).

try(CloseableHttpResponse response1 = httpClient.execute(new HttpGet("https://api.vk.com/method/database.getCountries"))) {
    int code1 = response1.getStatusLine().getStatusCode();
    EntityUtils.consume(response1.getEntity());
}
like image 59
ok2c Avatar answered Oct 20 '22 14:10

ok2c