Archived Forum Post

Index of archived forum posts

Question:

Http is slow

Nov 28 '16 at 18:37

We replaced our library by chilkat and it is 4x slower. We guess it is the resolving phase. Can we disable it ?


Answer

Since we saw the post : http://www.chilkatforum.com/questions/5880/dns-caching We did more test with the CkHttp client but the dns caching doesn't seem to works:

DWORD tick = GetTickCount();
CkHttpResponse* rsp = http.SynchronousRequest(host.c_str(), port, useSsl, *request);
TRACE("test1 %d \n", GetTickCount() - tick);
tick = GetTickCount();
rsp = http.SynchronousRequest(host.c_str(), port, useSsl, *request);
TRACE("test2 %d \n", GetTickCount() - tick);
tick = GetTickCount();
rsp = http.SynchronousRequest(host.c_str(), port, useSsl, *request);
TRACE("test3 %d \n", GetTickCount() - tick);
tick = GetTickCount();
rsp = http.SynchronousRequest(host.c_str(), port, useSsl, *request);
TRACE("test4 %d \n", GetTickCount() - tick);
tick = GetTickCount();
rsp = http.SynchronousRequest(host.c_str(), port, useSsl, *request);
TRACE("test5 %d \n", GetTickCount() - tick);
tick = GetTickCount();
rsp = http.SynchronousRequest(host.c_str(), port, useSsl, *request);
TRACE("test6 %d \n", GetTickCount() - tick);

Result :

test1 453 
test2 407 
test3 453 
test4 375 
test5 359 
test6 422

We did some test with XMLRPC chilkat client vs XmlRpcClient :

prepareRequest(methodName, params);

DWORD tick = GetTickCount();
const char* rsp = http.xmlRpc(url.c_str(), request.c_str());
TRACE("New %d \n", GetTickCount() - tick);

tick = GetTickCount();
XmlRpcClient c(server.c_str(), port, uri.c_str());
success =  c.execute(methodName, params, result);
TRACE("old %d \n", GetTickCount() - tick);

Result :

New 297 
old 93 
New 329 
old 62 
New 328 
old 63 
New 328 
old 109 
New 297 
old 78 
New 328 
old 63 
New 296 
old 79 
New 312 
old 78 
New 375 
old 125 
New 453 
old 188 
New 297 
old 62 
New 375 
old 141 
New 390 
old 94 
New 297 
old 109  
New 422 
old 141 
New 375 
old 63 
New 297 
old 62 
New 297 
old 93

Answer

These tests were done within a VPN.


Answer

My only guess is that maybe it has to do with DNS lookups (i.e. resolving a domain name to IP address). One way to find out what is consuming time is to turn on verbose logging (by setting the VerboseLogging property = true), and then examine the LastErrorText after the method call. The LastErrorText will always contain information about the call, even if successful, and when verbose, the time spent within each context, if greater than 1ms, will be shown.

Also, in any Chilkat method where a domain name is passed, you can instead pass the IP address. That would certainly avoid having Chilkat resolve the domain name.

Also, the Chilkat.Global.EnableDnsCaching property can be set to true. This makes it so that a domain name resolutions are cached. I'll check on the information at http://www.chilkatforum.com/questions/5880/dns-caching to see how this relates to Global.EnableDnsCaching


Answer

I looked into it...

The Chilkat.Global.EnableDnsCaching needs to be set to true to enable caching in the first place. The Http.DnsCacheClear would only have an effect if EnableDnsCaching was turned on. Otherwise, the cache is already empty because it was never enabled.


Answer

Thanks for your answers.

We were already using IP address. I enabled DNS caching and verbose without any noticeable improvement:

