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,将系统资源加以释放,服务暂且恢复。

Continue reading

一个月的艰辛稳定服务过程

业务大了成本问题更加的凸显,最重要的之一就是带宽,为了更好的优化资源,我们决定将目前 BGP 全线的流量切换一部分到双线上去。说白了很简单,网络方面不需要动什么大手脚,全网 10G 的链路半年之前就全部升级完毕,剩下的就是加前端,10G 服务器,LVS(nat), Keepalived,Nginx。接下来就是小流量的上线测试,从 10M 到 50M 到 100M 再到 300M 前后大概有一周的观察时间,整体还是很稳定的,当然也遇到了一些小问题,比如 10G 网卡不规则的出现了一些 rx_crc_errors/rx_missed_errors,通过优化一些硬件设备基本得到了解决,虽然后期还会时不时的冒出一些,但是从各个服务以及业务的监控方面没有看到潜在的影响,暂时略过。

正所谓稳定压倒一切,从开始小流量切换到正式全量上线的这一个月,为了稳定,充满了坎坷,下面是这一段时间遇到的一些比较有挑战的事件, 「很不幸的是」,全部是人为原因。

4xx 错误飙升
一周之后的某个早上收到报警,4xx, 5xx 的错误上升了大概一倍的样子:

可以确认的是这段时间没有任何的变更,从到后端的请求来看,这段时间的异常并没有对其有很大的影响,但是本着负责任的态度还是把当时的 log 归档拿出来分析了下详情:

可以看到,这段时间的 return code 主要是由 499 以及 500 错误引起,并且 499 的错误占了大部分的,那就从 499 的分析开始。G 了一番,发现这个 code 并非是一个标准的 RFC,唯一可以确认的就是是客户端主动的关闭了链接,至于是什么原因让客户端主动关闭的,原因就太多了。除此之外,还有一部分的稳定的 408 错误,这个比较好理解,对于由于 Nginx 读取客户端发来的请求会造成超时而返回 408。
看了上面的解释,基本得不到很明确的答案。接下来,至少还可以从 debug log 以及 error log 入手,看看能否得到一些信息。
首先看看 error log,关于 Nginx 的 access, error log 不少人都有误解,这里统一说明一下:
1. access log 的非 2xx 错误只有部分的会打到 err log 里面,仅仅是部分,而 access log 是所有的 return code 的集合
2. error log 并非是一些非 2xx code 的集合,里面很多都是开发定制的一些东西,代码都是写死的
3. 所以,任何的返回码(2xx, 4xx, 5xx)的问题都可以从 access log 里面找到问题
看 err log,大部分都是下面两种情形:
1. "no live upstreams while connecting to upstream"
2. "upstream timed out(110: Connection timed out) while reading response reader from upstream"
总结起来就是连不上 upstream 了,为什么会 time out 并不知道。再看看 debug log,这个需要在编译的时候加进 –with-debug,里面能得到的信息同样比较少:

2026/08/02 15:29:14 [debug] 58443#0: *26274947 http upstream recv(): -1 (11: Resource temporarily unavailable)

2026/08/02 15:29:14 [debug] 58443#0: *26274956 recv() not ready (11: Resource temporarily unavailable)

调查到了这里,基本从已有的信息没得到什么特别的结论,考虑到对后端本身并没有影响,这事就这么被放过去了。但是,再怎么逃避也逃避不了墨菲定律。

logrotate(gzip) 的问题
几天之后的某个晚上,突然收到报警,ipvs master 上的 rs 被移除,紧接着 ipvs slave 上的 rs 也被移除,接下来就是疯狂的短信轰炸了,一会儿 add,一会儿 remove。当时我不在现场,让我们同事先临时手动把 vip 从目前的 master 切换到了 slave,但是不见好转,当机立断,直接全部切换到全线,客户端由于会 cache 以及重发机制,所以这 20min 的 outage(发到后端的请求大概跌了 2/3) 对实际的影响并不是很大。回去之后开始重点分析这次事故。
首先是把 dr, rs 包括 traffic, req, lvs conn, Nginx return code/status, 各种 rt/delay 在内的核心监控一步一步分析回溯,理清了从问题开始一直到恢复这中间发生的每一步过程,发现的最大的收获是出问题的这段时间,lvs 到 rs 的延时大大增加:

其次,keepalived 打到 messages 里面的 log 也看到了不少的东西,比如这段时间,会频繁的 add, remove rs:
Sep  6 20:20:10 lvs-1 Keepalived_healthcheckers[107592]: TCP connection to [192.168.90.6]:80 success.
Sep  6 20:20:10 lvs-1 Keepalived_healthcheckers[107592]: Adding service [192.168.90.6]:80 to VS [111.111.111.4]:80
Sep  6 20:20:14 lvs-1 Keepalived_healthcheckers[107592]: TCP connection to [192.168.90.5]:80 failed !!!
Sep  6 20:20:14 lvs-1 Keepalived_healthcheckers[107592]: Removing service [192.168.90.5]:80 from VS [111.111.111.4]:80
Sep  6 20:20:20 lvs-1 Keepalived_healthcheckers[107592]: TCP connection to [192.168.90.5]:80 success.
Sep  6 20:20:20 lvs-1 Keepalived_healthcheckers[107592]: Adding service [192.168.90.5]:80 to VS [111.111.111.4]:80

