Laravel使用经验 - 框架压测及结果分析
2016-01-28
环境
服务器:
- anhouse (可对外的测试环境)
压测机:
- 一号机: 办公环境某标机
- 二号机: 某anhouse环境同机房的一台测试机
压测工具：
- AB Test
压测方法：
- 选取某laravel框架实现的service，取其中若干方法分批进行压测，并发数依次从5，10，20，40增加，请求次数约定在1000次。
问题
坑 · 其一
现象
- 慢到令人发指, 和自测结果严重不符
- CPU空闲
- 内存大量剩余
- 网络曲线比搓衣板还平
原因
经运维确认办公室网络限速... 据说限速20Mb, 实测只有10Mb
解决
抛弃压测一号机, 改用同机房的压测二号机进行测试 影响结果包括之前所有的压测结果(hft, esf, overseas, ...)
坑 · 其二
现象
- 低并发表现正常
- 高并发在请求量少的情况下表现正常
- 高并发在请求量大的情况下性能急剧下降
- 查看日志有少部分请求时间达几秒到十几秒
- CPU使用率忽高忽低不稳定
- 有redis连接超时的异常
原因
- 推测redis服务器产生问题导致请求无法及时响应请求, 经运维确认redis服务器iptables对连接数做了限制
- 没有执行fastcgi_finish_request()导致整个请求执行完之后才发送响应, 配合redis超时导致整个响应迟缓
解决
- 运维放开压测用的redis连接数限制
- 补上没有执行的
fastcgi_finish_request
这里说明下，我们的框架会在请求结束时有一个动作就是将所有这次请求产生的日志push到redis中，然后后面会有一个异步读的服务再从redis中读取日志落地到MongoDB，那么问题来了：如果一次请求的日志很大的话，再加上redis本身的连接数限制，是非常有可能让请求响应卡在这一步“写日志”上的，此时就需要用到
fastcgi_finish_request这个方法，这个方法在PHP手册上介绍是，可以将请求响应返回给客户端，但是这个PHP进程还存在，直到把后续占用时间的事情（如写日志等）处理完成。
坑 · 其三
现象
- 高并发持续请求, 大约 15,000 ~ 30,000 次请求时redis以及mysql同时报cannot assign requested address
原因
考虑到redis和mysql同时报出相同错误, 又redis和mysql不在同一台机器上 推测为压测服务器本身问题 查找相关报错说明, 确认原因为TCP连接结束后进入TIME_WAIT状态(30秒+), 进而导致本机端口资源耗尽而无法分配新的端口
当FIN N没有收到ACK N+1时会重新发送一次 所以为了避免新连接接收到老连接的数据而混淆, 需要等待2倍的报文生存时间才能结束TIME_WAIT状态
解决
与运维沟通, 修改压测机上tcp_tw_reuse为1, 使得允许系统重用TIME_WAIT状态下的socket
测试结果
平均响应时间: 总时间 / 总请求数 * 并发数 (越小越好)
吞吐量: 每秒可以执行的请求数 (越大越好)
空闲CPU: 处于空闲状态的CPU资源 (越大越好)
HwHouseController@index (7次sql)
未优化
| 并发数 | 请求次数 | 平均响应时间(ms) ↓ | 吞吐量(sec) ↑ | 空闲cpu(%) ↑ |
|---|---|---|---|---|
| 5 | 10000 | 33.408 | 149.66 | 79 |
| 10 | 10000 | 55.84 | 179.08 | 53 |
| 20 | 10000 | 60.119 | 332.67 | 20 |
| 40 | 10000 | 88.35 | 452.74 | 4 |
已优化
| 并发数 | 请求次数 | 平均响应时间(ms) ↓ | 吞吐量(sec) ↑ | 空闲cpu(%) ↑ |
|---|---|---|---|---|
| 5 | 10000 | 31.052 | 161.02 | 82 |
| 10 | 10000 | 52.17 | 191.68 | 60 |
| 20 | 10000 | 48.935 | 408.7 | 27 |
| 40 | 10000 | 69.8 | 573.06 | 7 |
HwHouseController@show (6次sql)
未优化
| 并发数 | 请求次数 | 平均响应时间(ms) ↓ | 吞吐量(sec) ↑ | 空闲cpu(%) ↑ |
|---|---|---|---|---|
| 5 | 10000 | 26.242 | 190.53 | 77 |
| 10 | 10000 | 39.544 | 252.88 | 52 |
| 20 | 10000 | 48.316 | 413.94 | 18 |
| 40 | 10000 | 71.379 | 560.39 | 4 |
已优化
| 并发数 | 请求次数 | 平均响应时间(ms) ↓ | 吞吐量(sec) ↑ | 空闲cpu(%) ↑ |
|---|---|---|---|---|
| 5 | 10000 | 23.176 | 215.74 | 82 |
| 10 | 10000 | 36.103 | 276.99 | 60 |
| 20 | 10000 | 37.726 | 530.14 | 26 |
| 40 | 10000 | 53.166 | 752.36 | 7 |
HwContentController@index (2次sql)
未优化
| 并发数 | 请求次数 | 平均响应时间(ms) ↓ | 吞吐量(sec) ↑ | 空闲cpu(%) ↑ |
|---|---|---|---|---|
| 5 | 10000 | 19.675 | 254.13 | 73 |
| 10 | 10000 | 30.951 | 323.09 | 45 |
| 20 | 10000 | 33.475 | 597.47 | 13 |
| 40 | 10000 | 60.811 | 657.77 | 3 |
已优化
| 并发数 | 请求次数 | 平均响应时间(ms) ↓ | 吞吐量(sec) ↑ | 空闲cpu(%) ↑ |
|---|---|---|---|---|
| 5 | 10000 | 16.038 | 311.76 | 80 |
| 10 | 10000 | 26.546 | 376.71 | 54 |
| 20 | 10000 | 29.389 | 680.53 | 25 |
| 40 | 10000 | 41.615 | 961.2 | 8 |
HwContentController@show (1次sql)
未优化
| 并发数 | 请求次数 | 平均响应时间(ms) ↓ | 吞吐量(sec) ↑ | 空闲cpu(%) ↑ |
|---|---|---|---|---|
| 5 | 10000 | 14.882 | 335.98 | 70 |
| 10 | 10000 | 22.836 | 437.91 | 42 |
| 20 | 10000 | 26.786 | 746.65 | 11 |
| 40 | 10000 | 50.126 | 797.98 | 2 |
已优化
| 并发数 | 请求次数 | 平均响应时间(ms) ↓ | 吞吐量(sec) ↑ | 空闲cpu(%) ↑ |
|---|---|---|---|---|
| 5 | 10000 | 13.076 | 382.39 | 77 |
| 10 | 10000 | 20.275 | 493.22 | 52 |
| 20 | 10000 | 23.206 | 861.85 | 23 |
| 40 | 10000 | 34.078 | 1173.77 | 6 |
持续压测结果 (200并发压测60s)
60秒内当请求次数达到最大限制50000时, 括号中为达到该次数时所消耗的时间
| 接口 | 请求次数 | 平均响应时间(ms) ↓ | 吞吐量(sec) ↑ |
|---|---|---|---|
| HwHouseController@index (未优化) | 29613 | 405.235 | 493.54 |
| HwHouseController@index (已优化) | 35858 | 334.665 | 597.61 |
| HwHouseController@show (未优化) | 36193 | 331.607 | 603.12 |
| HwHouseController@show (已优化) | 50000 (57.313) | 229.252 | 872.40 |
| HwContentController@index (未优化) | 41965 | 286.004 | 699.29 |
| HwContentController@index (已优化) | 50000 (45.482) | 181.930 | 1099.32 |
| HwContentController@show (未优化) | 50000 (59.295) | 237.182 | 843.23 |
| HwContentController@show (已优化) | 50000 (35.520) | 142.081 | 1407.65 |
总结
测试使用内网机器排除外部网络影响
- 包括网络延迟, 带宽限制等
测试时应检查CPU, 内存, 网络是否表现怪异
- CPU在占用到本次测试的最大值后 应该 保持在稳定状态直到测试结束
- 逐渐提高压测强度当CPU占用达100%时成为瓶颈将影响测试后续结果
- 逐渐提高压测强度当内存占用达100%时成为瓶颈将影响测试后续结果
- 网络吞吐量随测试强度变化而发生变化, 不应该 在不同测试中表现出完全相似的值
检查错误日志看是否有错误信息生成
redis报错是由日志服务链接redis导致的, 而日志服务是在响应发送之后才执行
而ab的错误判断是根据输出的字节数是否发生改变
结果就是ab上无失败请求而错误日志中有异常记录
压测时需要有足够的测试量使得能得出一个稳定状态下的测试结果
平均响应时间根据 总时间 / 请求总数 * 并发数 计算得出
样本量少的情况测试结束快单个请求的响应延迟会极大拖慢整次测试的平均响应时间
以及在少量请求的情况下很可能无法发现 坑 · 其三 中的问题
附
办公室网络压测结果
- 流量限制
- 请求量太少导致外部因素对结果影响大
HwHouseController@index (7次sql)
| 并发数 | 请求次数 | 平均响应时间(ms) ↓ | 吞吐量(sec) ↑ | 流量(KB/s) |
|---|---|---|---|---|
| 10 | 1000 | 75 | 111.36 | 804.95 |
| 20 | 1000 | 121 | 142.63 | 1031.03 |
| 25 | 1000 | 119 | 117.52 | 849.51 |
| 40 | 1000 | 230 | 140.67 | 1016.81 |
HwHouseController@show (6次sql)
| 并发数 | 请求次数 | 平均响应时间(ms) ↓ | 吞吐量(sec) ↑ | 流量(KB/s) |
|---|---|---|---|---|
| 10 | 1000 | 49 | 145.69 | 668.53 |
| 20 | 1000 | 78 | 194.21 | 891.22 |
| 25 | 1000 | 87 | 199.92 | 917.41 |
| 40 | 1000 | 142 | 203.91 | 935.74 |
HwContentController@index (2次sql)
| 并发数 | 请求次数 | 平均响应时间(ms) ↓ | 吞吐量(sec) ↑ | 流量(KB/s) |
|---|---|---|---|---|
| 10 | 1000 | 145 | 63.82 | 1104.69 |
| 20 | 1000 | 286 | 63.10 | 1092.22 |
| 25 | 1000 | 356 | 63.26 | 1094.98 |
| 40 | 1000 | 563 | 61.52 | 1065.00 |
HwContentController@show (1次sql)
| 并发数 | 请求次数 | 平均响应时间(ms) ↓ | 吞吐量(sec) ↑ | 流量(KB/s) |
|---|---|---|---|---|
| 10 | 1000 | 31 | 231.70 | 52.71 |
| 20 | 1000 | 44 | 280.50 | 63.83 |
| 25 | 1000 | 44 | 338.98 | 77.13 |
| 40 | 1000 | 56 | 396.35 | 90.19 |
内网压测结果
- 请求量太少导致外部因素对结果影响大
- redis服务器并发数限制
40并发, 1000次请求
| 接口 | 5并发响应(ms) ↓ | 10并发响应(ms) ↓ | 20并发响应(ms) ↓ | 40并发响应(ms) ↓ |
|---|---|---|---|---|
| HwHouseController@index (未优化) | 46.84 | 55.94 | 77.05 | 111.28 |
| HwHouseController@index (已优化) | 38.92 | 44.78 | 61.65 | 88.63 |
| HwHouseController@show (未优化) | 38.63 | 64.42 | 64.23 | 90.77 |
| HwHouseController@show (已优化) | 30.39 | 37.00 | 51.86 | 73.40 |
| HwContentController@index (未优化) | 35.96 | 52.70 | 58.67 | 78.85 |
| HwContentController@index (已优化) | 23.65 | 35.80 | 38.76 | 60.14 |
| HwContentController@show (未优化) | 31.75 | 41.97 | 44.27 | 64.81 |
| HwContentController@show (已优化) | 22.10 | 28.39 | 30.99 | 49.92 |