HTTP test (Time in ms):

    test1 438 
    ChilkatLog:
      SynchronousRequest(438ms):
        DllDate: Nov 12 2016
        ChilkatVersion: 9.5.0.64
        UnlockPrefix: IMAGEMHttp
        Architecture: Little Endian; 32-bit
        Language: Visual C++ 10.0 (32-bit)
        VerboseLogging: 1
        domain: 10.103.104.167
        port: 80
        ssl: 0
        originallySetFromUrl: http://10.103.104.111:80/PSlicence/api/v1/authentication
        httpRequest:
          httpVersion: 1.1
          verb: POST
          path: /PSlicence/api/v1/authentication
          contentType: application/x-www-form-urlencoded
          charset: windows-1252
          sendCharset: 0
          mimeHeader: 
          requestParams:
            requestItem:
              name: action
              value: login
            --requestItem
            requestIt
    test2 375 
    ChilkatLog:
      SynchronousRequest(375ms):
        DllDate: Nov 12 2016
        ChilkatVersion: 9.5.0.64
        UnlockPrefix: IMAGEMHttp
        Architecture: Little Endian; 32-bit
        Language: Visual C++ 10.0 (32-bit)
        VerboseLogging: 1
        domain: 10.103.104.167
        port: 80
        ssl: 0
        originallySetFromUrl: http://10.103.104.111:80/PSlicence/api/v1/authentication
        httpRequest:
          httpVersion: 1.1
          verb: POST
          path: /PSlicence/api/v1/authentication
          contentType: application/x-www-form-urlencoded
          charset: windows-1252
          sendCharset: 0
          mimeHeader: 
          requestParams:
            requestItem:
              name: action
              value: login
            --requestItem
            requestIt

XMLRPC comparison (New means chilkat http, old means another client) (Time in ms):

New 328 
ChilkatLog:
  XmlRpcPost(328ms):
    DllDate: Nov 12 2016
    ChilkatVersion: 9.5.0.64
    UnlockPrefix: IMAGEMHttp
    Architecture: Little Endian; 32-bit
    Language: Visual C++ 10.0 (32-bit)
    VerboseLogging: 1
    url: http://10.103.104.167:8084/RPC2
    finalizeRequestHeader:
      Auto-adding Host header.
    --finalizeRequestHeader
    fullRequest(312ms):
      httpRequest:
        httpVersion: 1.1
        verb: POST
        path: /RPC2
        contentType: text/xml
        charset: utf-8
        sendCharset: 0
        mimeHeader: Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Connection: keep-alive
User-Agent: Mozilla/5.0 (Windows NT 6.3; WOW64; rv:49.0) Gecko/20100101 Firefox/49.0
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip
      --httpRequest
      HttpOptions:
        AddHostHeader: 1
        AllowCookieResponseCaching: 0
        AllowGzip: 1
        CookieDir: 
        FollowRedirects: 1
        Login: 
        LoginDomain: 
old 78 
New 313 
ChilkatLog:
  XmlRpcPost(313ms):
    DllDate: Nov 12 2016
    ChilkatVersion: 9.5.0.64
    UnlockPrefix: IMAGEMHttp
    Architecture: Little Endian; 32-bit
    Language: Visual C++ 10.0 (32-bit)
    VerboseLogging: 1
    url: http://10.103.104.167:8084/RPC2
    finalizeRequestHeader:
      Auto-adding Host header.
    --finalizeRequestHeader
    fullRequest(313ms):
      httpRequest:
        httpVersion: 1.1
        verb: POST
        path: /RPC2
        contentType: text/xml
        charset: utf-8
        sendCharset: 0
        mimeHeader: Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Connection: keep-alive
User-Agent: Mozilla/5.0 (Windows NT 6.3; WOW64; rv:49.0) Gecko/20100101 Firefox/49.0
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip
      --httpRequest
      HttpOptions:
        AddHostHeader: 1
        AllowCookieResponseCaching: 0
        AllowGzip: 1
        CookieDir: 
        FollowRedirects: 1
        Login: 
        LoginDomain: 