把 log 的时间扩展到三天前,再仔细的观察观察,可以发现,每一次 add, remove 的操作都是出现在整点的时候:
Sep  6 12:00:15 lvs-1 Keepalived_healthcheckers[107592]: TCP connection to [192.168.90.5]:80 failed !!!
Sep  6 12:00:15 lvs-1 Keepalived_healthcheckers[107592]: Removing service [192.168.90.5]:80 from VS [111.111.111.4]:80

Sep  6 15:00:11 lvs-1 Keepalived_healthcheckers[107592]: TCP connection to [192.168.90.5]:80 failed !!!
Sep  6 15:00:11 lvs-1 Keepalived_healthcheckers[107592]: Removing service [192.168.90.5]:80 from VS [111.111.111.4]:80

联想到整点 ngx 会进行 logrotate 的操作,期间会产生大量的 io,导致系统负载变高,再加上 ngx 本身处理 req 会有一定的负载,导致 lvs 监测到 rs 无法响应的状态。
通过监控可以发现,每个整点的 load 都会变大:

从上图可以发现,整点的这一小段时间,load 至少会超过 1,跟 24 核的机器比,似乎非常的小,但是需要考虑的一点是,我们的采集 load 的监控是 60s 一次,监控实现秒级的成本太大,实际在 60s 内系统的负载会比上图的大得多。
为了验证这个问题,手动的模拟一次 logrotate(gzip) 的操作,平均一小时的 log 量在 5G 左右。下面的是手动执行一次 logroate 操作得到的监控数据,可以看到高峰时段,这块普通的 SAS 盘的 io util 达到了 100%,磁盘写吞吐达到了 245M/s,load 峰值超过 10:
04:06:00 CST       DEV       tps  rd_sec/s  wr_sec/s  avgrq-sz  avgqu-sz     await     svctm     %util
04:06:01 CST    dev8-0    702.06     24.74 711958.76   1014.13    145.91    208.25      1.47    103.20
04:06:02 CST    dev8-0    701.01      8.08 704840.40   1005.48    146.79    208.00      1.44    101.01
04:06:03 CST    dev8-0    677.55      0.00 681755.10   1006.20    144.27    213.12      1.51    102.04
04:06:04 CST    dev8-0    672.45      8.16 681608.16   1013.63    141.47    210.12      1.52    102.04
04:06:05 CST    dev8-0   1364.65      0.00 694884.85    509.21    122.71     91.27      0.74    100.91

这总算是找到 lvs 频发 add, remove 的原因了,接下来改进就相对比较简单了:
1. lvs 对 ngx 不要太敏感,这个在 timeout 的一些设置上适当的加大可以缓解
2. ngx 的 log 处理问题,最初有同学提议只开一台 rs 的log,其他的全部关闭,这个看上去似乎可行,开一台基本可以代表其他 rs 的情况,但是实际情况可能并非我们所能想像,如果没有开启 access 的机器出现了问题而开启的每有任何问题,后续的问题排查将会比较的麻烦。所以,不管如何,保留一分全量的 log 还是非常有必要的。对此,比较通用的做法将 Nginx 通过 syslog 直接传到的远端的机器上,本地保留一分全量的,但是不开启 logrotate 的 gzip 压缩。
3. 除此之外,还可以考虑通过 access_log, error_log 的 ratio 来控制产生 log 的比例

Nginx open file 的问题
这个问题到此结束,这样安稳的过了四天,某天晚上 messages 里面发现 keepalived 频繁的 add, remove rs 了,这次时间不是整点了,虽然只出现了一两次,但是可以暴露出整个集群还是处于一个不稳定的状态,最初我们认为是 TCP_CHECK 的检测机制有问题,太过敏感,于是换成了 HTTP_GET 的方式,但是第二天仍然时不时的报错,并且从时间上来看完全没有规律:
Sep 10 17:15:19 lvs-2-2399 Keepalived_healthcheckers[34943]: MD5 digest error to [192.168.90.6]:80 url[/], MD5SUM [f9943d27e3420479271984e01dfe85dd].
Sep 10 17:15:19 lvs-2-2399 Keepalived_healthcheckers[34943]: Removing service [192.168.90.6]:80 from VS [124.251.33.4]:80
Sep 10 17:15:22 lvs-2-2399 Keepalived_healthcheckers[34943]: MD5 digest success to [192.168.90.6]:80 url(1).
Sep 10 17:15:28 lvs-2-2399 Keepalived_healthcheckers[34943]: Remote Web server [192.168.90.6]:80 succeed on service.
根据 keepalived_healthcheckers 检测的逻辑来看,肯定是发现 http://192.168.90.6/ 返回的不是既定的 md5sum 值,才触发了 remove 操作,很可能 rs 返回的不是 200 的错误才导致的。
抓包,为此蹲守了很长的时间抓住了重现的机会:

