李剑, 携程技术保障中心系统研发部资深软件工程师, 负责 Redis 和 MySQL 的容器化和服务化工作, 以及维护容器宿主机的内核版本, 喜欢深入分析系统疑难杂症.
容器化对于 Redis 自动化运维效率, 资源利用率方面都有巨大提升, 携程在对 Redis 在容器上性能和稳定性进行充分验证后, 启动了生产 Redis 迁移容器化的项目. 其中第一批次两台宿主机, 第二批次五台宿主机.
本次 "异常" 是第二批次迁移过程中发现的, 排查过程一波三折, 最终得出让人吃惊的结论.
希望本次结论能给遇到同样问题的小伙伴以启发, 另外本次分析问题的思路对于分析其他疑难杂症也有一定借鉴作用.
一, 问题描述
在某次 Redis 迁移容器后, DBA 发来告警邮件, slowlog>500ms, 同时在 DBA 的慢日志查询里可以看到有 1800ms 左右的日志, 如下图 1 所示:
图 1
二, 分析过程
2.1 什么是 slowlog
在分析问题之前, 先简单解释下 Redis 的 slowlog. 阅读 Redis 源码 (图 2) 不难发现, 当某次 Redis 的操作大于配置中 slowlog-log-slower-than 设置的值时, Redis 就会将该值记录到内存中, 通过 slowlog get 可以获取该次 slowlog 发生的时间和耗时, 图 1 的监控数据也是从此获得.
图 2
也就是说, slowlog 只是单纯的计算 Redis 执行的耗时时间, 与其他因素如网络之类的都没关系.
2.2 矛盾的日志
每次 slowlog 都是 1800+ms 并且都随机出现, 在第一批次 Redis 容器化的宿主机上完全没有这种现象, 而 QPS 远小于第一批次迁移的某些集群, 按常理很难解释, 这时候翻看 CAT 记录, 更加加重了我们的疑惑, 见图 3:
图 3
CAT 是携程根据开源软件 (https://github.com/dianping/cat) 的定制版本, 用于客户端记录打点的耗时, 从图中可以很清晰的看到, Redis 打点的最大值 367ms 也远小于 1800ms, 它等于是说下面这张自相矛盾图, 见图 4:
图 4
2.3 求助社区
所以说, slowlog 问题要么是 CAT 误报, 要么是 Redis 误报, 但 Redis 使用如此广泛, 并且经过询问 CAT 的维护者说 CAT 有一定的消息丢弃率, 而 Redis 在官方 GitHub issue 中并没有发现类似的 slowlog 情形, 因此我们第一感觉是 CAT 误报, 并在官方 Redis issue 中提问, 试图获取社区的帮助.
很快社区有人回复, 可能是 NUMA 架构导致的问题, 但也同时表示 NUMA 导致 slowlog 高达 1800ms 很不可思议. 关于 NUMA 的资料网上有很多, 这里不再赘述, 我们在查阅相关 NUMA 资料后也发现, NUMA 架构导致如此大的 slowlog 不太可能, 因此放弃了这条路径的尝试.
2.4 豁然开朗
看上去每个方面好像都没有问题, 而且找不到突破口, 排障至此陷入了僵局.
重新阅读 Redis 源代码, 直觉发现 gettimeofday()可能有问题, 模仿 Redis 获取 slowlog 的代码, 写了一个简答的死循环, 每次 Sleep 一秒, 看看打印出来的差值是否正好 1 秒多点, 如图 5 所示:
图 5
图 5 的程序大概运行了 20 分钟后, 奇迹出现了, gettimeofday 果然有问题, 下面是上面程序测试时间打印出来的 LOG, 如图 6:
图 6
图 6 中标红的时间减去 1 秒等于 1813ms, 与 slowlog 时间如此相近! 在容器所在的物理机上也测试一遍, 发现有同样的现象, 排除因容器导致 slowlog, 希望的曙光似乎就在眼前了, 那么问题又来了:
1, 到底为什么会相差 1800ms + 呢?
2, 为什么第一批机器没有这种现象呢?
3, 为什么之前跑在物理机上的 Redis 没有这种现象呢?
带着这三个问题, 重新审视系统调用 gettimeofday 获取当前时间背后的原理, 发现一番新天地.
三, 系统时钟
系统时钟的实现非常复杂, 并且参考资料非常多.
简单来说 我们可以通过
cat /sys/devices/system/clocksource/clocksource0/current_clocksource
命令来获取当前系统的时钟源, 携程的宿主机上都是统一 Time Stamp Counter(TSC):80x86 微处理器包括一个时钟输入插口, 用来接收来自外部振荡器的时钟信号, 从奔腾 80x86 微处理器开始, 增加了一个计数器.
随着每增加一个时钟信号而加一, 通过 rdtsc 汇编指令也可以去读 TSC 寄存器, 这样如果 CPU 的频率是 1GHz,TSC 寄存器就能提供纳秒级别的计时精度, 并且现代 CPU 通过 FLAG constant_tsc 来保证即使 CPU 休眠也不影响 TSC 的频率.
当选定 TSC 为时钟源后, gettimeofday 获取墙上时钟 (wall-clock) 正是从 TSC 寄存器读出来的值转换而来, 所谓墙上时钟主要是参照现实世界人们通过墙上时钟获取当前时间, 但是用来计时并不准确, 可能会被 NTP 或者管理员修改.
那么问题又来了, 宿主机的时间没有被管理员修改, 难道是被 NTP 修改? 即使是 NTP 来同步, 每次相差也不该有 1800ms 这么久, 它的意思是说难道宿主机的时钟每次都在变慢然后被 NTP 拉回到正常时间? 我们手工执行了下 NTP 同步, 发现的确是有很大偏差, 如图 7 所示:
图 7
按常识时钟正常的物理机与 NTP 服务器时钟差异都在 1ms 以内, 相差 1s + 绝对有问题, 而且还是那个老问题, 为什么第一批次的机器上没有问题?
四, 内核 BUG
两个批次宿主机一样的内核版本, 第一批没问题而第二批有问题, 差异只可能在硬件上, 非常有可能在计时上, 翻看内核的 commit log 终于让我们发现了这样的 commit, 如图 8 所示:
图 8
该 commit 非常清楚指出, 在 4.9 以后添加了一个宏定义 INTEL_FAM6_SKYLAKE_X, 但因为搞错了该类型 CPU 的 crystal frequency 会导致该类型的 CPU 每 10 分钟慢 1 秒钟.
这时再看看我们的出问题的第二批宿主机 xeon bronze 3104 正好是 skylake-x 的服务器, 影响 4.9-4.13 的内核版本, 宿主机内核 4.10 正好中招.
并且 NTP 每次同步间隔 1024 秒约慢 1700ms, 与 slowlog 异常完全吻合, 而第一批次的机器 CPU 都不是 SKYLAKE-X 平台的, 避开了这个 BUG, 迁移之前 Redis 所在的物理机内核是 3.10 版本, 自然也不存在这个问题. 至此, 终于解开上面三个疑惑.
五, 总结
5.1 问题根因
通过上面的分析可以看出, 问题根因在于内核 4.9-4.13 之间 skylake-x 平台 TSC 晶振频率的代码 BUG, 也就是说同时触发这两个因素都会导致系统时钟变慢, 叠加上 Redis 计时使用的 gettimeofday 会容易被 NTP 修改导致了本文开头诡异的 slowlog"异常". 有问题的宿主机内核升级到 4.14 版本后, 时钟变慢的 BUG 得到了修复.
5.2 怎么获取时钟
对于应用需要打点记录当前时间的场景, 也就是说获取 Wall-Clock, 可以使用 clock_gettime 传入 CLOCK_REALTIME 参数, 虽然 gettimeofday 也可以实现同样的功能, 但不建议继续使用, 因为在新的 POSIX 标准中该函数已经被废弃.
对于应用需要记录某个方法耗时的场景, 必须使用 clock_gettime 传入 CLOCK_MONOTONIC 参数, 该参数获得的是自系统开机起单调递增的纳秒级别精度时钟, 相比 gettimeofday 精度提高不少, 并且不受 NTP 等外部服务影响, 能准确更准确来统计耗时 (java 中对应的是 System.nanoTime), 也就是说所有使用 gettimeofday 来统计耗时(java 中是 System.currenttimemillis) 的做法本质上都是错误的.
来源: https://juejin.im/entry/5bee09edf265da61380ecc11