一次生产环境499问题定位

问题现象

某服务(代号 business) 通过网关(代号 gateway) 调用 基础业务服务(代号 service) 时, 会出现 499 报警, 偶现, 出现频率不高

基础信息描述

基础业务信息

• business 业务系统, 超时时间配置 合理 , 符合 gateway 与 service 服务的要求
• gateway 纯代理, 没有业务逻辑, 只是负责流量的分发与调度
• service 提供具体的业务需求的功能, 问题也是出现在这个系统

开发信息

• 开发语言 : Golang
• 机器数量 : 9台
• 机器配置 : 腾讯云虚拟主机, 虚拟主机介绍 , 前一天, 8核16G , 后因怀疑容量问题, 扩容至 16核32G
• 部署方式 : 混布, gateway 与 service 混布在 相同的集群

流量信息

• QPS : 峰值 gateway 与 service 均在 6k 左右
• 总访问量(每天) : gateway 与 service 均在 1.5亿 次左右
• 其他混布服务, 开发语言均为 Golang, 日访问次数在百万级, QPS 300 左右, 忽略不计

异常信息收集

业务报警

• 业务监控 : Redis is slowing , 报警条件为 : redis指令执行耗时 超过20m
• 业务监控 : Mysql is slowing , 报警条件为 : sql 语句执行耗时 超过40ms
• 流量监控 : 在报警时, 可以看到 系统协程数量明显增加,出现请求堆积 , 但是在这个时间段, 没有流量突增

基础组件监控

• redis监控 : 平响 1ms , 且无波动, 在业务系统报警(redis is slowing)期间 , 没有超过 10ms 的请求, 稳定的一批
• mysql 监控 : 平响 20ms , 且无波动, 在业务系统报警(mysql iss lowing)期间, 也很稳定, 并且报警的sql经过分析, 精确 命中索引, 不存在慢查询的可能

代码变更

• 最近没有代码变更, 可以确认, 不是代码变更引入未知 BUG 导致的问题
• 服务引流 : service 服务通过 gateway 接管了一个老服务的流量, 做了流量的切换

信息汇总

• 业务监控的redis耗时, 与redis基础服务的监控 严重不一致
• 业务监控的mysql耗时, 与基础服务mysql的监控 严重不一致
• 服务进行了引流, 相比前一日的流量, 增长约50%

问题分析

代码无变更 , 但是 由于服务引流, 流量上涨 50% , 虽然经过 资源查看 内存 、 CPU 、 带宽 ,资源使用情况均在 安全范围之内 , 但是 第一时间的直觉是, 既然流量上涨了才报警, 那就是 资源不足 呗, 隧迅速以一个机器优雅的姿势, 给运维大佬跪下, 老板, 求 扩容 . 然后, 集群的 9台 服务器, 配置从 8核16G 升级至 16核32G , 一系列骚操作完成之后, 已然后半夜, 流量已经自然下降, 同时偶尔抖一抖报警也没了, 于是, 安心与周公相会, 聊人生, 谈理想去了.

梦中, 周公对我说, 小伙子, 还是太年轻啊, 你觉得你问题解决了么? 倏然梦中惊醒, 东方已泛白.

当晨曦撕破云层, 将光明洒向大地, 沉睡中的的人们陆续苏醒, 开始一天的工作与生活, 我们的服务, 随着人们的醒来, 流量开始 自然上涨 , 是不是猜到接下来要说什么了? 没错, 昨天的问题再次开始, 服务又双叒叕报警了, 相同的内容, 依旧是偶发.

继续分析

在 问题分析 中说过, 在没扩容前 内存 、 CPU 、 带宽 ,资源使用情况均在 安全范围之内 , 扩容后, 资源以及在安全范围之内, 且因为扩容, 各项资源 利用率明显变低 , 这说明什么? 说明什么? 这压根绝不是资源不足导致的问题啊 . 资源 : 莫挨老子,啥都让老子背锅.扩容解决不了问题就麻爪, 你个瓜怂.