果真,确实是 rs 返回了 500 的错误才导致被 remove 的。之前虽然 5xx, 4xx 会增大,但是几乎并不影响 200 的数量,这次却不是这样的情况,500 的增多,200 的却异常下跌。全量分析 err log,惊人的发现,这段时间内的错误条目是平时的 100 倍,并且,出现奇怪的出现了下面的错误:
2014/09/06 20:09:55 [alert] 3164#0: *4082964565 socket() failed (24: Too many open files) while connecting to upstream, client: 122.93.211.105, server: foo.example.com, request: "POST /fk HTTP/1.1", upstream: "http://192.168.90.53:8888/fk", host: "foo.example.com"

一查 /proc 下面的 limits,Ngx 的竟然变成了 1024:

看到 1024 的那一刹那突然想起了我们之前某个产品线同样的出现过一次这个文档,当时尝试了各种办法包括直接修改 limits 文件也无法提高 open file,后来直接 reboot 机器了(有自动的 failover 策略),恢复,这事后来就被慢慢淡忘了,但是真相依然不清楚。结果,这次墨菲又找上门来了。后来我们发现还是有些用户(1, 2)  出现了跟我们类似的情况,但是依然不清楚原因。
为了确认就是 open file 造成了,对比一下 5xx(too many open file) 跟非 200 错误的比例:

完全符合。
真正的原因我也没法说清楚,基本可以肯定的是在 Nginx 运行过程中 open file 被改成了 1024。不过现在应该可以完全避免这个问题了,除了通过 worker_rlimit_nofile 指定之外,我们把这些进程的 limits 文件全部监控起来,包括 fd 的数量,这样即使再次「诡异」的变成了 1024,我们也能及时的发现采取措施。

kernel panic 的一些问题

机器稳定的运行了几天之后,某天早上 master 突然 kernel panic 了。
能得到的信息非常少,接下来继续挖坟似的分析 messages log。5min 打出的几百条 log 一条一条的对着 timestamp 分析,从 log 看,slave 是成功切换了,在 master 起来之后,流量又逐渐的恢复到了 master 上,但是至此之后,rs 上的流量由于 master 出现了问题。开始 master 看上去像是 work 的,inacctive conn 开始恢复,但是 active conn 一直到 5min 之后才开始恢复,这期间发生了什么,lvs 的 log 并没有很详细的说明,看上去像是两台 lvs 都没有工作,slave 变成了 backup 自然不再工作,挂掉的那台 master 虽然起来之后进入了 master 并且也 enable 了两台 rs,但是正常的流量却没有过来。
出现上面这种情况的可能原因是什么?keepalived 的配置出现问题了,果真,没有指明 priority。这个问题复现还算比较容易,直接把 master 的搞 kernel panic 就可以出现跟生产环境一样的现象,严格指定 priority 之后则不会出现这么长时间内无人接收请求的情况。
拿来主义是非常可怕的,当时我没有 review 下 keepalived 的配置就直接开跑了,核心服务还是要亲自验证。
除了上面这个教训之外,既然是 HA,一定要自己做一些破坏性实验,验证各种可能的情况。真正上线之前不验证,及时发现问题,真的全量上了,到时候出现问题的影响更大。我们虽然在小流量切换时,也做了一些破坏性实验验证 HA,但是并没有缜密的把所有情况都列穷举出来。

上面仅仅解决了 keepalived 的一个问题,kernel panic 似乎没有引起我们的注意,之后几天接连的出现 kernel panic,我们才意识到,这是个非常严重的问题,虽然每次 kernel panic 都完全的切换成功了。想到现在 lvs 使用的 kernel 跟官方唯一不一样的地方就是我自己重新编译了 kernel,调大了 IP_VS_TAB_BITS。既然这么一个小的改动都会引发 kernel panic,那索性还是先切回官方的版本,毕竟我们现在线上 90% 的机器都已经成功的跑了很长时间了。没想到的是,即使使用了官方的版本,依然不停的 panic,后来发现是其实是个 bug,在给 ipvs 的连接做 hash&unhashing 的时候缺少对被修改连接的锁,导致内存奔溃。理论上,我们可以对目前的 src 打 patch,但是实际的效果不得而知,加上没有之前的成功案例以及团队缺少精通内核的人,不得放弃这个想法。后来想到了我们兄弟团队,在多方求助之后,终于用上了高大上的集团内核,至此内核运行的很稳定。


4xx 问题的最终调查
还记得最上面第一次出现的 4xx 飙升问题吧,从某日起,4xx 的错误又明显的增大,通过对历史数据的分析发现增多的 4xx 错误主要集中在 499,随着高峰的来临(白天工作时间至凌晨),499 的错误也显著性的增加:

再次回顾下 499, 408 的问题。
499 实际上是客户端先关连接的,原因很多(无法确定,客户端引起),比如:
1. 刷页面的时候连按了 2 次 F5,就会导致之前页面上的请求没有收到完的就 499
2. 网络太慢
3. ngx 刚转发请求往后端,后端还没来得及应答,前端就主动关连接了

408 问题的解释:
1. 408 是客户端连完整的请求也没有传完,从 access log 里面没每发现 ua,正常的上传应该是有 ua 的,所以这个问题很可能是由于网络问题造成的
2. 408 的复现也比较简单,发送 POST /app_log HTTP/1.1 给 ngx,不发数据,过 60s 就会返回 408 的错误

