I'm having an unusual issue. I have a C++ Boost.ASIO web server, and to handle incoming requests I'm using this code:
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 a boost::asio::streambuf)
I'm trying to just grab the headers of the request, then I later do a second async_read_until with transfer_exactly matching the "Content-Length" that was parsed from the request header. The problem is that above code is taking 100-900ms to return on a very modern server (From that read block, until handle_read_headers() is called). The incoming request looks like:
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 terminated with a \r\n\r\n, and it does trigger the handle_read_headers() function before reading all the way to EOF (so it's not reading the whole page) - it actually is tripping the regex. And these requests are coming from Google, so I'm quite confident it's not lag on their end.
Is there anything I could be overlooking on why it's taking so long to return? Any other catches with aync_read_until I might have missed?
Thanks!
EDIT/UPDATE: Okay, now I'm very confused. In trying megabyte's suggestion, I switched from a streambuf to a character array (no luck), then I refactored my code to use async_read_some rather than async_read_until, and just scan for the delimited manually. I also reset all OS variables (sysctrl.conf) to bone stock default (to narrow down possibilities). Unfortunately I'm still seeing 100-900ms 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 (same 100-900ms delays). There's no way this is normal - any thoughts?
EDIT2: Per the recommendation of Rhashimoto, I enabled handler tracking and found this oddity in the log:
[2013-07-05 15:58:39 - Thread 7fae57e3f700]: Incoming connection (0ms elapsed)
@asio|1373054319.874916|506*508|[email protected]_receive
@asio|1373054319.874963|506*509|[email protected]_accept
@asio|1373054319.875008|<506|
@asio|1373054320.609088|>508|ec=system:0,bytes_transferred=512
@asio|1373054320.609233|508*510|[email protected]_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
There are over 700 milliseconds between the async_accept and async_receive. In the code, it goes from this block (virtually straight from the "HTTP Server 2" of 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 start() 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, 700ms have passed.
Does anyone have ANY ideas? I'm completely lost.
Thanks so much!
Lets look at the handlers log
[2013-07-05 15:58:39 - Thread 7fae57e3f700]: Incoming connection (0ms elapsed)
@asio|1373054319.874916|506*508|[email protected]_receive
@asio|1373054319.874963|506*509|[email protected]_accept
@asio|1373054319.875008|<506|
@asio|1373054320.609088|>508|ec=system:0,bytes_transferred=512
@asio|1373054320.609233|508*510|[email protected]_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 log we can see async_receive
is called twice: first is called(#508) 734ms after handler setup(#506). Now, second async_receive
is called(#510) 53 microseconds after handler setup(#508). Thats it, second handler call was fired blasingly fast because the data (those 404 bytes) was already ready in TCP stack.
Conclusion: it is not a handler call delay, it is transport delay. Probably trouble with the ISP or a balancer, or maybe Google really dont want to bother you with requests and setting up delays.
UPD: I think you can check this with tcpdump
P.S. I dont like io_service_pool_
implementation from HTTP server 2 example. This can cause some problems too, but i think its not current case.
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With