nghttp2-asio服务端epoll_pwait/recvfrom性能瓶颈排查

• 基于tatsuhiro-t公开的nghttp2 asio示例代码，整理了一份简化版HTTP/2服务端代码用于观测疑似性能瓶颈，初步怀疑瓶颈来自Boost.Asio自身限制，或是nghttp2的Asio封装层底层接口使用逻辑存在缺陷。
• 简化版代码移除了原示例的工作线程队列结构，测试已确认问题不在业务逻辑层，而是出在epoll/recvfrom事件循环中：日志显示Boost.Asio事件循环始终无法将待处理任务充分派发给工作线程，同一时间点最多仅有1~2个线程处于实际工作状态，其余工作线程长期空闲。
• 简化服务端逻辑仅返回200状态码与响应体done，curl验证效果如下：

curl --http2-prior-knowledge -i http://localhost:3000
HTTP/2 200
date: Sun, 03 Jul 2022 21:13:39 GMT

done

编译依赖版本 #

nghttp2 version 1.47.0
boost version   1.76.0

压测基准表现 #

代码调整点：将服务端工作线程数硬编码为1（该调整不影响测试结论，压测时h2load仅指定1个客户端连接，参数为-c1）

• 无请求体场景：QPS可达约12.8万

h2load -n 1000 -c1 -m20 http://localhost:3000/
starting benchmark...
spawning thread #0: 1 total client(s). 1000 total requests
Application protocol: h2c
progress: 10% done
...
progress: 100% done

finished in 7.80ms, 128155.84 req/s, 2.94MB/s
requests: 1000 total, 1000 started, 1000 done, 1000 succeeded, 0 failed, 0 errored, 0 timeout
status codes: 1000 2xx, 0 3xx, 0 4xx, 0 5xx
traffic: 23.48KB (24047) total, 1.98KB (2023) headers (space savings 95.30%), 3.91KB (4000) data
                     min         max         mean         sd        +/- sd
time for request:      102us       487us       138us        69us    92.00%
time for connect:       97us        97us        97us         0us   100.00%
time to 1st byte:      361us       361us       361us         0us   100.00%
req/s           :  132097.43   132097.43   132097.43        0.00   100.00%

• 携带请求体场景：性能出现明显下降，且损耗与请求体大小无关
  1. ~22字节小请求体场景，QPS降至约4.2万

h2load -n 1000 -c1 -m20 -d request22b.json http://localhost:3000/
starting benchmark...
spawning thread #0: 1 total client(s). 1000 total requests
Application protocol: h2c
progress: 10% done
...
progress: 100% done

finished in 23.83ms, 41965.67 req/s, 985.50KB/s
requests: 1000 total, 1000 started, 1000 done, 1000 succeeded, 0 failed, 0 errored, 0 timeout
status codes: 1000 2xx, 0 3xx, 0 4xx, 0 5xx
traffic: 23.48KB (24047) total, 1.98KB (2023) headers (space savings 95.30%), 3.91KB (4000) data
                     min         max         mean         sd        +/- sd
time for request:      269us       812us       453us       138us    74.00%
time for connect:      104us       104us       104us         0us   100.00%
time to 1st byte:      734us       734us       734us         0us   100.00%
req/s           :   42444.94    42444.94    42444.94        0.00   100.00%

2. 3K大小请求体场景，QPS约3.6万，与小请求体性能接近

h2load -n 1000 -c1 -m20 -d request3k.json http://localhost:3000/
starting benchmark...
spawning thread #0: 1 total client(s). 1000 total requests
Application protocol: h2c
progress: 10% done
...
progress: 100% done

finished in 27.80ms, 35969.93 req/s, 885.79KB/s
requests: 1000 total, 1000 started, 1000 done, 1000 succeeded, 0 failed, 0 errored, 0 timeout
status codes: 1000 2xx, 0 3xx, 0 4xx, 0 5xx
traffic: 24.63KB (25217) total, 1.98KB (2023) headers (space savings 95.30%), 3.91KB (4000) data
                     min         max         mean         sd        +/- sd