除了 4xx 错误的飙升之外,upstream java 的 fd 也会随之飙升,从上面的一些数据至少可以得到下面的一些结论:
1. 本身移动网络的质量相比会比较差,再加上刚切换完双线,有一定 4xx 的增加还是可以理解的
2. 正常的应用,比较稳定的 4xx 应该是比较正常的
3. 但是,我们的情况是连续数天的 4xx 频繁不稳定,所以,可以确定有问题

想到这段期间唯一的操作就是切换了流量,于是,直接回滚,全部切换到全线 BGP,观察了一天没有任何效果。在跟开发确认一些细节的时候发现,原来在 4xx 飙升的前一天,更新过一次代码,既然切回全线没效果,那继续回滚代码吧,结果大跌眼镜的是问题依然存在。

结合 upstream 发现,有大量的 CLOSE_WAIT  状态,并且 recv-Q 均为非 0:
# cat status
established
syn-sent
syn-recv
fin-wait-1
fin-wait-2
time-wait
closed
close-wait
last-ack
closing
# for i in $(cat status);  do echo -n  "$i: " && ss -o state $i src INTERNAL_IP | wc -l; done
# ss src INTERNAL_IP:PORT  | head


上面的非 0 字段表明,upstream 没能成功的接受发过来的请求将其放到网卡的 buffer 里面,导致其 queue 一直保持在非 0 状态。
问题分析到这里,基本可以确定是用户态的应用没法正确的接收请求才导致此类结果,再结合上面 return code 的分析以及 upstream 的分析:
1. 切换完双线之后,由于本身网络质量会有一定的下降,所有 4xx 的会增多,这个是可以容忍的
2. upstream 代码层面应该还存在一些问题,结合 fd 的监控,网上高峰 fd 可能会飙升到 100+K,是不是有可能 fd 没有及时的回收?(fd 泄漏有没有这种可能)
3. 出问题前一天更新过一次代码,在其他没有变化的情况下,从前端到后端的监控都有不同程度的异常,是不是上线的有问题

上面提到的 fd 飙升问题,既然飙升,那就在出问题的时候上去看看是哪些 fd 飙升,首先需要确认是确实是 java 的进程导致:
for x in `ps -eF| awk '{ print $2 }'`;do echo `ls /proc/$x/fd 2> /dev/null | wc -l` $x `cat /proc/$x/cmdline 2> /dev/null`;done | sort -n -r | head -n 20

在某天出问题的中午 12 点,我登录到出问题的机器上统计了 fd 的情况:
出问题的时间段 fd 在 ~40k,分解下来包含
* tcp estab: ~1.7k,跟正常的比没变化
* tcp close-wait: ~9k,这两者大概 10k
* 剩余的 30k 通过 lsof 观察全部是 can't identify protocol 的状态

而正常情况是:
* tcp estab: ~1.5k
* tcp close-wait: ~2k
* 剩余的一些是 can't xxx

也就是说出问题阶段,close-wait & can't identiy protocol 飙升了原来的数倍:
1. close-wait 的很好理解,跟之前的观点一样,tcp 一直在等待 user space 调用 close(),否则会一直处于 close-wait 状态
2. can't xxx 的暂时没法解释,等到下一次出问题的时候再观察

有这么多的 close wait,很容易让人联想到是 fd 泄漏,想关闭的一方发送 tcp fin,服务端收到之后,如果程序逻辑有问题,忘记调用 close(socketfd),则会造成 fd 泄漏,表象就是有大量的 close wait 状态。不过从监控来看,这部分的飙升的 fd 很快就会直线下降到正常值(后来分析 jvm 的时候发现其实是 mgc, fgc 导致的 fd 回收):

问题分析到这里,那就继续深入下去,从 JVM 层面看看有没有问题。
首先看看 java 的进程,不管是正常状态还是异常状态,某几个 thread 都消耗了大量的 cpu 以及 fd,也就是说目前的 thread 是非常不均匀的,某一个 thread 能消耗 50% 以上的 fd:

接下来,搞个脚本看看最耗资源的那个 thread dump 是什么样的,有了这个就可以很容易的看到某些方法的异常了。这我在前一篇博客已经总结过,这里假设我们已经得到了 TID,先转换成 hex 然后 for 循环就能找到真相了。
for i in {1..100}; do echo "—$(date +'%H:%M:%S')—" >> tiddump.log; LAB=$(date '+%s'); HEX=`echo "obase=16; $TID" |bc`; jstack {PID} >> ./jstack$LAB; grep -iA 20  $HEX  ./jstack$LAB –color >> tiddump.log; sleep5; done

到了这一步,真相大白了,从 log 里面发现某些方法调用常年的 hang 在那儿,源于系统在处理某个大 List,客户端的 SDK 层面逻辑判断有问题,不做检查的把一些巨型字段经过压缩都发到前端这边来,结果到了后端解压缩处理的时候发现处理不了。

