异步模型的脆折风险-从一次Node服务故障谈起

见贤思齐

异步模型的脆折风险-从一次 Node 服务故障谈起 异步模型的脆折风险-从一次 Node 服务故障谈起 姚泽源 贝壳产品技术 贝壳产品技术 “贝壳产品技术公众号”作为贝壳官方产品技术号，致力打造贝壳产品、技术干货分享平台，面向互联网/O2O开发/产品从业者，每周推送优质产品技术文章、技术沙龙活动及招聘信息等。欢迎大家关注我们。 242篇内容 2021年07月01日 17:32 当抵达 Node 服务的请求数达到理论最高吞吐量时, 单个请求的响应时间和所有请求平均响应时间会是什么关系？答: 所有请求平均响应时间一切如常, 单个请求响应时间突然飞涨为什么是这样？周末接到三次报警, 线上 Node 服务突然出现大量接口 30 秒超时. 但每次都是刚连上 vpn, 报警就消失. 期间没有上线操作, 流量不大且平稳, 报错的是普通接口逻辑流程正常, 99.5%的请求响应时间在 100ms 以内, 服务器 CPU 使用率稳定在 30% 且无波动, 内存使用无波动, 硬盘读写无波动. 但就是突然几千个请求响超时, 故障期间连服务器上的静态资源文件也拉不下来, 然后自动恢复正常...why？排查步骤问题表现需要先确认问题表现, 在这次报警中, 问题表现如下服务短时间内出现大量请求超时, 30 秒内无响应, 504 报错在服务故障期间(排查期间正好赶上一次故障), 访问服务器上的静态资源文件(只需要服务进程进行简单读取磁盘)也没有响应, 说明服务进程处于"卡死"状态代码发版最近 7 天无发版操作通过查询日志, 报错前 3 天内没有发生过重启, 报错期间也没有进程重启事件历史报警5 天前晚 7 点左右也有一次 504 报警, 1 分钟后解除, 当时排查后认为是网络抖动, 没有注意服务器服务器 CPU 使用率无波动, 稳定在 30% 左右服务进程 CPU 使用率大致在 16~25% 之间磁盘 io 无波动内存使用无波动, 且有较大冗余空间请求流量最高 QPS 67, 持续 1 秒, 随后恢复正常平均每分钟有一次 QPS 为 20 的并发, 但只维持 1 秒日常 QPS 6~10故障期间(11:05:00~11:20:00)接口响应时间每分钟有一批接口响应时间在 1~3 秒, 只持续 1 秒故障期间接口响应时间快速升高, 然后达到 30s, 持续 60s 后快速下降回正常状态日常接口响应时间 40~50ms故障期间(11:05:00~11:20:00)线上服务器日志服务器本身只有 200 的日志记录, 通过 grep 遍历搜索, 没有 504 超时记录.504 超时记录只出现在 Nginx 日志中看到的记录响应耗时大部分为 0, 偶有 40~100 的情况服务器情况线上三台服务器几乎同步发生异常, 然后同步恢复日常接口响应时间每天大约有 1000 个请求响应时间在 300ms 以上, 但都是集中出现一阵后消失, 没有规律原始请求日志请求时间响应时长请求接口09:20:250.091/api/xxx/list09:20:250.036/api/xxx/list09:20:250.040/api/xxx/list09:20:250.036/api/xxx/list09:20:250.045/api/xxx/list09:20:250.054/api/xxx/list09:20:250.151/api/xxx/list09:20:250.036/api/xxx/list09:20:250.106/api/xxx/list09:20:260.046/api/xxx/list09:20:260.061/api/xxx/list09:20:260.056/api/xxx/list09:20:260.042/api/xxx/list09:20:282.177/api/xxx/list09:20:280.811/api/xxx/list09:20:282.377/api/xxx/list09:20:280.929/api/xxx/list09:20:292.916/api/xxx/list09:20:302.735/api/xxx/list09:20:4014.397/api/xxx/list09:20:4619.809/api/xxx/list09:20:461.723/api/xxx/list09:20:4821.274/api/xxx/list09:20:481.063/api/xxx/list09:20:493.777/api/xxx/list09:20:4922.506/api/xxx/list09:20:4921.235/api/xxx/list09:20:4922.760/api/xxx/list09:20:4922.239/api/xxx/list09:20:4922.534/api/xxx/list09:20:5021.391/api/xxx/list09:20:5014.277/api/xxx/list09:20:5021.354/api/xxx/list09:20:5015.353/api/xxx/list09:20:5022.900/api/xxx/list09:20:5020.077/api/xxx/list09:20:5020.772/api/xxx/list09:20:5010.949/api/xxx/list09:20:5016.745/api/xxx/list09:20:5022.802/api/xxx/list09:20:5022.125/api/xxx/list09:20:5630.000/api/xxx/list09:20:5730.001/api/xxx/list09:20:5730.001/api/xxx/list09:20:5830.000/api/xxx/list09:20:5930.000/api/xxx/list09:20:5930.000/api/xxx/list09:20:5930.001/api/xxx/list09:20:5930.000/api/xxx/list代码问题？对于线上服务故障, 第一反应就是检查代码本身是否有问题. 由于是新业务, 排查日志发现 90%的请求都在访问/api/xxx/list, 所以检查起来比较简单. 经审核, 代码没有问题, 也没有明显存在风险的点. 考虑到如果代码真有问题, 那之前一定会有报错记录. 于是翻查请求历史日志, 发现请求都能在 50ms 内正常响应, 说明代码本身确实没毛病.MySQL 慢查询 / 远程服务无响应？排除代码本身问题后, 紧接着需要考虑的是 MySQL 集群故障/ 慢查询的可能. 如果 MySQL 调用超时, 那 await 等待远程接口响应的 Node 服务自然也会超时.但这个想法很快被排除掉了, 主要是两个原因:假设是 MySQL 集群故障, 查询无响应. 那么同一时间段内, 依赖 MySQL 集群的其他服务必然也会报错, 不会只有我们一个服务故障. 但现实是故障期间只有我们的服务出现了 504 超时错误.如果请求卡在等待远程调用中, 由于 Node 使用的是异步模型, 服务进程并不会阻塞在等待接口响应上. 此时其他接口/静态文件(不依赖外部接口)应该可以继续访问. 但在问题描述中可以看到, 故障期间静态文件也无法访问. 所以问题更像是整个服务进程失去了响应, 而非 MySQL 集群有问题.MySQL 问题排除.服务器问题？有没有可能是服务器本身挂了呢？ 但这也没可能：故障期间服务器上其他应用响应正常位于三台服务器上的进程几乎同步故障, 说明是三台机器间共有的部分出错, 不像是单台服务器故障服务进程本身问题代码没有问题, MySQL 没有问题, 服务器也没有问题. 那只能是服务进程本身出了毛病.通过故障期间每秒接口响应数(QPS)+接口响应时长合并图可以看到, 接口响应时长和 QPS 明显相关, 当 QPS 变大时, 接口响应时长一般都会随之增加, 而增大到极值(11:17~11:19), 响应时长突破 30s, 对应的就是线上 Nginx 504 报错. 但是, 服务器压力大导致接口超时可以理解, 但为什么静态资源请求也跟着超时？ 为什么会这样？抖动期间QPS+接口响应时长合并数据异步模型的脆折风险所有这些, 需要从 io 请求处理模型说起.图：理想同步io模型传统 io 模型是串行模式, 一个一个处理请求. 可以看到, 处理 6 个请求时, 总耗时 1200ms. 大量时间浪费在 io 等待中.图：理想异步io处理模型为了避免浪费, 提升服务器吞吐率, 异步 io 模型应运而生. 异步的基本思路是时间复用, 在等待 io 的期间让 CPU 去处理其他请求, 从而充分利用计算资源. 可以看到, 在理想情况下, 异步模型处理 6 个请求只需要 650ms.不过, 这是理想情况. 在实际应用中, 请求的计算部分和 io 等待部分会交织在一起, 由于每个部分消耗时间都不太长, 因此会形成时间片的效果. 只有执行完所有时间片, 一个任务才能执行完成.图：请求模型而当多个请求同时到达 Node 进程时, Node 的任务队列会变成下边这样: 不同请求的回调在任务队列中进行等待执行.图：Node任务队列由于接口响应过程被异步等待被拆分成一个个子任务, 形成了细碎的时间片, 接口的异步处理模型如下图所示. 当多个请求同时到达时, 由于 io 等待+任务队列调度的效果, Node 倾向于在请求间平均分配时间片, 对同一接口同时到达的请求倾向于同时完成. 但可以看出, 即使切换时间片本身需要时间, 导致单个请求响应时长增加, 但因为可以利用 io 等待时间, 异步模型仍然比串行模式要高效.图：实际异步io处理模型那如果待执行的任务没有 io 操作, 是纯计算密集型请求呢？那就会悲剧. 如果是计算密集型请求, 异步模型的处理能力会回落到和串行模型同一水平, 甚至更差: 在串行模式下, 高并发时串行模式至少可以保证前几个接口的正常响应, 后续接口由于等待时间过长才会超时报 504. 但在异步模型下, 由于在各个任务间不断进行调度, 所有任务的完成时间都差不多, 会导致最终没有一个请求可以正常响应, 所有任务一起 504 超时报错如下图所示图：计算密集型异步io处理模型一般认为, web 服务是典型的 io 密集型场景, 大量时间消耗在 MySQL 通信与和其他接口交互中, 所以 Node 的异步模型天然适合用做 web 服务器. 但在特殊场景下, web 服务也会由 io 密集型退化为计算密集型: 当请求数量超过阈值, 请求提供的 io 等待时长不足以完成其他请求的 CPU 操作时, 此时 CPU 就会变成服务的性能瓶颈. 由于所有请求都没有足够的 CPU 资源完成运算, 导致所有请求都无法在可接受时间内响应, 出现服务进程"卡死"的效果.由于这个过程的临界点是待处理请求所需的总CPU处理时长大于待处理请求所需的总IO时长, 所以当问题发生时, 会有类似于钢板脆折的效果. 在临界点以下, 一切安好, 响应时长正常, 看不出有什么问题. 一旦超过临界点, 响应时长快速增加, 然后就是大规模 504 报错, 直到请求量降到临界点以下, 处理完所有挤压请求后, 一切又回归正常.图：并发量过大时的异步io处理模型所以 Node 服务会有一个很特殊的现象: 绝大多数情况下表现正常, 但当并发量比最大容纳值稍微高一点, 所有接口响应速度就会快速抬升(脆折), 但请求量只要降一点, 服务性能又会恢复正常. 整个表现非常反直觉, 但符合异步模型的原理.实践验证说了这么多, 实际测试一下.压测框架使用 koa, 分别用asyncSetTimeoutSleep和asyncCPUSleep模拟 io 密集型和计算密集型请求, 压测工具使用 ApacheBench, 测试命令为ab -c 1/10/100/400 -n 10000 -k 'http://127.0.0.1:3000/', -n指测试总数, 取 10000, -c指每轮测试并发请求数, 分别取 1/10/100/400 进行测试, 测试代码&实验结果如下//测试代码constKoa=require("koa");constapp=newKoa();asyncfunctionasyncSetTimeoutSleep(ms=0){awaitnewPromise((reslove,reject)=>{setTimeout(()=>{reslove(true);},ms);});return;}asyncfunctionasyncCPUSleep(ms=0){awaitnewPromise((reslove,reject)=>{//这里必须使用setTimeout模拟sleep,否则Node会由于没有调度机会,只能按先后顺序处理请求//(接受请求1->处理请求1->响应请求1->接受请求2->处理请求2->响应请求2->...)//此时异步模式降级为串行模式,失去比较意义setTimeout(()=>{//运算150000次在我的机器上正好是1ms,单纯用来模拟CPU密集型操作,没有特别意义for(leti=0;i{//awaitasyncCPUSleep(10);awaitasyncSetTimeoutSleep(10);ctx.body="HelloKoa";});app.listen(3000);计算密集型并发量/响应时长最小值[ms]平均数[ms]中位数[ms]最大值[ms]平均请求响应时间(总时长/总请求数)[ms]总响应时长[s]QPS[次/秒]1711103711.172111.72489.51101010810626410.792107.92092.661003410811097140310.847108.47292.1940010042164437467510.753107.53492.99io 密集型并发量/响应时长最小值[ms]平均数[ms]中位数[ms]最大值[ms]平均请求响应时间(总时长/总请求数)[ms]总响应时长[s]QPS[次/秒]1911111210.614106.13994.221091111141.08610.857921.03100101413430.1441.4426934.204002043351500.1101.0999099.8010003570671300.0860.86111618.10可以看到当并发量为 1 时, 实际为串行模式, 此时请求平均响应时间等于平均请求响应时间, 计算密集型请求和 io 密集型请求吞吐量&平均请求响应时长接近.当并发量增大时异步框架充分利用 io 等待时间进行 CPU 运算, 平均请求响应时间不断缩短, 直到逼近单个请求必要CPU时间随着并发量增大, 在 io 等待时间内(10ms)不足以完成请求, CPU 时间逐渐变为性能瓶颈, 性能表现逐步向计算密集型请求靠近, 体现为请求平均响应时间不断增大换言之, 由于接收请求/给出响应总会消耗 CPU 资源, 只要并发请求量够大, io 密集型总会退化为 CPU 密集型.异步模型没有可供利用的 io 等待时间, 平均请求响应时间等于单个请求必要CPU时间, 因此 平均请求响应时间不变, 异步模式劣化为串行模式同时, 由于框架中的各种 await 等待形成了时间片效果, 导致 Node 会在各个请求间对时间片进行调度, 所有请求接近同时完成, 请求平均响应时间大幅上升需要说明的是, 由于事件驱动的随机性, 这里的调度并不是指公平调度, 先进入的请求大概率先集齐所有时间片完成请求, 但不代表先进入的请求一定先完成对于 计算密集型请求对于 io 密集型请求顺带提一句, 处理计算密集型请求时还有一个特殊情况:如果 CPU 运算为整块代码, 期间没有 await 形成时间片供 Node 调度, 那么会 Node 处理模型劣化为串行模式, 执行过程变为接收请求1->处理响应请求1->接收请求2->处理响应请求2->接收请求3->处理响应请求3...由于所有请求同时发出, 串行处理, 所以请求响应时长会呈递增关系, 如下所示//示例代码constKoa=require("koa");constapp=newKoa();asyncfunctionasyncCPUSleep(ms=0){for(leti=0;i{//由于没有promise返回,这里的await是无效的,不会形成时间片//阻塞式休眠1秒awaitasyncCPUSleep(1000);ctx.body="HelloKoa";});app.listen(3000);//串行模式对应日志第0条请求完成,耗时842毫秒第1条请求完成,耗时1573毫秒第2条请求完成,耗时2275毫秒第3条请求完成,耗时2987毫秒第4条请求完成,耗时3683毫秒第5条请求完成,耗时4396毫秒第7条请求完成,耗时5085毫秒第6条请求完成,耗时5821毫秒第9条请求完成,耗时6535毫秒第11条请求完成,耗时7247毫秒第8条请求完成,耗时7963毫秒第10条请求完成,耗时8671毫秒第12条请求完成,耗时9381毫秒第13条请求完成,耗时10151毫秒第14条请求完成,耗时10852毫秒第15条请求完成,耗时11555毫秒第16条请求完成,耗时12225毫秒第24条请求完成,耗时12996毫秒第23条请求完成,耗时13723毫秒第25条请求完成,耗时14531毫秒第28条请求完成,耗时15235毫秒第22条请求完成,耗时15954毫秒第18条请求完成,耗时16860毫秒第29条请求完成,耗时17906毫秒第21条请求完成,耗时18595毫秒第26条请求完成,耗时19400毫秒第27条请求完成,耗时20333毫秒第17条请求完成,耗时21199毫秒第20条请求完成,耗时22080毫秒第19条请求完成,耗时23064毫秒但如果在处理过程中不断有 await 形成时间片, 可供 Node 调度. 则 Node 服务仍然遵循异步模型规律, 所有请求一起返回(一起超时)constKoa=require("koa");constapp=newKoa();asyncfunctionasyncCPUSleep(ms=0){awaitnewPromise((reslove,reject)=>{setTimeout(()=>{for(leti=0;i{//切片式休眠1秒for(leti=0;i