POST request with request body slow with TLS

[llJochemll]

It seems like a POST request with a request body performs considerably worse than a request without one when using TLS.

I don't know if I'm missing something or if I made any mistakes, if that's the case please let me know.

Results:

No TLS:
With body: 47 ms, 816 ╬╝s, and 1 hnsec
Without body: 44 ms, 917 ╬╝s, and 8 hnsecs
2 ms, 898 ╬╝s, and 3 hnsecs difference
-------------------------------------------
TLS:
With body: 135 ms and 559 ╬╝s
Without body: 50 ms, 824 ╬╝s, and 3 hnsecs
84 ms, 734 ╬╝s, and 7 hnsecs difference

Code:

import requests;
import std.datetime;
import std.stdio;
void main() {
    int iterations = 50;

    writeln("No TLS:");
    writeln((withBody("http://eu.httpbin.org/post", iterations) - withoutBody("http://eu.httpbin.org/post", iterations)), " difference");
    writeln("-------------------------------------------");
    writeln("TLS:");
    writeln((withBody("https://eu.httpbin.org/post", iterations) - withoutBody("https://eu.httpbin.org/post", iterations)), " difference");

}

Duration withBody(string url, int iterations) {
    auto request = Request(); 
    request.keepAlive = true;
    request.sslSetCaCert = "ca.pem";

    auto start = Clock.currTime;
    foreach (i; 0..iterations) {
        request.post(url, `a`);
    }
    auto end = (Clock.currTime - start) / iterations;

    writeln("With body: ", end);

    return end;
}

Duration withoutBody(string url, int iterations) {
    auto request = Request(); 
    request.keepAlive = true;
    request.sslSetCaCert = "ca.pem";

    auto start = Clock.currTime;
    foreach (i; 0..iterations) {
        request.post(url);
    }
    auto end = (Clock.currTime - start) / iterations;

    writeln("Without body: ", end);

    return end;
}

Dub.json:

{
    "name": "testd",
    "dependencies": {
        "requests": "0.10.0"
    }
}

Tested with dub run --arch=x86_64 --build=plain --compiler=dmd on a Windows 10 64bit PC, also tested with OpenSSL1.1 on a Debian 9 VM

[ikod]

Hello, @llJochemll

looking into this

[ikod]

Hello, @llJochemll

Thanks for your valuable reports!

This particular bug were fixed:

No TLS:
With body: 95 ms, 684 μs, and 9 hnsecs
Without body: 94 ms, 491 μs, and 6 hnsecs
1 ms, 193 μs, and 3 hnsecs difference
-------------------------------------------
TLS:
With body: 97 ms, 523 μs, and 8 hnsecs
Without body: 98 ms, 248 μs, and 9 hnsecs
-725 μs and -1 hnsecs difference

It is on the gitmaster now. Please, check.

I also discovered another strange place in code, and I'll roll out bugfix release as soon as I'll fix it.

[ikod]

Ok, looks like this "strange place" is not in my code, so I'll release bugfix soon.

More details: with glibc (linux) call to getaddrinfo lead to some test connects (see https://code.woboq.org/userspace/glibc/sysdeps/posix/getaddrinfo.c.html#2376 ). And I can see these strange connects from strace under linux:

     0.000013 socket(AF_INET, SOCK_DGRAM, IPPROTO_IP) = 3
     0.000012 connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("52.31.160.1")}, 16) = 0
     0.000018 getsockname(3, {sa_family=AF_INET, sin_port=htons(53537), sin_addr=inet_addr("10.0.2.15")}, [28->16]) = 0
     0.000012 connect(3, {sa_family=AF_UNSPEC, sa_data="\0\0\0\0\0\0\0\0\0\0\0\0\0\0"}, 16) = 0
     0.000011 connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("34.253.18.118")}, 16) = 0
     0.000011 getsockname(3, {sa_family=AF_INET, sin_port=htons(39938), sin_addr=inet_addr("10.0.2.15")}, [28->16]) = 0
     0.000012 connect(3, {sa_family=AF_UNSPEC, sa_data="\0\0\0\0\0\0\0\0\0\0\0\0\0\0"}, 16) = 0
     0.000010 connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("52.16.242.35")}, 16) = 0
     0.000010 getsockname(3, {sa_family=AF_INET, sin_port=htons(33047), sin_addr=inet_addr("10.0.2.15")}, [28->16]) = 0
     0.000012 connect(3, {sa_family=AF_UNSPEC, sa_data="\0\0\0\0\0\0\0\0\0\0\0\0\0\0"}, 16) = 0
     0.000009 connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("52.213.184.66")}, 16) = 0
     0.000011 getsockname(3, {sa_family=AF_INET, sin_port=htons(35353), sin_addr=inet_addr("10.0.2.15")}, [28->16]) = 0
     0.000011 connect(3, {sa_family=AF_UNSPEC, sa_data="\0\0\0\0\0\0\0\0\0\0\0\0\0\0"}, 16) = 0
     0.000010 connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("52.17.186.25")}, 16) = 0
     0.000010 getsockname(3, {sa_family=AF_INET, sin_port=htons(54935), sin_addr=inet_addr("10.0.2.15")}, [28->16]) = 0
     0.000011 connect(3, {sa_family=AF_UNSPEC, sa_data="\0\0\0\0\0\0\0\0\0\0\0\0\0\0"}, 16) = 0
     0.000010 connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("52.17.87.182")}, 16) = 0
     0.000011 getsockname(3, {sa_family=AF_INET, sin_port=htons(47093), sin_addr=inet_addr("10.0.2.15")}, [28->16]) = 0
     0.000011 connect(3, {sa_family=AF_UNSPEC, sa_data="\0\0\0\0\0\0\0\0\0\0\0\0\0\0"}, 16) = 0
     0.000010 connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("52.30.103.119")}, 16) = 0
     0.000011 getsockname(3, {sa_family=AF_INET, sin_port=htons(47575), sin_addr=inet_addr("10.0.2.15")}, [28->16]) = 0
     0.000011 connect(3, {sa_family=AF_UNSPEC, sa_data="\0\0\0\0\0\0\0\0\0\0\0\0\0\0"}, 16) = 0
     0.000009 connect(3, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("52.211.4.11")}, 16) = 0

Bottomline - bug with slow ssl post should be fixed, please check. I'll soon roll out bugfix release.

[llJochemll]

Tested again with master, looks all good to me.

Thanks for the fast response!

[ikod]

nice, closing issue