C ++ Boost.ASIO async_read_until slow

Question

I have an unusual problem. I have a C ++ Boost.ASIO web server, and I use this code to process incoming requests:

boost::asio::async_read_until( socket_, response_, "\r\n\r\n", boost::bind( &connection::handle_read_headers, shared_from_this(), boost::asio::placeholders::error, boost::asio::placeholders::bytes_transferred ) ); 

(where "socket_" is my boost :: asio :: ip :: tcp :: socket and "response_" is boost :: asio :: streambuf)

I try to just grab the request headers, then I will later do a second async_read_until with a transmission that exactly matches the "Content-Length" that was parsed from the request header. The problem is that the above code takes 100-900 ms to return to a very modern server (from this read block until handle_read_headers () is called). The incoming request looks like this:

 POST /load HTTP/1.1 host: www.mysite.com Accept: */* Accept-Encoding: gzip,deflate Content-type: application/x-www-form-urlencoded From: googlebot(at)googlebot.com Origin: http://www.mysite.com Referer: http://www.mysite.com/another-page/ User-Agent: Mozilla/5.0 (compatible; Googlebot/2.1; +http://www.google.com/bot.html) X-Forwarded-For: 66.249.75.103 X-Forwarded-Port: 80 X-Forwarded-Proto: http Content-Length: 287 Connection: keep-alive and-the-actual-content-is-here.... (287 bytes worth) 

The headers seem to be completed with \ r \ n \ r \ n, and it runs the handle_read_headers () function before fully reading the EOF (so that it does not read the whole page) - in fact, this is a regular expression. And these requests come from Google, so I'm pretty sure that it is not far behind their end.

Is there anything I could forget about why he has been returning for so long? Any other catches with aync_read_until that I might have missed?

Thanks!

EDIT / UPDATE: Okay, now I'm very confused. After trying a megabyte sentence, I switched from streambuf to an array of characters (no luck), then I reorganized my code to use async_read_some rather than async_read_until, and just scanned it manually. I also reset all OS variables (sysctrl.conf) to the default for bones (to narrow down the possibilities). Unfortunately, I still see 100-900 ms delays in the following code from calling handle_read () with the same incoming POST request:

 socket_.async_read_some( boost::asio::buffer(response_), boost::bind( &connection::handle_read, shared_from_this(), boost::asio::placeholders::error, boost::asio::placeholders::bytes_transferred ) ); 

where response_ is now:

 boost::array<char, 4096> response_; 

To no avail (delay 100-900 ms). No, is that normal, no thoughts?

EDIT2: Following Rhashimoto's recommendation, I turned on handler tracking and found this weirdness in the log:

 [2013-07-05 15:58:39 - Thread 7fae57e3f700]: Incoming connection (0ms elapsed) @asio|1373054319.874916|506*508|[e-mail]_receive @asio|1373054319.874963|506*509|[e-mail]_accept @asio|1373054319.875008|<506| @asio|1373054320.609088|>508|ec=system:0,bytes_transferred=512 @asio|1373054320.609233|508*510|[e-mail]_receive @asio|1373054320.609264|<508| @asio|1373054320.609284|>510|ec=system:0,bytes_transferred=404 [2013-07-05 15:58:40 - Thread 7fae57e3f700]: Received packet headers (638 bytes) - 734ms elapsed 

Between async_accept and async_receive there are more than 700 milliseconds. In the code, it goes from this block (almost directly from "HTTP Server 2" http://www.boost.org/doc/libs/1_54_0/doc/html/boost_asio/examples/cpp03_examples.html - server.cpp and connection. cpp):

 new_connection_->start(); new_connection_.reset(new connection( io_service_pool_.get_io_service() )); acceptor_.async_accept( new_connection_->socket(), boost::bind( &server::handle_accept, this, boost::asio::placeholders::error ) ); 

and from the beginning () to:

 void connection::start() { boost::asio::async_read_until( socket_, response_, "\r\n\r\n", boost::bind( &connection::handle_read_headers, shared_from_this(), boost::asio::placeholders::error, boost::asio::placeholders::bytes_transferred ) ); } 

and when handle_read_headers () is called, 700 ms has passed.

Does anyone have any ideas? I am completely lost.

Many thanks!

Answer 1

Let's look at the handler log

 [2013-07-05 15:58:39 - Thread 7fae57e3f700]: Incoming connection (0ms elapsed) @asio|1373054319.874916|506*508|[e-mail]_receive @asio|1373054319.874963|506*509|[e-mail]_accept @asio|1373054319.875008|<506| @asio|1373054320.609088|>508|ec=system:0,bytes_transferred=512 @asio|1373054320.609233|508*510|[e-mail]_receive @asio|1373054320.609264|<508| @asio|1373054320.609284|>510|ec=system:0,bytes_transferred=404 [2013-07-05 15:58:40 - Thread 7fae57e3f700]: Received packet headers (638 bytes) - 734ms elapsed 

From the log we can see that async_receive is called twice: first (# 508) 734ms is called after the handler is configured (# 506). Now the second async_receive is called (# 510) 53 microseconds after setting up the handler (# 508). That is, the call to the second handler was fired quickly because the data (these 404 bytes) was already ready on the TCP stack.

Conclusion : this is not a delay in calling a handler, this is a transport delay. There is probably a problem with the provider or the balancer, or maybe Google really does not want to bother you with requests and sets up delays.

UPD: I think you can check it with tcpdump

PS I do not like the io_service_pool_ implementation from the example of HTTP server 2. This may cause some problems, but I think this is not the current case.