如果依然发现不了问题了?其实这时候问题的范围已经被缩的很小了,除了继续通过 mat、btrace、perf 深层次的跟踪服务情况之外,还有个重要的方面遗漏了,确认我们使用的一些软件的版本有无 bug,不要以为那些 release log, changelog, readme 文档是写着玩的,开发没养成看这些细节文档的习惯如果 如果我们一线运维也不看,那最坏的结果就是折腾了十来天最后看到最新的发型版本的 release log 出现了一些特殊的 bugfix 字段以及最后的欲哭无泪。
最初我们怀疑是服务在关闭连接的处理逻辑上有问题,后来发现我们的代码里面并不涉及这方面的逻辑处理,连接的建立关闭全部由 Finagle 框架自己处理了,所以一个重要的疑点是我们使用的该框架的版本是否存在连接方面的 bug,查一下他的下一个以及下几个版本的 release log 很快就能确认。

以上分析的这些案例,虽然影响没有大到会让业务遭受严重的损失,但是不夸张的说,每一个都是一个重量级的定时炸弹,不及时排除,指不定哪天全线就都挂了。这些事件,可能绝大多数的公司都不会遇到,但是思考问题的思路方向比这些案例重要的多,拿这次来说,其实思路在一开始就跑偏了,在确认前端没有问题的情况下还在花了大量的时间而不是一开始就从 upstream 下手。

ipvs 频繁 add/remove 后端 rs 问题追查

这个问题我们三年前就遇到过,限于当时的资源,没能分析出具体的原因。欠下的债肯定是要还的,最近又遇到了,不过解决起来倒是很快。
看 messages,发现有不少类似的 log:
Mar  6 15:00:11 lvs-1 Keepalived_healthcheckers[107592]: TCP connection to [192.168.90.5]:80 failed !!!
Mar  6 15:00:11 lvs-1 Keepalived_healthcheckers[107592]: Removing service [192.168.90.5]:80 from VS [111.111.111.4]:80
Mar  6 15:00:17 lvs-1 Keepalived_healthcheckers[107592]: TCP connection to [192.168.90.5]:80 success.
Mar  6 15:00:17 lvs-1 Keepalived_healthcheckers[107592]: Adding service [192.168.90.5]:80 to VS [111.111.111.4]:80
Mar  6 20:00:16 lvs-1 Keepalived_healthcheckers[107592]: TCP connection to [192.168.90.5]:80 failed !!!
Mar  6 20:00:16 lvs-1 Keepalived_healthcheckers[107592]: Removing service [192.168.90.5]:80 from VS [111.111.111.4]:80
Mar  6 20:00:22 lvs-1 Keepalived_healthcheckers[107592]: TCP connection to [192.168.90.5]:80 success.
Mar  6 20:00:22 lvs-1 Keepalived_healthcheckers[107592]: Adding service [192.168.90.5]:80 to VS [111.111.111.4]:80

结合监控图,发现出现问题的时候都是在整点,并且正点的时候系统的 load 确实比较大,把历史的 sar 数据调出来发现正点的 IO 利用率都是在 100%,这一联想就只有 logrotate 在正点做 rotate 然后 zip 压缩了。模拟了一下发现可以复现该问题,剩下的就是解决问题了。

除了上面这个,我们还发现在非整点也会出现类似的 log
Mar 10 17:10:23 lvs-2 sshd[54526]: Accepted publickey for jaseywang from 192.168.10.254 port 56532 ssh2
Mar 10 17:15:19 lvs-2 Keepalived_healthcheckers[34943]: MD5 digest error to [192.168.90.5]:80 url[/], MD5SUM [f9943d27e3420479271984e01dfe85dd].
Mar 10 17:15:19 lvs-2 Keepalived_healthcheckers[34943]: Removing service [192.168.90.5]:80 from VS [111.111.111.4]:80
Mar 10 17:15:22 lvs-2 Keepalived_healthcheckers[34943]: MD5 digest success to [192.168.90.5]:80 url(1).
Mar 10 17:15:28 lvs-2 Keepalived_healthcheckers[34943]: Remote Web server [192.168.90.5]:80 succeed on service.


抓包发现 LVS 向 RS 发送 GET / HTTP/1.0 的请求, RS 却返回了 HTTP/1.1 500 Internal Server Error 的非 200 错误码,所以 LVS remove 掉这些 RS 确实是正常的逻辑:

同样从监控中看到,出问题的时间段由于频繁的切换导致了前端几乎不可用,在 5 点多这一时段 error log 的比平常大了 100 多倍,达到了 500M:

从上面的信息,全量分析了出问题阶段所有 err log 的类型,发现了惊人的答案,99% 以上的问题都源于 "too many open file" 的错误,/proc 一看,发现 Nginx 的确实变成了 1024:
# cat /proc/3148/limits
Limit                     Soft Limit           Hard Limit           Units     
Max cpu time              unlimited            unlimited            seconds   
Max file size             unlimited            unlimited            bytes     
Max data size             unlimited            unlimited            bytes     
Max stack size            10485760             unlimited            bytes      
Max core file size        0                    unlimited            bytes     
Max resident set          unlimited            unlimited            bytes     
Max processes             514947               514947               processes
Max open files            1024                 4096                 files     
Max locked memory         65536                65536                bytes     
Max address space         unlimited            unlimited            bytes      
Max file locks            unlimited            unlimited            locks     
Max pending signals       514947               514947               signals   
Max msgqueue size         819200               819200               bytes     
Max nice priority         0                    0                    
Max realtime priority     0                    0                    
Max realtime timeout      unlimited            unlimited            us      

