C++ Boost.ASIO async_read_until 慢

Question

我遇到了一个不寻常的问题。我有一个 C++ Boost.ASIO 网络服务器，为了处理传入的请求，我正在使用以下代码:

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
    )
);

(其中“socket_”是我的 boost::asio::ip::tcp::socket，“response_”是 boost::asio::streambuf)

我试图只获取请求的 header ，然后我执行第二个 async_read_until，transfer_exactly 匹配从请求 header 解析的“Content-Length”。问题是上面的代码需要 100-900 毫秒才能在非常现代的服务器上返回(从那个读取 block ，直到调用 handle_read_headers())。传入请求如下所示:

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)

header 似乎以\r\n\r\n 结尾，它确实在一直读取到 EOF 之前触发了 handle_read_headers() 函数(因此它没有读取整个页面)——它实际上正在跳闸正则表达式。这些请求来自 Google，因此我非常有信心他们不会延迟。

关于为什么需要这么长时间才能返回，有什么我可以忽略的吗？我可能错过了 aync_read_until 的任何其他捕获？

谢谢!

编辑/更新:好吧，现在我很困惑。在尝试 megabyte 的建议时，我从 streambuf 切换到字符数组(运气不好)，然后我重构了我的代码以使用 async_read_some 而不是 async_read_until，并且只是手动扫描分隔符。我还将所有操作系统变量 (sysctrl.conf) 重置为默认值(以缩小可能性)。不幸的是，我仍然看到以下代码使用相同的传入 POST 请求调用 handle_read() 时有 100-900 毫秒的延迟:

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
    )
);

response_ 现在在哪里:

boost::array<char, 4096> response_;

无济于事(同样的 100-900 毫秒延迟)。这不可能是正常的——有什么想法吗？

编辑2:根据 Rhashimoto 的建议，我启用了处理程序跟踪并在日志中发现了这个奇怪的地方:

[2013-07-05 15:58:39 - Thread 7fae57e3f700]: Incoming connection (0ms elapsed)
@asio|1373054319.874916|506*508|socket@0x7fae50004f98.async_receive
@asio|1373054319.874963|506*509|socket@0x7fffd40fed68.async_accept
@asio|1373054319.875008|<506|
@asio|1373054320.609088|>508|ec=system:0,bytes_transferred=512
@asio|1373054320.609233|508*510|socket@0x7fae50004f98.async_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

async_accept 和 async_receive 之间有超过 700 毫秒的间隔。在代码中，它来自此 block (实际上直接来自 http://www.boost.org/doc/libs/1_54_0/doc/html/boost_asio/examples/cpp03_examples.html 的“HTTP 服务器 2”- server.cpp 和 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
        )
);

从 start() 到:

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
        )
    );
}

当调用 handle_read_headers() 时，已经过了 700 毫秒。

有人有什么想法吗？我完全迷路了。

非常感谢!

Answer 1

让我们看看处理程序日志

[2013-07-05 15:58:39 - Thread 7fae57e3f700]: Incoming connection (0ms elapsed)
@asio|1373054319.874916|506*508|socket@0x7fae50004f98.async_receive
@asio|1373054319.874963|506*509|socket@0x7fffd40fed68.async_accept
@asio|1373054319.875008|<506|
@asio|1373054320.609088|>508|ec=system:0,bytes_transferred=512
@asio|1373054320.609233|508*510|socket@0x7fae50004f98.async_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

从日志中我们可以看到 async_receive 被调用了两次:第一次被调用(#508)在处理程序设置(#506)之后的 734 毫秒。现在，第二个 async_receive 在处理程序设置 (#508) 后 53 微秒被调用 (#510)。就是这样，第二个处理程序调用的速度非常快，因为数据(那 404 个字节)已经在 TCP 堆栈中准备好了。

结论:这不是处理程序调用延迟，而是传输延迟。可能是 ISP 或平衡器出了问题，或者 Google 真的不想用请求和设置延迟来打扰您。

UPD:我想你可以用 tcpdump

检查一下

附言我不喜欢 HTTP 服务器 2 示例中的 io_service_pool_ 实现。这也会导致一些问题，但我认为这不是当前的情况。