Long respond when Request Body size high than 1024 Bytes

[alex-lebedko]

Hello.
I've found unnormal behaviour in RESTbet library.

When i try to PUT 1024 bytes for Request it pass with 0m0.007s and when i pass 1025+ bytes
Request passed in 0m1.008s

For example:

time curl -X PUT http://127.0.0.1:3911/resource/456456 --data "1111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111"
Done

real 0m0.007s
user 0m0.004s
sys 0m0.000s

time curl -X PUT http://127.0.0.1:3911/resource/456456 --data "11111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111"
Done

real 0m1.008s
user 0m0.004s
sys 0m0.000s

Resource init:

    auto resource = make_shared< Resource >();
    resource->set_path("/resource/{TeaserId: \\d+}");
    resource->set_method_handler("PUT", WebServer::post_method_handler);

handler:

static void post_method_handler(const shared_ptr< Session > session) {
const auto& request = session->get_request();
int content_length = request->get_header( "Content-Length", 0 );
session->fetch( content_length, [](const shared_ptr< Session > session, const Bytes & body){
std::string StrResult;
StrResult= "Done\r\n";
session->close(200, StrResult,{
{ "Content-Length", std::to_string(StrResult.length())}
});
}

[alex-lebedko]

Default example also have same behavior

https://github.com/Corvusoft/restbed/blob/master/example/http_service/source/example.cpp

time curl -w'\n' -v -X POST --data "11111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111" 'http://localhost/resource'

• Hostname was NOT found in DNS cache
• Trying ::1...
• Connected to localhost (::1) port 80 (#0)
  POST /resource HTTP/1.1
  User-Agent: curl/7.38.0
  Host: localhost
  Accept: /
  Content-Length: 1025
  Content-Type: application/x-www-form-urlencoded
  Expect: 100-continue
• Done waiting for 100-continue
  < HTTP/1.1 200 OK
  < Connection: close
  < Content-Length: 13
  <
• Closing connection 0
  Hello, World!

real 0m1.018s
user 0m0.012s
sys 0m0.000s

[ben-crowhurst]

Are you working off HEAD?

[alex-lebedko]

Sorry, but what?

Why when i put 1024 bytes in Request i've got 7 milli second answer and when i try to put 1025 bytes i've got 1000 ms answer speed...

What's wrong with it?
i'm going to choose lib for our project and i can't get clear what to do with this bug or feature, how to increase this limit or buffer .....

[ben-crowhurst]

What commit are you working off?

[alex-lebedko]

Yes, from head.

[ben-crowhurst]

I've not managed to replicate this issue, what platform are you on? Please show your complete codebase.

Test One

Bens-MacBook-Pro-2:restbed Crowhurst$ time curl -w'\n' -v -X POST --data 'Hello, Restbed' 'http://localhost/resource'
* Hostname was NOT found in DNS cache
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 80 (#0)
> POST /resource HTTP/1.1
> User-Agent: curl/7.35.0
> Host: localhost
> Accept: */*
> Content-Length: 14
> Content-Type: application/x-www-form-urlencoded
> 
* upload completely sent off: 14 out of 14 bytes
< HTTP/1.1 200 OK
< Connection: close
< Content-Length: 13
< 
* Closing connection 0
Hello, World!

real    0m0.018s
user    0m0.006s
sys 0m0.006s

Test 2 - 1024 Bytes

Bens-MacBook-Pro-2:restbed Crowhurst$ time curl -w'\n' -v -X POST 'http://localhost/resource' --data "1111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111"
* Hostname was NOT found in DNS cache
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 80 (#0)
> POST /resource HTTP/1.1
> User-Agent: curl/7.35.0
> Host: localhost
> Accept: */*
> Content-Length: 1024
> Content-Type: application/x-www-form-urlencoded
> 
* upload completely sent off: 1024 out of 1024 bytes
< HTTP/1.1 200 OK
< Connection: close
< Content-Length: 13
< 
* Closing connection 0
Hello, World!

real    0m0.018s
user    0m0.008s
sys 0m0.006s

Test 3 - 1025

Bens-MacBook-Pro-2:restbed Crowhurst$ time curl -w'\n' -v -X POST 'http://localhost/resource' --data "11111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111"
* Hostname was NOT found in DNS cache
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 80 (#0)
> POST /resource HTTP/1.1
> User-Agent: curl/7.35.0
> Host: localhost
> Accept: */*
> Content-Length: 1025
> Content-Type: application/x-www-form-urlencoded
> Expect: 100-continue
> 
< HTTP/1.1 200 OK
< Connection: close
< Content-Length: 13
< 
* Closing connection 0
Hello, World!

real    0m0.025s
user    0m0.006s
sys 0m0.006s

Test 4 - 1105 Bytes

Bens-MacBook-Pro-2:restbed Crowhurst$ time curl -w'\n' -v -X POST 'http://localhost/resource' --data "1111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111"
* Hostname was NOT found in DNS cache
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 80 (#0)
> POST /resource HTTP/1.1
> User-Agent: curl/7.35.0
> Host: localhost
> Accept: */*
> Content-Length: 1105
> Content-Type: application/x-www-form-urlencoded
> Expect: 100-continue
> 
< HTTP/1.1 200 OK
< Connection: close
< Content-Length: 13
< 
* Closing connection 0
Hello, World!

real    0m0.018s
user    0m0.006s
sys 0m0.005s

[alex-lebedko]

so.. i use "Linux debian 3.16-2-amd64 #1 SMP Debian 3.16.3-2 (2014-09-20) x86_64 GNU/Linux"
on Intel(R) Core(TM) i3-2100 CPU @ 3.10GHz(cat /proc/cpuinfo)

My http_service dynamic libs

ldd http_service 
    linux-vdso.so.1 (0x00007fff8a75d000)
    librestbed.so.0 => /home/sasha/BuildCpp/Testing/restbed/build/librestbed.so.0 (0x00007f08f9fca000)
    libstdc++.so.6 => /usr/lib/x86_64-linux-gnu/libstdc++.so.6 (0x00007f08f9c8a000)
    libm.so.6 => /lib/x86_64-linux-gnu/libm.so.6 (0x00007f08f9988000)
    libgcc_s.so.1 => /lib/x86_64-linux-gnu/libgcc_s.so.1 (0x00007f08f9772000)
    libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0 (0x00007f08f9555000)
    libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007f08f91ab000)
    libssl.so.1.0.0 => /usr/lib/x86_64-linux-gnu/libssl.so.1.0.0 (0x00007f08f8f4b000)
    libcrypto.so.1.0.0 => /usr/lib/x86_64-linux-gnu/libcrypto.so.1.0.0 (0x00007f08f8b51000)
    /lib64/ld-linux-x86-64.so.2 (0x00007f08fa2ab000)
    libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x00007f08f894c000)

i've run your code example http_service ( this is my code base) 200 times and wrote profile logs...

for ((i=0;i<200;i++)); do curl -w'\n' -v -X POST 'http://localhost/resource' --data "1111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111111"; done;

On each request i've got a correct response but with timeout ~1c....

This is my profile results when i put 1105 bytes std::_Function_handler has 1.31% of loading

This is my profile results when i put 13 Bytes aka "Hello,RestBed" std::_Function_handler has 39.31% of loading

check green blocks.

i guess some asio or allocation function spoil time..

[ben-crowhurst]

I'll look at replicating your rig on a VM and see what I can do.

[ben-crowhurst]

OK! I've ditched the VM and purchased a HP device especially to install debian jessie. And, I've failed to replicate your concern; which is driving me nuts!!!!

I have however found a smaller area of optomisation that I shall apply in the next 24-48hours in the hope of improving your situation.

Thanks for your patience.

[ben-crowhurst]

Good news? I've managed to finally replicate this issue :D. Time to start debugging.

[ben-crowhurst]

This issue has nothing to do with Restbed itself. It is a property of the HTTP protocol. As you can see, when 1025 bytes are transfered Curl sends an Expect: 100-Continue header. It waits for the response before sending the body; causing the delay.

> Expect: 100-continue
> 
* Done waiting for 100-continue

You can handle this in your code by calling Session::yield( CONTINUE, callback ) or by passing -H"Expect:" to the curl command line.

This delay appears to be much shorter on Mac OSX systems, hence why I missed it.