time for request:      126us      5.01ms       528us       507us    94.80%
time for connect:      109us       109us       109us         0us   100.00%
time to 1st byte:      732us       732us       732us         0us   100.00%
req/s           :   36451.56    36451.56    36451.56        0.00   100.00%

两类场景性能对比如下：

无请求体 -> ~132k reqs/s
携带请求体 -> ~40k  reqs/s

问题定位过程 #

使用strace追踪epoll_pwait、recvfrom、sendto三类系统调用，执行命令：

strace -e epoll_pwait,recvfrom,sendto -tt -T -f -o strace.log ./server

• 3K请求体场景抓包显示：epoll_pwait返回可读事件后，recvfrom调用存在约300微秒延迟，且单次recvfrom最多读取8KB数据，说明内核接收队列存在积压：

21201 21:37:25.835841 epoll_pwait(5, [{EPOLLIN, {u32=531972776, u64=140549041767080}}], 128, 0, NULL, 8) = 1 <0.000020>
21201 21:37:25.835999 sendto(7, "\0\0\2\1\4\0\0\5?\210\276\0\0\2\1\4\0\0\5A\210\276\0\0\2\1\4\0\0\5C\210"..., 360, MSG_NOSIGNAL, NULL, 0) = 360 <0.000030>
21201 21:37:25.836128 recvfrom(7, "878\":13438,\n  \"id28140\":16035,\n "..., 8192, 0, NULL, NULL) = 8192 <0.000020>
// 其余日志片段省略

• 22字节小请求体场景下，虽然recvfrom可一次性读完所有缓存数据（后续调用返回EAGAIN），但epoll事件通知仍存在约300微秒固定延迟。该延迟直接导致增加工作线程数无法提升性能：epoll事件循环本身存在调度空窗，无法及时获取就绪事件，工作线程长期空闲、CPU资源无法充分利用，即使增加客户端并发数，CPU使用率也无明显提升。
• 查阅nghttp2源码发现读逻辑位于asio_server_connection.h第136行的async_read_some回调中，疑似与Boost.Asio async_read_some无法一次性读取所有可用数据的已知问题相关，但未定位到具体根因。

补充验证信息 #

经后续验证，该性能问题仅在VirtualBox虚拟机（通过Vagrant启动Linux guest系统）环境下可复现，宿主机直接运行二进制、同内核Docker环境运行均性能正常。
在Boost.Asio的epoll_reactor实现（boost/asio/detail/impl/epoll_reactor.ipp）与nghttp2的读回调中添加微秒级时间戳打印，日志显示当单次recvfrom读取字节数不足8KB时，epoll_wait会出现约300微秒的等待空窗，与strace观测结果一致：

USECS ENTERING socket_.async_read_some LAMBDA ARGUMENT: 1657370015373265, bytes transferred: 8192
USECS BEFORE deadline_.expires_from_now: 1657370015373274
USECS AFTER deadline_.expires_from_now: 1657370015373278
USECS BEFORE reactor_op::status status = op->perform(): 1657370015373279
USECS ONCE EXECUTED reactor_op::status status = op->perform(): 1657370015373282
USECS AFTER  scheduler_.post_immediate_completion(op, is_continuation);: 1657370015373285
USECS EXITING socket_.async_read_some LAMBDA ARGUMENT: 1657370015373287
USECS BEFORE epoll_wait(epoll_fd_, events, 128, timeout): 1657370015373288
USECS AFTER epoll_wait(epoll_fd_, events, 128, timeout): 1657370015373290
USECS ENTERING socket_.async_read_some LAMBDA ARGUMENT: 1657370015373295, bytes transferred: 941
USECS BEFORE epoll_wait(epoll_fd_, events, 128, timeout): 1657370015373312
USECS AFTER epoll_wait(epoll_fd_, events, 128, timeout): 1657370015373666
USECS ENTERING socket_.async_read_some LAMBDA ARGUMENT: 1657370015373676, bytes transferred: 8192
...

待咨询问题 #

该VirtualBox环境下性能问题的触发根因与可行优化方案。

内容的提问来源于stack exchange，提问作者eramos