记一次线上故障处理

Posted 2021-03-21 wiswang

前言

下面信息裁剪了一些，有的不确定了就拍脑袋定了，大体情况还是和实际相似。

整体过程

最开始接到告警

一个周六的 9:00 接到钉钉告警A应用线上 499 数量大量增加，

A应用的背景介绍

先说下A应用的背景，我们A应用每天上亿次访问，主要是给别的厂商买接口的，按照各个厂商的调用量收钱，A 应用的实例数有几十个，接入的 nginx 也有 10 个以上，分布在 3 个机房，平均RT时间 15 ms，一般 499 数量多是某个tomcat或者某个机房的资源有问题导致的，这种问题登录我们收集了 nginx 日志的 ELK 平台查看 499 在各个 nginx 还有各个 tomcat 的分布一般就能看出来。
A应用依赖 3 个 RPC(其中一个rpc非常重要)，3 个 redis，日志是A应用自己异步打到 kafka。4 个月前A应用做过一个比较大的改动，A应用的日志之前是自己写磁盘，然后通过 filebeat 收集到 kafka ，后来为了简化运维的复杂度，让A应用自己打到 kafka。当时还做了测试：把A应用的一个线上实例连接 kafka 的 hosts 改成一个根本通不了的，A应用起来以后观察了1周，RT 时间和正常的应用实例是基本一致的，所以判断日志打 kafka 是异步而且 kafka 宕机与否不会影响A应用。

初步诊断

这次问题从这两处都没啥明显异常，499 在各个 nginx 还有各个 tomcat 的分布很均匀，没发现异常。因为突然多出来的 499 一般是由于A应用 RT 时间增长导致的，所以问题就变成了为什么A应用 RT 时间会变长，查看平台发现A应用在周四上午 11:00 就增加了，但是当时增加的不明显，RT时间一直再 20ms 以下，周六上午发现的时候 RT 时间已经超过了 50ms，而且还在增长。
然后检查这周的变更记录，这周由于是要放假，所以变更是就有几个，A 应用是周一发了灰度大约10%，周二发了全量。周二周三观察了两天也没有什么异常。还有一些创建 kafka topic 的变更，还有其他一些和A应用没有关系的发版。

从现有信息分析不出结果，联系开发

9:30 从现在的信息分析不出原因在哪里，所以找到负责这个应用的开发，让开发看看 RT 时间为什么这么长，开发反馈是S服务（那个重要的 RPC）调用时间过长，有好多超过 2s 的，A应用正常的平均RT时间就在 15ms 左右，所以我们一起查看S服务是否正常，决定重启一个机房的所有 S 服务实例，但是重启了之后，RT 时间没有改善。

再仔细分析问题

10:30 然后想起了开发说超过 2s 的有很多请求，判断开发说S服务RT时间长的根据是在所有超过 2s 的请求中，A调用S服务 RT 时间最长的，但是如果超过2s 请求的只占总请求的 1%，或者不到 1%，那么说 S 服务的问题，这个逻辑就是有问题的。所以联系开发询问情况，一问才知道他果然只查看了超过 2s 的请求，其他维度的数据（比如所有RT时间的平均耗时，各个机房的 RT 等等）他就没查过，我觉得这次问题是总的RT时间长，我们并不是要查个别请求 RT 时间长的问题，而是为什么总平均 RT 时间超过平时的5倍。
要推翻是否是 S 服务器 RT 时间长导致A应用 RT 时间的假设，我们查看了这周S服务超过1s请求的个数的曲线图，发现这周超过S服务RT时间超过1s的请求个数曲线没有明显变化。所以排除 S 服务的嫌疑。
之后仔细问了开发 A 应用收到 ELK 日志里面调用各个服务的标识，比如 TT 是总耗时，st 是调用S服务，yt 是调用y服务，我们一一查看了所有A应用依赖的各个服务的RT时间在这周的曲线变化，没有发现哪个服务的 RT 时间是周四开始，周六变的很高的，这个过程还发现了一个比较大的问题就是A应用里记录的总RT时间在这周的曲线图变化不明显，总的 RT 时间这周都是不到 20ms，但是 nginx 记录的RT时间此时已经超过100ms了。
11:30 到此为止，发现应用的日志 RT 时间居然和 nginx 记录的RT时间不一致， nginx 的 upstream_response_time 和 request_time 的变化曲线是一致的，所以肯定是应用的 RT 时间变长了，但是为什么应用记录的RT时间是正常的呢？仔细和开发聊了一下他记录的耗时的计算方法，开发表示这个日志都收了一年多了，日志也一直这么打，这么分析，没有出过什么问题，如果不是开发记录日志的问题，那么还能是 nginx 记录日志的问题。。。

问题影响进一步扩大

