一叶障目, 不见泰山. 前阵子一直在排查一个性能问题, 结果由于一些惯性思维, 费了好大劲才弄明白原因, 而且原因非常简单….把这事记录下来,免得以后再掉坑里去.
现象是到了晚上10点多, server lantency 突然一瞬间变高, 但持续时间很短，马上就会恢复, timeout 的请求也不多，影响不大.问题其实从蛮久前就出现了, 但一直也没很重视, 因为持续时间短,影响也不大,简单看了下也没看出明显的问题, 就一直搁置着. 直到最近，觉得问题变严重了, latency 变的更高了，而且在10～11点间多次变高, 开始认真看为什么.
以下是 debug 过程:
- 时间段非常固定，每天的晚上10 ~ 11点之间, 每次持续时间很短, 触发时间不是很有规律.
- 查看那段时间每个 group 的 load 情况, 有变高,但不明显.
- 查看 qps, 并没显著变化.
- 查看 qps * avg_latency, 可以看到在一段时间内最耗时的接口, 只能看到几乎所有接口都变高了, 占比最高的还是那几个最慢的接口, 并不能解释突发的 latency 变化.
开始推测, 晚上的 10 点到 11 点,美国那边用户差不多起床,是每天第一次打开 app 的时候, 而我们有些接口里很慢的 code path 只有用户在一天内第一次使用 app 的时候才会触发, 那边的业务逻辑本来就很混乱, 开始着手优化业务代码.
- 看 datadog 的 apm tracing, 查看慢接口对各种 service 的调用情况 (Redis, MySQL, ElasticSearch,DynamoDB…)
- 通过 pyflame 抓取进程运行时的 stack trace.
结果很失望, 没有能一眼定位问题的地方, 只能说慢的地方一如预期的慢, 硬着头皮优化代码, 去掉了一些接口的重复调用, 能缓存的地方继续加缓存, 能合并的接口合并下, 结果并没有显著效果.
开始怀疑是一些用户的数据量太多, 她们回来的时候，一次拉取了太多的数据, 因为程序是 python + gevent, 如果一次拉取很多数据到内存计算, 写的不好会阻塞进程, 还是有可能拉升 latency 的.
而且我推测应该是个别用户导致的, 不然不会只持续一瞬间, 把一组内的 server load by host 看了下, 进一步验证了想法, 在 latency 升高的时候, 都是只有一台 server 的 load变高, 很快又降下去(by group 看的确看不出). 同时查看每台 server 的流量, 的确也能在那个点上看到出问题的 server 流入流量有一个突高, 但 qps 并没什么异常, 确信是拉取了大量数据(其实并不是).
下一步是要想办法捕获到出问题的 request, 光看慢查询也看不出什么名堂, 索性把问题比较大的那一组里所有 server 的 tracing 开到100%(平时只在一个机器上开 20% 的 sampling), 到出现问题的那分钟去一个个接口看, 肯定能看到异常的.
结果还是没能看到异常可疑的, 所有 request 一起慢了下来, 但看 tracing 过程中, 看到有一个用户的一个慢 request 触发了800 多次的 redis 调用, 而且每次都异常慢(20ms+), 吐槽这逻辑写的也真是….先看下 redis 吧,为啥这么慢, slowlog 里却没有相应的 request, 因为前面加了层 twemproxy 来做 sharding, 可能问题在 twemproxy 上, twemproxy 是安装在每台机器本地的，并没有单独的集群, 一直非常稳定, 也没怎么关心过, 那就看下吧, 把那个时间段内 twemproxy 的进程监控数据拉出来看下cpu 占用, 结果发现在那一瞬间 twemproxy 的 cpu 占用竟然大幅下降, 可是整个 server 的 cpu 却是瞬间飙升的? 感觉离原因近了, 同时看下那个瞬间业务进程的cpu占用, 竟然也是瞬间降低的. 那就是什么东西用光了 cpu, 看 syslog, 发现那台机器在那个时间点运行了一个 更新 security patch 的cronjob, 恍然大悟.
原来是那个更新 security patch 的任务从某一天开始失败了, 所以每天都在重复尝试安装 patch，但又一直失败, 所以总是一瞬间拉高 cpu load, 随着时间过去，积累的 patch 越来越多, 所以现象也就越明显, 流量变高也是因为下载包. 失败的原因是 unattended-upgrades 命令在更新某些 service 之后需要配置和重启进程, 要用到 ldconfig 的 start-stop-daemon 命令, 这两命令在 /sbin/ 目录下， sbin 不在 crontab 的默认 PATH里，所以失败了, 坑的是这个命令安装失败返回值还是 0…
这个 job 还是好几个月前设置的, 当时弄完就丢一边了, 完全忘了, 运行时间设置的是 UTC 14 ~ 15 之间的随机一分钟，当时为啥设置了这个点也是很迷, 每台机器时间运行时间不一样也是为了避免同时更新对整体压力太大. 同时因为每一组机器都开了 autoscaling, 新开的机器时间会被重新设置, 所以才会每天时间都不一样.
总结:
- 对 cronjob 的监控不够, 大部分 cronjob 是设置了失败报警的， 这个job没有, 不过因为那个命令失败了返回值也是0,也收不到报警, 但我每天会把 unattented-upgrade 的更新日志上传到 s3 上，但只是上传了，并没有检测日志内容, 如果检测了, 应该早就发现问题了.
- 因为前段时间一直在优化代码, 碰到性能问题思维定势问题在代码上(的确也挺慢的), 忽视了其他更宏观的监控数据.