root 用户的没有问题:
# ulimit  -a
core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
scheduling priority             (-e) 0
file size               (blocks, -f) unlimited
pending signals                 (-i) 514947
max locked memory       (kbytes, -l) 64
max memory size         (kbytes, -m) unlimited
open files                      (-n) 512000
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
real-time priority              (-r) 0
stack size              (kbytes, -s) 10240
cpu time               (seconds, -t) unlimited
max user processes              (-u) 512000
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited

不过为什么突然由原来的系统级别的数字变成了 1024,实在值得奇怪,该问题很早之前在我们一台 Nginx 的机器上同样遇到,记得当时 restart 了 Nginx 依然没有效果,不得已只能 reboot 机器恢复。Nginx limit 变成 1024 的问题,其他用户也遇到类似的问题:
* http://serverfault.com/questions/516802/too-many-open-files-with-nginx-cant-seem-to-raise-limit
* http://anothersysadmin.wordpress.com/2013/08/09/nginx-and-the-too-many-open-files-limit/

目前还无法得知为什么,但是找到了部分原因,要避免此类问题倒是很简单,强行指定 worker_rlimit_nofile 就好了,谨慎起见,把 /proc/xxx/ 下面重要的文件都给监控上。

访问 VIP 缓慢的调查

将某个 https 的域名迁移到 lvs,部署完成,绑定 hosts 测试过程中发现 GET 请求非常的缓慢,一个 90KB 的图片耗费的时间长达几十秒甚至超过 1min,这个在未迁移前是从未出现过的现象。
为了一步一步调查,绑定了 hosts 直接访问 rs,结果跟未迁移前效果一样,但是直接访问 VIP 则十分的缓慢。看到这么多的现象,第一反应是难道经过了 VIP 之后 ssl 的处理速度会急剧下降?直接用浏览器自带的开发工具观察好了,发现包含 DNS 查询之前的响应还是很快的,从 Connecting 开始之后的每一步当然包括 SSL 了,其 RT 都是原先的 100 倍以上,Waiting 以及 Receiving 的时间更是长的惊人。
为了方便后续的分析,找了个简单的脚本,可以通过 curl 更方面的观察:

# cat curl-format.txt
    time_namelookup:  %{time_namelookup}\n
       time_connect:  %{time_connect}\n
    time_appconnect:  %{time_appconnect}\n
   time_pretransfer:  %{time_pretransfer}\n
      time_redirect:  %{time_redirect}\n
 time_starttransfer:  %{time_starttransfer}\n
                    ———-\n
         time_total:  %{time_total}\n

curl -w "@curl-format.txt" -o /dev/null -s http://wordpress.com/
连续几次的测试结果跟上面观察的到的一样。当时的第一反应是,虽然怎么都讲不通,经过了 VIP 之后质量还不到原来的 1%,但观察到的结果就是,这个 SSL 把个 VIP 搞的这么慢,为了确认确实是 https 的问题,又找了几个 http 的资源测试了一下,结果,奇怪的事情发生了,也极其的缓慢。
看来最初的判断是错误的,所有的走 VIP 的 GET 都变的极其缓慢了,那为什么之前比这个量大的多的 POST 没有任何异常了?最大的区别就是发送请求 body 的大小了,前者一个静态资源都是几十上百 K,而后者仅仅是返回一个 json 的纯文本。
直接抓包,最初仅仅是在客户端分别抓经过 VIP 跟不经过 VIP 的包,除了每一个 segment 的返回时间差距很大之外,其他的并无差异。后来经我们主管提醒,需要在服务器上也同时抓包,于是一个在原来的 Nginx 上抓,一个在 VIP 上抓,对比相面四张图应该就能看出原因所在了。



上面两张是不走 VIP 的情况,可以看到一个 90K 的文件经过 12 个 TCP segment 就重组了,看 length 这一栏也可以得出,平均一个 segment 都在8K 左右。



上面两张是走 VIP 的,所有的 segment 都变成了 1514(14B 的二层加上 MTU),导致的结果是分了 60 多个 segment。
看到这里立马就联想 2.6.32 ipvs 对 gro 的那个 bug: 2.6.32 – 2.6.36 的内核上在使用 ipvs 的情况下需要关闭 gro。这个我之前曾经单独写过一篇博客。只不过当年没有深入的研究下开启 gro 会有什么具体的影响,这次算是经历过了。
由于配置管理的问题,导致我们一个集群上部分网卡的 gro off 操作没有生效,这个其实是主因。
既然说到 gro/lro,那干脆把 tso, gso 的也一并实践一下。
tso, gso 在 Ubuntu 以及 RedHat 上默认是开启。
gro 在 Ubuntu 上默认关闭,在 Redhat 上默认开启。
lro 的在这两个发行版本上默认均是关闭。