13:00 查问题已经查了好几个小时，很多三方合作的厂商都打过电话问具体的请求，现在线上影响正在逐步扩大，RT时间还在增长，这时有人反馈最近这几天 kafka 连接超时，问我们 kafka 是不是有问题，我们 nginx 日志有个监控，如果5分钟内一条 nginx 日志都没有就会有告警，所以我们肯定 kafka 是没有问题的。而且经过之前的测试就算 kafka 挂掉A应用的RT时间也不会收影响。

进一步分析问题

13:30 这时候问题就比较难排查，但是如果说 nginx 记录的RT时间还有应用记录的RT时间都没有问题的话，那么问题还能出在哪里呢？机房网络？三个机房不可能同时出问题吧，而且就算出问题，不可能出问题的就只有A应用，不过还是仔细查了一下，结果还是没有什么发现。nginx 本身的问题？nginx 配置文件检查了这周都没有变动过，nginx 接了很多应用，就应用A有问题，而且所有应用在 nginx 的配置基本一致。

领导介入，A应用回版到4个月前的版本

最开始我们尝试了回版，就回了最近一两次的版本，一般回版就回一个机房的，但是没有效果。领导说要回到A应用不直接打到 kafka 的版本，那个版本是 4 个月前的版本了。不过我觉得用途不大，毕竟当时做个测试，A应用就算连不上 kafka 也不会影响 RT 时间。不过只能先回版看看了，回了一台以后，发现这个tomcat 的 RT 时间回到了 15ms 的水平。然后就把一个机房的A应用都回到了这个版本。观察了 10 分钟后，这个机房A应用的RT时间回到了正常水平。然后就接着把剩下的应用实例都回到了 4 个月前的版本，这时候已经 14:30 了。实在想不出来为什么回到 4 个月前的版本能解决问题。

周日 ELK 告警

周日早上 5:00 起来看手机的时候发现有 ELK 的告警，5 分钟内没有一条日志进入 elasticsearch，赶紧起床解决问题。这个过程持续了 3，4 个小时，最终查出原因是 kafka 一共有 5 个实例，有 3 个实例内存耗尽了，swap 都用了好多，解决方法就是把整个 kafka 集群重启了（因为 3 个实例出了问题，所以一个个重启解决不了问题，还会有 kafka topic partition 的 reassign）。

kafka 问题分析

kafka 的内存也是周四上午 11:00 开始下降的，而周六A应用RT时间过长的问题也是通过应用不直接连 kafka 解决的。所以 kafka 服务器的内存问题是引起A应用RT时间长的根本原因。

kafka 服务器内存泄漏 bug 简述

kafka 服务器的内存问题之所以只有3个实例又内存问题，这个又是一个故事了，简单的说就是光纤网卡驱动的bug导致的内存泄漏，当时这 5 台都有这个 bug，都是 centos 7.3 网卡绑定 mode 4，当时出于对问题的好奇就采取了两种不同的解决方法，有3台是通过解绑 linux 网卡绑定解决的，2台是通过把 centos 7.3 升级到 7.4 解决的。之所以说解决是因为当时观察了一两个月内存使用一直平稳，所以认定是解决了。

kafka 服务器内存泄漏 bug 因何而再次出现？

距离这次事件发生已经一年半多了，之所以周四上午这个 bug 会被触发，初步分析是因为某个应用使用的 kafka 方式改了，虽然要查是哪个具体应用引起的这个问题不难（因为故障的时间点很明确），但是我没有查下去，因为就算查出来是哪个应用，我们也不能做什么，所以这个问题就到此为止了。

事后分析

这个事情过去了两三个月，再问开发为什么应用记录的 RT 时间会和实际有那么大的出入，他们也不知道为什么。不过后来又出现几次这种 java 应用自己记录的 RT 时间和实际的不一致的问题，这个问题的共性就是出问题的时候 java 的 GC 会比较频繁。我分析当时A应用连接 kafka 肯定是耗时比平常多很多，所以同一时间内连接 kafka 的资源消耗肯定比平时多，这样 java 的 GC 可能会比平时多，可能就会引起应用自己记录的RT时间和实际的不一致的问题。但是这个只是猜测，具体对不对只能在今后的遇到的问题中仔细分析了。

整体回顾

本文的整体回顾就以谷歌 SRE 处理问题的几个原则来分析：

初学者心态

当时领导要把A应用回版到4个月之前，自己内心其实是十分反对的，因为觉得没道理，不过现在觉得，所以的问题我们都应该用事实说话，不能觉得自己真正了解整个系统了，有时候问题是复杂的，很多东西我们只有遇到了才会知道自己其实有很多不清楚的。

信任但要验证

当周六有人报 kafka 的问题的时候，我就直接说 kafka 没有问题，并没有去验证 kafka 是否有问题，只是觉得自己的检测脚本没有告警就没有问题。试想如果当时自己登陆 kafka 服务器简单查看了下，当时也不用那么多人花了大半天的解决问题。其实自己的检测脚本也有些问题，事后改良了一下，和这个问题关系不大就不细说了。