12 月 06 日统计分析数据延时的技术背景分析

2014 年 12 月 06 日,由于一台 Kafka 机器磁盘问题,导致友盟的统计分析业务的数据出现了延时。下面我会从技术的角度给大家分享一下当时问题发生的背景、处理过程以及事后。

18:15 PM: 我们收到前端 4xx 增多的报警,对比正常时段,4xx/200 的比例由正常的 0.5% 以下上升到了 1.5% 左右。收到报警后我们立马介入现场排查问题,确认了包括每秒接受日志数量在内的核心指标并无大的异常,暂且判定为了非紧急事故。

19:06 PM: 我们开始疯狂的收到报警,查看了我们实时的 dashboard,发现 4xx 已经由原先的 ~400 req/s 飙升到了 ~10k req/s,200 也开始直线下降。同时,我们收到前端接受日志的 logtorrent 服务(基于 Finagle 实现)的 file descriptor 已经由原先的 ~7k 飙升到了几乎系统 fs.file-max 的极限。

19:07 PM: 报警显示,出问题的这条链路的入口带宽在有 20% 充足富裕的情况下被全部打满。导致我们几乎不能从主 VPN 登录我们的线上机器,于是执行了 plan B,经过我们备用的一条链路,最终登录上了我们的线上机器。
根据之前的经验,这类问题很可能是 logtorrent 承受不住某个时间点巨大的突发请求而造成的,经过再三的确认,我们发现并不是这个问题,并且经过不断的升级改造以及水平扩展,目前我们后端的一组 logtorrent 扛过 100k req/s 请求是完全没问题的,出问题的时间点,总请求只有不到 60k req/s 。

19:47 PM: 经过轮番的查看,我们发现某台 Kafka 机器的 latency 异常波动,并且数值相比正常的水准大大增加。
我们知道,Kafka 有非常良好的 fault-tolerance 机制,也就是说,在理想的 fail fast 的情况下,根据你 replica 的设置,可以宕掉任意数量不等的机器。但是,最坏的情况,不幸的被我们命中了,这种「要挂不挂」的状态导致了出问题的 Kafka 机器的 produce/consume 都受到了极大的影响。

19:53 PM: 在重启了出问题的 Kafka 机器,情况没有好转的情况下,我们直接停掉了这台机器。但是情况依然没有好转。因为雪崩效应,导致前面的 logtorrent 耗尽了系统资源无法再继续处理请求,一次 DDoS 攻击就这样形成了。

19:58 PM: 分批重启了 logtorrent,将系统资源加以释放,服务暂且恢复。

事后,我们开始分析问题的原因,从历史监控来看,在出问题的时间段内,异常机器的 consume 请求由正常的平均 0.015ms 突发达到了 0.1ms 的峰值,produce 的也由于机器的异常随之增加。拉长了历史数据来看,发现这个问题早在当日的 12 点多就开始发生,但是没有任何人发现该机器的异常。


从 Kafka 的特性来看,出现这种问题,很可能是磁盘 IO 问题导致,在监控系统上确认 IO 异常之后,我们直接在硬件层面采集了当时的数据,结果也是跟预想一样,6 块 RAID 10 组成的 SAS 磁盘有一块被标志为了 "Critical Disks",进一步确认发现有不少的 Media Error Count/Other Error Count:
$ sudo MegaCli64 -LDPDInfo -aall
Physical Disk: 1
Enclosure Device ID: 32
Slot Number: 2

Media Error Count: 784
Other Error Count: 601
Predictive Failure Count: 53
Last Predictive Failure Event Seq Number: 4309

Port status: Active
Port's Linkspeed: Unknown
Drive has flagged a S.M.A.R.T alert : Yes

接着翻看了我们磁盘监控的历史数据,系统显示早在 11/15/2014 的 11:00 AM 就首次发现了有 Media Error 的报错,只不过当时没有引起足够的重视,"Murphy's law" 告诉我们:
Anything that can go wrong, will go wrong.
终究,该来的还是来了。

上面提到的 Media/Other Error 都是不同硬盘厂商定义的一些错误代码,根据我们的经验,Media Errors 一般是在数据传输过程中产生的错误而 Other Error 则是由于硬件层面的故障导致,比如线缆问题。即使出现了上述的错误,也不能判定磁盘一定有问题,还有种可能是系统问题导致,对于这类错误的分析一般以厂商的最终检测为准,对于我们来说,返厂报修是比较好的选择。

经历了这次事故事故之后,我们至少在下面几个方面需要加强。
1. 重视每一条的报警信息,如果我们能对早在 11/15 日发出的报警信息就重视起来,及时更换磁盘或者干脆摘掉、更换该 Kafka 机器,都不会造成今天的事故。
2. 监控的加强,事后我们发现对于 Kafka 的一些基本监控的严重缺失,同样的,如果我们能在中午 12 点就收到 latency 增大的报警,也会给问题的解决争取充裕的时间。
3. VPN 入口的自动切换,默认情况下,我们只会提供一个主的 VPN 登录链路,只有在主链路不可用的情况下,需要人工干预切换到另外一条链路上,这个操作可以自动化的完成,做到对开发同学无感知。
4. 对于 logtorrent 增加 FD 超限后的逻辑判断以及自动重启,这虽然不能根本的解决某些特定的问题,但是对于减轻雪崩,及时释放系统宝贵的资源,能起到关键的作用。
5. 修改 producer 的逻辑,由于目前一台 broker 的变慢会导致所有 logtorrent 吞吐收到极大的影响,后期会考虑直接连接单台 broker 可行性。

问题发生在 12/06/2014,但是这片技术分析文档完成于 12/20/2014,很高兴的看到,经过了半个月的改进,回头来看,上面提到的 1、2、3、4 点都已经全部实现上线,对于最后一点,我们也在紧锣密鼓的测试当中,预计很快就会上线。

出现问题并不可怕,及时发现问题,事后认真分析,以 blameless 的态度完成每次 postmortem,避免类似问题再次发生,服务终究会越来越稳定。