这不能服啊, 继续剋它.

目光再次来回报警信息与现象 : 基础服务的运行状态平稳, 但是业务系统记录超时, 那中间的 时差 是如何产生的呢?是否是 连接池 配置的不合理, 当流量增长后, 连接耗尽 , 导致请求处于连接等待状态, 导致 业务系统 与 基础监控之间, 产生了时差? 实际 客户端耗时 = 连接等待时间 + 指令执行时间 , 听起来极度合理, 但是经过确认, 连接池配置合理 , 并不是不合理配置导致的问题. 同时, 如果假定是连接池的问题, 还有另一个事情解释不了 : 在流量自然增长的情况下, 为什么不是问题越来越严重了, 而是低频率偶尔报警一次, 反复恶心你.

问题再次陷入僵局, 开始疯狂掉头发……

漫无头绪, 服务器上四处瞎瞅, 一位同事忽然发现, 服务器上的日志咋这么大啊, 连个服务 gateway + service 每日日志量 100GB+ , 我们的服务器上是有代理的, 会实时将文件日志同步到 日志系统中 , 这其中会消耗很多资源 磁盘IO 、 CPU 、 带宽 这个过程是否会产生问题? 答曰 : 不应该啊, 昨天资源使用情况在安全范围之内, 且扩容之后, 空闲资源更多, 不应该是这个原因. 但是, 此时不能放过任何一个疑点, 我们还是 进行关闭线上日志 的处理.

神奇的事情出现了! 服务再也没有报警, 而且在每天流量的 最峰值 , 服务也没有出现报警, 依旧稳如老狗.罪魁祸首就是 日志采集的agent , 当日志数据量过大时, 他竟然会影响在线服务! 耗尽带宽会导致 redis 与 mysql 查询发生 网络拥塞 , 这也是为什么 业务的监控 和基础服务的监控有 时差 , 结果不一致的原因.

复盘

在整个问题处理过程中, 大家会发现有如下的问题 :

• 在前一天, 机器各项资源指标都充足的情况下, 我们依旧是凭经验, 对集群机器配置进行升级, 刚好赶上深夜, 流量自然下降, 误以为问题已解决
• 开发人员均忽略了一个问题, 服务器上, 除了部署我们的业务服务外, 还有各种自动化采集服务器信息的 agent , 他们也是要消耗各种资源的

在问题定位过程中, 其实某同事还提供了另一个想法, 横向增加集群机器 , 这样能解决问题么? 当然能 , 在流量不变的情况下, 日志体量也不会发生变化, 但是这些日志却分摊到了更多的服务器上, 单服务器日志体量变小, 对带宽的消耗自然降低, 也可以解决 网络拥塞 问题, 但是这种解决方案会存在两个问题 :

• 机器横向扩容, 需要运维同学操作, 且有固定时间窗口, 变更主动权不在我们手里, 在下一个变更的时间窗口到来之前, 我们是走加急通道还是硬挺呢。。。
• 增加机器,意味着 机器成本拉高 ,这可都是钱啊,虽然这是公司的钱….

但是, 这篇文章你能读到这里, 你可能会有一个疑问 : 这不瞎搞么? 前面都讲了, 没扩容前, 资源都是足够的, 扩容之后甚至资源利用率都变低了, 哪里来的网络拥塞? 你没有看错, 我也没写错, 至于这个问题的解释, 请注意一个细节 : 我们用的是 腾讯云的虚拟主机 , 我们严重怀疑 腾讯云服务器超卖 , 虽然我们的服务器标着的是 8核16G / 16核32G , 但是实际可用资源应该 远远达不到这个水平! , 但是这个解释没有实锤, 只能后续继续观察.

结语

任何你觉得稳妥的地方, 都可能是翻车点, 富时修路, 穷时荫庇, 才是比较稳妥.

感谢阅读!