可以看看我下面的两个抓包,第一张是 tso, gso 均关闭的情况

下面一张是单独开启 tso 或者 gso 的情况

现象是不是很明显。所以开启 tso/gso 对于绝大多数的应用来说还是很有必要的,能节约不少资源。

ref:
http://wiki.wireshark.org/CaptureSetup/Offloading

最近半个月的工作[14P]

5 月发生的事,6 月补充完,9 月发出来 ;-)


5 月 13 日周二
开始我们另外一个核心 IDC 最后一次常规性 10G 升级,下面的一部分我们后来把他总结成了《5 月故障总结(post-mortem)》
回家睡了会儿,3:00 am 起床,4:00am 开始连续干了 6h
回公司休息了 1h,塞了点巧克力复活
中午去水立方进行了常规的 1h 训练
回来面(对了,我们目前招高级应用运维工程师 PE,有兴趣的给我简历,邮箱是 w 在 umeng 点 com)了一个候选人,结果在我问到第二个问题的时候就怂了,第一个问题是常规性的自我介绍,第二个问题也是我最喜欢问的问题之一,最近半个月在做什么
由于 uplink 依然在老的网络环境中,我们老的 3750X 到新的 Nexus 中间的 8G port channel 链路中的一条物理链路由于 LB 的算法不科学,导致其打满丢包的状态,当机立断,直接让 NE 更改了 LB 的算法,效果明显

5 月 14 日周三
由于 uplink 这个不稳定因素的存在,开会讨论最后一次也是最重要的升级以及收尾工作,由原本的周四凌晨升级提前到了周三凌晨进行
10G 的最后一次也是最重要的升级,应为涉及到切换我们的 uplink,迁移我们的 GW 以及我们两地双机房中间的互联链路迁移
晚上去和颐休息了 3h,凌晨 3 点干到早上 7 点,期间除了 uplink 切换成功之外,其他的均已失败回滚告终,回酒店休息了 3h
中午回公司继续,讨论了凌晨出现的一些问题以及解决方案,其中我们两地双机房互联链路不通的问题最后发现是 HSRP 的问题
凌晨 GW 迁移失败之后,我跟我们 ne, director 回公司模拟了一下当时出现问题的场景,想了几种可能的原因,不过都被实际的模拟结果所否定,唯一的可能性就是服务器会自动的更新 arp 表,找到新的 GW 地址
下班之前,上面遇到的所有问题都已经找到了问题的根源,想到了对策,唯独 GW 的问题,这个对我们整个生产环境的影响绝对是毁灭性的,一旦 GW 迁移失败,我们所有跨 VLAN 的访问都将失败,由于当时时间太紧迫,根本没有时间让我去 debug 就回滚了,我也就无法得知当时真正的现象以及后续的细节
临走之前,我们 director 问我要不要他过去帮忙,我当时是拍着胸脯说的「相信我,你回家休息吧」,虽然我当时有 95% 的把握确认了上面提到的迁移失败的原因以及 80% 左右的把握让我在非常短的时间内 debug 找到问题并且修复,其后者是最具有挑战性的

现在看到的我们的还是 1G 的上联,等你看到这篇博客的时候,应该已经升级到了 10G 的上联了

5 月 15 日周四
这次升级提前预留了充足的时间,从 3:30 – 6:00,我觉得 3h 的时间足够我 debug 一个中等难度的线上问题了
跟昨晚一样,先是回酒店休息了一下,凌晨 2 点开足马力一直干到了早上 8 点多,GW 的问题也在我们开始的第一步被我很快的发现了问题的原因并且修复,两地双机房互联 HSRP 的问题也后续被我们 ne 一举解决,「基本完美」收官,为什么这么说?因为后续的几天出现了若干的问题,好在都不是我们核心的 Nexus 引起的
回酒店休息到 11 点,打车回家准备继续休息,结果在车上就收到报警说我们的一台前端的 ngx 挂了,当时电话跟我们工程师沟通了下,看现象不大像是新升级的网络造成的,回家又花了 1h 时间救了把火,最后查明原因发现确实跟网络没有关系,只不过在这个敏感的时间点上,出现任何的问题,正常人都会不由得往网络上面倾斜
下午先赶到公司跟我们 director 沟通了进展的,然后赶到清华,在那儿度过了下午剩余的时间,干嘛的了?我花了 3h 的时间去拜拜 RMS 大神,花了 1h 的时间跑到教室外面的走廊插上了 3G 网卡排查了一起路由问题
RMS 大神确实蛮有意思的,下面这三段视频是我当时在现场拍的,虽然 RMS 说不要把这些视频照片传到 youtube, instgram 上,但我还是本着共享的精神跟大家分享了:

  1. Windows is malware
  2. Dancing during class break
  3. St. iGNUcius avatar

