DEBUG_LOG.md

问题1

问题描述

使用wrk进行压力测试，发现Avg Req/Sec只有10^2数量级，显然不符合预期。请求返回的Avg Latency 也在40ms左右，在单机测试的环境下，这也是很长的响应时间了。

下面是wrk的测试报告：

$ wrk -t5 -c10 -d10s http://localhost:8888/ -vvv
wrk  [epoll] Copyright (C) 2012 Will Glozer
wrk  [epoll] Copyright (C) 2012 Will Glozer
wrk  [epoll] Copyright (C) 2012 Will Glozer
Running 10s test @ http://localhost:8888/
  5 threads and 10 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    43.72ms    3.16ms  49.97ms   99.21%
    Req/Sec    45.68      6.97    60.00     88.00%
  2284 requests in 10.01s, 333.74KB read
Requests/sec:    228.12
Transfer/sec:     33.33KB

Debug记录

一开始猜测是在某个函数上开销比较大，但是函数太多，具体到某个函数又不容易定位。于是想起可以用on-cpu 火焰图分析函数执行耗时。

针对是否使用http keep-alive选项，对lotos使用两种模式的压力测试。

• ab版本

  ab版本不加keep-alive，纯http1.0模式，得到

• wrk版本

  采用http/1.1协议，支持keep-alive，得到

ab版本的火焰图很符合预期，每次都会建立、断开tcp连接，请求、回复的handler占有的比重也很正常，总之是个很漂亮的火焰图😉。

相比ab版本，发现wrk版本在epoll_wait上等待较多，cpu的采样点也少得可怜，可以大胆猜测应该是在某处IO上阻塞了。

我给lotos的主事件循环中加入了一些调试信息，采用curl命令发起keep-alive请求，命令如下

curl localhost:8000 localhost:8000 -vvv

命令的返回如下：

$ curl localhost:8888 -o /dev/null localhost:8888 -o /dev/null  -vvv
* Rebuilt URL to: localhost:8888/
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 -