old 62 
New 391 
ChilkatLog:
  XmlRpcPost(375ms):
    DllDate: Nov 12 2016
    ChilkatVersion: 9.5.0.64
    UnlockPrefix: IMAGEMHttp
    Architecture: Little Endian; 32-bit
    Language: Visual C++ 10.0 (32-bit)
    VerboseLogging: 1
    url: http://10.103.104.167:8084/RPC2
    finalizeRequestHeader:
      Auto-adding Host header.
    --finalizeRequestHeader
    fullRequest(375ms):
      httpRequest:
        httpVersion: 1.1
        verb: POST
        path: /RPC2
        contentType: text/xml
        charset: utf-8
        sendCharset: 0
        mimeHeader: Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Connection: keep-alive
User-Agent: Mozilla/5.0 (Windows NT 6.3; WOW64; rv:49.0) Gecko/20100101 Firefox/49.0
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip
      --httpRequest
      HttpOptions:
        AddHostHeader: 1
        AllowCookieResponseCaching: 0
        AllowGzip: 1
        CookieDir: 
        FollowRedirects: 1
        Login: 
        LoginDomain: 
old 109 
New 313 
ChilkatLog:
  XmlRpcPost(313ms):
    DllDate: Nov 12 2016
    ChilkatVersion: 9.5.0.64
    UnlockPrefix: IMAGEMHttp
    Architecture: Little Endian; 32-bit
    Language: Visual C++ 10.0 (32-bit)
    VerboseLogging: 1
    url: http://10.103.104.167:8084/RPC2
    finalizeRequestHeader:
      Auto-adding Host header.
    --finalizeRequestHeader
    fullRequest(313ms):
      httpRequest:
        httpVersion: 1.1
        verb: POST
        path: /RPC2
        contentType: text/xml
        charset: utf-8
        sendCharset: 0
        mimeHeader: Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Connection: keep-alive
User-Agent: Mozilla/5.0 (Windows NT 6.3; WOW64; rv:49.0) Gecko/20100101 Firefox/49.0
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip
      --httpRequest
      HttpOptions:
        AddHostHeader: 1
        AllowCookieResponseCaching: 0
        AllowGzip: 1
        CookieDir: 
        FollowRedirects: 1
        Login: 
        LoginDomain: 
old 78 
New 297 
ChilkatLog:
  XmlRpcPost(297ms):
    DllDate: Nov 12 2016
    ChilkatVersion: 9.5.0.64
    UnlockPrefix: IMAGEMHttp
    Architecture: Little Endian; 32-bit
    Language: Visual C++ 10.0 (32-bit)
    VerboseLogging: 1
    url: http://10.103.104.167:8084/RPC2
    finalizeRequestHeader:
      Auto-adding Host header.
    --finalizeRequestHeader
    fullRequest(297ms):
      httpRequest:
        httpVersion: 1.1
        verb: POST
        path: /RPC2
        contentType: text/xml
        charset: utf-8
        sendCharset: 0
        mimeHeader: Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Connection: keep-alive
User-Agent: Mozilla/5.0 (Windows NT 6.3; WOW64; rv:49.0) Gecko/20100101 Firefox/49.0
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip
      --httpRequest
      HttpOptions:
        AddHostHeader: 1
        AllowCookieResponseCaching: 0
        AllowGzip: 1
        CookieDir: 
        FollowRedirects: 1
        Login: 
        LoginDomain: 
old 62

Answer

Thanks, but you truncated each LastErrorText. What we really need to see is the full contents of a verbose LastErrorText for one call to SynchronousRequest that takes longer than expected.


Answer

My bad, VS trace doesn't log all. At first, we thought that the our server cache could shorter the 2nd transaction, but we have the exact same result (Old client about 4x faster), if we use our old client first. (We run the exact same request)

Xmlrpc comparison:

[2016-11-25 11:08:53]   [DEBUG]     Chilkat http client took 313 ms

[2016-11-25 11:08:53]   [DEBUG]     ChilkatLog:

  XmlRpcPost(313ms):

    DllDate: Nov 12 2016

    ChilkatVersion: 9.5.0.64

    UnlockPrefix: IMAGEMHttp

    Architecture: Little Endian; 32-bit

    Language: Visual C++ 10.0 (32-bit)

    VerboseLogging: 1

    url: http://10.103.104.167:8084/RPC2

    finalizeRequestHeader:

      Auto-adding Host header.

    --finalizeRequestHeader

    fullRequest(313ms):

      httpRequest:

        httpVersion: 1.1

        verb: POST

        path: /RPC2

        contentType: text/xml

        charset: utf-8

        sendCharset: 0

        mimeHeader: Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8