下午在会场收到反馈说,我们某个 storm cluster 的处理性能出现了问题,时间点跟我们升级网络的时间几乎吻合,但是从我们内网的各项监控指标来看,数值得到了前所未有的好转,pkg loss 由原来的 8% 直接变为了 0,latency 也由原来高峰时期动辄 4, 5ms 直接下降到了 0.2ms 以下,直觉告诉我几乎不可能是核心网络引起的,但是,没有更有力的数据来证明这些
看码农们在邮件里面以 「猜测」、「推脱」的姿态开始了问题的 debug 之后,我直接以「明天人齐了一起讨论下吧。」结束了这场闹剧
听完演讲之后本想回公司报个销就回去休息的,结果的结果,碰巧我们一个核心业务线上出现了很严重的性能问题,伴着麦当劳雪碧继续搞到了接近凌晨,没找到的问题原因,但是紧急扩容了一些机器,情况有所好转

两个出口的 ngx 都挂了


两个出口的流量一个跌没了一个直接爆了

Continue reading

耗时半个月排查问题的小结

这次是最近遇到的比较 tricky 问题的升级版本,当然他们二者没什么关系了,基本上我这半个月的时间都耗在这上面了,尝试了各种手法,包括 systemtap, dropwatch(感谢 @bitstream 的帮忙),不管如何,最终还是在我们 director 的帮助下一起解决了,虽然最后的 root cause 不是什么很高深的理论,懂点 TCP/IP 的应该都能理解,但是整个排查的过程我认为还是很值得参考的。本次 debug 仅仅涉及到 IP 层以下的内容,跟上层应用没有什么关系,对 IP、MAC 等数字不敏感的建议不要读了,即使要读也务必理清楚了再往下,下面会涉及大量的 VLAN IP 段,如果想知道最终的结果,直接跳到最后就好了。

在升级完我们所有的 10G 网络之后,出现了如下的现象。
1. 所有只配有一个内网的机器没有任何的问题,通过默认的 GW 可以访问其他 VLAN 机器,比如这个,默认都通过 10.118.10.250 出去:
jaseywang@u9:~$ route -n
Kernel IP routing table
Destination     Gateway         Genmask         Flags Metric Ref    Use Iface
10.118.10.0      0.0.0.0         255.255.255.0   U     0      0        0 eth1
0.0.0.0         10.118.10.250    0.0.0.0         UG    0      0        0 eth1

2. 所有配有公网的服务器到一部分内网的 VLAN 不通而到另外一部分内网 VLAN 则是通的:
jaseywang@un10:~$ ip add
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 16436 qdisc noqueue state UNKNOWN
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc mq state UP qlen 1000
    link/ether 78:2b:cb:53:d6:55 brd ff:ff:ff:ff:ff:ff
    inet 111.111.111.230/26 brd 111.111.111.255 scope global eth0
3: eth1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc mq state UP qlen 1000
    link/ether 78:2b:cb:53:d6:56 brd ff:ff:ff:ff:ff:ff
    inet 10.118.10.20/24 brd 10.118.10.255 scope global eth1

root@un10:~# route -n
Kernel IP routing table
Destination     Gateway         Genmask         Flags Metric Ref    Use Iface
111.111.111.192 0.0.0.0         255.255.255.192 U     0      0        0 eth0
10.118.20.0      0.0.0.0         255.255.255.0   U     0      0        0 eth1
10.118.10.0      0.0.0.0         255.255.255.0   U     0      0        0 eth1
10.111.0.0       0.0.0.0         255.255.255.0   U     0      0        0 eth1
0.0.0.0         111.111.111.193 0.0.0.0         UG    100    0        0 eth0

root@un10:~# ping 10.118.20.1
PING 10.118.20.1 (10.118.20.1) 56(84) bytes of data.
64 bytes from 10.118.20.1: icmp_seq=1 ttl=63 time=43.6 ms
64 bytes from 10.118.20.1: icmp_seq=2 ttl=63 time=30.4 ms
^C
— 10.118.20.1 ping statistics —
2 packets transmitted, 2 received, 0% packet loss, time 1001ms
rtt min/avg/max/mdev = 30.453/37.054/43.655/6.601 ms

root@un10:~# ping 10.111.0.1
PING 10.111.0.1 (10.111.0.1) 56(84) bytes of data.
From 10.118.10.21 icmp_seq=2 Destination Host Unreachable
From 10.118.10.21 icmp_seq=3 Destination Host Unreachable
From 10.118.10.21 icmp_seq=4 Destination Host Unreachable
^C
— 10.111.0.1 ping statistics —
5 packets transmitted, 0 received, +3 errors, 100% packet loss, time 4008ms
, pipe 3

当时我在现场发现了这个问题,看路由表,写的好像有些问题。抱着试一试的态度,反正也是不通,死马当活马医,找了一台有问题的机器把之前的:
root@un10:~# route add -net 10.111.0.0 netmask 255.255.255.0 eth1
改成了下面的这种方式:
root@un10:~# route add -net 10.111.0.0 netmask 255.255.255.0 gw 10.118.10.250

「神奇」的是,竟然 work 了。现场任务繁重,没有那么时间仔细考虑,恢复系统要紧,我很快把我们剩余的出现问题的机器都按照这种方式修改了 route。至此,线上的机器总算能恢复正常了,虽然当时不清楚为什么。回来之后,当然要做详细分析了。为了复现当时的问题,我又找了几台机器。

Continue reading