OpenResty API网关延迟异常增高问题排查

请求异常失败及延迟抖动问题排查

问题背景

由于在项目初建时没有比较适合的可以方便部署于 k8s 下的 GRPC 网关，我们的项目中使用 OpenResty 搭建了一套GRPC的API-Gateway，用于接入现有的模调、鉴权等功能。同时扩展了限流、配置热加载等特性。
随着业务量的上涨，在某天开始陆续发现接入的请求延迟会在某些时刻有所抖动，伴随着一段时间内的失败率陡增，持续时间不定，也没有与请求量表现出强相关的特征(问题出现的时刻不一定是业务最高峰的时刻)。

问题初步排查

从模掉上观察，经过简单的排查后，确定问题出现在鉴权链路上。
鉴权链路走 http 请求，已设置好超时时间(3s)，但从模调上反映出普遍有10秒、20秒、最长60秒的调用时间。
http 请求使用的 resty.http 库，是一个经过 OpenResty 官方认证并广泛被生产环境采用的库，经过简单的验证，排除了是 http 超时设置无效的可能，这个超时不仅有效，还特别的准...
细看整个鉴权链路，从网关接到请求到发送到鉴权服务器，后半段(到鉴权服务器后)有完整的模调记录，可以排除是这一段的问题，那问题只能出现在鉴权的前半段，即发送出鉴权请求之前。此时 http 超时的可能又被排除，那其实只剩下唯一一种，也是最容易被忽略的一种可能，即 DNS 解析耗时增加！ 明确这个思路后，虽然没有排查出为什么某些请求 DNS 解析耗时增加会导致大量的其他请求失败，而且会 hold 住这个请求长达60s，但是还是本着先治病的原则准备了一个备用版本用于应对突发情况。

问题详细排查

有了之前的经验，对网关的 DNS 解析部分进行了修改，替换了之前的 DNS 解析函数(c实现)为 resty.dns 的实现，给 DNS 解析加上了本地缓存和模调。
在又一个某天的深夜，问题再次出现并迅速恶化，经过又一次长达半小时的简单排查后，发布了备用的修复版本，问题迅速得到解决，这从一个侧面上印证了之前推断的 DNS 解析导致的异常这个表象原因是正确的。
重新 review 之前的 DNS 解析部分，结合各方的文档，在之前排查的基础上推断出了问题所在:

• 之前的实现中，使用c函数调用 gethostbyname 实现了 DNS 的解析，这是问题的根本原因！ 因为对这个函数的调用是同步阻塞的，会阻塞住当前的请求，导致OpenResty没法调度到其他请求上，从而使得部分请求的问题恶化到了某一段时间内的请求问题。
  
• 另一方面，由于之前的代码实现上，没有考虑到实际上后端的服务器的IP是不变的(k8s的service ip)，实际上不需要每一次请求都去实际的解析，可以将结果缓存起来，导致了大量的无效请求给到了 DNS 服务器，CoreDNS在这种情况下表现不够好，对部分请求没有进行及时的响应。
  
• 同时，由于没有对默认的超时时间进行设置(linux默认5s超时，重试三次共15s)，导致在异常情况下没有及时的放弃掉请求，使得整个问题急速恶化。

总结

• 模调一定要覆盖全面，粒度一定要细，否则在排查问题时会抓瞎
• 即使初步排查的原因看起来多么的不靠谱，也要对自己的排查抱有一定的信心。毕竟排除了错误答案剩下的虽然可能也是错误答案，但正确答案的几率已经很大了。
• DNS 解析并不靠谱也不轻量，并且由于linux默认的设置过于的宽容加k8s的特性(解析一个地址需要搜索三个search域+本身共四次，在默认情况下最大耗时 \(5 \times 3 \times 4 = 60\) 秒)，可能会导致在这个看起来轻量的操作上吃大亏。
• OpenResty 的使用中一定要注意涉及到同步阻塞操作、c函数调用时的影响评估。