Connection: keep-alive

User-Agent: Mozilla/5.0 (Windows NT 6.3; WOW64; rv:49.0) Gecko/20100101 Firefox/49.0

Accept-Language: en-us,en;q=0.5

Accept-Encoding: gzip

      --httpRequest

      HttpOptions:

        AddHostHeader: 1

        AllowCookieResponseCaching: 0

        AllowGzip: 1

        CookieDir:

        FollowRedirects: 1

        Login:

        LoginDomain:

        AuthMethod:

        MaxResponseSize: 0

        MaxUrlLen: 2000

        PasswordLen: 0

        ReadTimeoutMs: 300000

        RequiredContentType:

        ResumePoint: 0

        SaveCookies: 1

        SendBufferSize: 65535

        SendCookies: 1

        UnavailableRetryCount: 0

        UnavailableRetryWaitMs: 2000

      --HttpOptions

      a_synchronousRequest(313ms):

        generateRequestHeader:

          httpRequestGenStartLine:

            authOnly: 0

            hasMimeBody: 1

            genStartLine:

              startLine: POST /RPC2 HTTP/1.1

            --genStartLine

          --httpRequestGenStartLine

          startLine: POST /RPC2 HTTP/1.1

          genHeaderSb:

            getMimeHeaderHttp:

              headerField: Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8

              headerField: Connection: keep-alive

              headerField: User-Agent: Mozilla/5.0 (Windows NT 6.3; WOW64; rv:49.0) Gecko/20100101 Firefox/49.0

              headerField: Accept-Language: en-us,en;q=0.5

              headerField: Accept-Encoding: gzip

            --getMimeHeaderHttp

          --genHeaderSb

          addCookies:

            Not auto-adding cookies.

            sendCookies: 1

            cookieDir:

          --addCookies

          m_host: 10.103.104.167:8084

          finalRequestHdr: Content-Type: text/xml

Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8

Connection: keep-alive

User-Agent: Mozilla/5.0 (Windows NT 6.3; WOW64; rv:49.0) Gecko/20100101 Firefox/49.0

Accept-Language: en-us,en;q=0.5

Accept-Encoding: gzip

Host: 10.103.104.167:8084

Content-Length: 191

        --generateRequestHeader

        fullHttpRequest(313ms):

          domain: 10.103.104.167

          port: 8084

          ssl: 0

          openHttpConnection(32ms):

            Opening connection directly to HTTP server.

            httpHostname: 10.103.104.167

            httpPort: 8084

            ssl: 0

            bUsingHttpProxy: 0

            httpProxyAuthMethod:

            socket2Connect(32ms):

              connect2(32ms):

                hostname: 10.103.104.167

                port: 8084

                ssl: 0

                connectSocket(32ms):

                  domainOrIpAddress: 10.103.104.167

                  port: 8084

                  connectTimeoutMs: 300000

                  connect_ipv6_or_ipv4(32ms):

                    This is an IPV4 numeric address.

                    Domain to IP address resolution not needed.

                    connecting to IPV4 address...

                    ipAddress: 10.103.104.167

                    createSocket:

                      Setting SO_SNDBUF size

                      sendBufSize: 262144

                      Setting SO_RCVBUF size

                      recvBufSize: 4194304

                    --createSocket

                    connect(32ms):

                      Waiting for the connect to complete...

                      myIP: 10.152.53.88

                      myPort: 4944

                      socket connect successful.

                    --connect

                  --connect_ipv6_or_ipv4

                --connectSocket

              --connect2

            --socket2Connect

            socketOptions:

              SO_SNDBUF: 262144

              SO_RCVBUF: 4194304

              TCP_NODELAY: 0

              SO_KEEPALIVE: 1

            --socketOptions

            HTTP connection succeeded.

          --openHttpConnection

          connectTime: Elapsed time: 32 millisec

          startLine: POST /RPC2 HTTP/1.1

          fullRequestHeader:

            requestHeader: Content-Type: text/xml

Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8

Connection: keep-alive

User-Agent: Mozilla/5.0 (Windows NT 6.3; WOW64; rv:49.0) Gecko/20100101 Firefox/49.0

Accept-Language: en-us,en;q=0.5

Accept-Encoding: gzip

Host: 10.103.104.167:8084

Content-Length: 191

          --fullRequestHeader

          computeRequestDataSize:

            Request body is in a memory buffer..

          --computeRequestDataSize

          sendRequestHeader:

            sendHeaderElapsedMs: 0

          --sendRequestHeader

          sendRequestBody:

            idleTimeoutMs: 300000

            sendBodyElapsedMs: 0

          --sendRequestBody

          readResponseHeader(281ms):

            responseHeader: HTTP/1.1 200 OK

Server: Apache XML-RPC 1.0

Connection: close

Content-Type: text/xml

Content-Length: 128

          --readResponseHeader

          statusCode: 200

          statusText: OK

          readResponseBody:

            bDiscard: 0

            contentLength: 128

            numBytesToReceive: 128

          --readResponseBody

          responseBodySize: 128

          checkCloseConnection:

            Response includes connection:close header (or proxy-connection:close header)

            cleanCloseHttpConnection:

              terminateConnection:

                TCP connection cleanly closed by peer.

                Cleanly terminated TCP connection.

              --terminateConnection

            --cleanCloseHttpConnection

          --checkCloseConnection

        --fullHttpRequest

        originalUrl: http://10.103.104.167:8084/RPC2

        success: 1

      --a_synchronousRequest

      success: 1

    --fullRequest

    Success.

  --XmlRpcPost

  Success.

--ChilkatLog

[2016-11-25 11:08:53]   [DEBUG]     Old client took 78 ms

Answer

The LastErrorText tells us:

  1. Establishing the connection took 32ms (socket2Connect(32ms))
  2. Sending the request header + body was < 1ms because the times were not reported (sendRequestHeader/sendRequestBody). When sending, the socket "send" function is essentially handing the data to the OS to send. (The following essentially applies to Windows, Linux, Mac, FreeBSD, Solaris, etc: https://linux.die.net/man/2/send )
  3. Receiving the response took 281ms (readResponseHeader(281ms)). The time spent here could've included time spent by the OS in actually sending out the request. I see the "TCP_NODELAY: 0" is 0/false. Maybe this is the problem. I'll check into it..

Answer

Try this new build, which should have TCP_NODELAY turned on:

http://chilkatdownload.com/prerelease/chilkat-9.5.0-x86-vc10-sp1.zip
http://chilkatdownload.com/prerelease/chilkat-9.5.0-x86_64-vc10-sp1.zip


Answer

That's it, now we got similar response time!

[2016-11-28 09:51:08]   [DEBUG]     Chilkat http client took 78 ms
[2016-11-28 09:51:08]   [DEBUG]     Old client took 63 ms
[2016-11-28 09:51:08]   [DEBUG]     Chilkat http client took 93 ms
[2016-11-28 09:51:08]   [DEBUG]     Old client took 78 ms
[2016-11-28 09:51:09]   [DEBUG]     Chilkat http client took 78 ms
[2016-11-28 09:51:09]   [DEBUG]     Old client took 78 ms
[2016-11-28 09:51:09]   [DEBUG]     Chilkat http client took 62 ms
[2016-11-28 09:51:09]   [DEBUG]     Old client took 78 ms
[2016-11-28 09:51:09]   [DEBUG]     Chilkat http client took 62 ms
[2016-11-28 09:51:09]   [DEBUG]     Old client took 94 ms
[2016-11-28 09:51:09]   [DEBUG]     Chilkat http client took 110 ms
[2016-11-28 09:51:10]   [DEBUG]     Old client took 79 ms