加入收藏 | 设为首页 | 会员中心 | 我要投稿 云计算网_泰州站长网 (http://www.0523zz.com/)- 视觉智能、AI应用、CDN、行业物联网、智能数字人!
当前位置: 首页 > 站长学院 > MySql教程 > 正文

携程一次Redis迁移容器后的Slowlog“异常”分析

发布时间:2019-01-11 18:08:12 所属栏目:MySql教程 来源:李剑
导读:副标题#e# 容器化对于Redis自动化运维效率、资源利用率方面都有巨大提升,携程在对Redis在容器上性能和稳定性进行充分验证后,启动了生产Redis迁移容器化的项目。其中第一批次两台宿主机,第二批次五台宿主机。 本次异常是第二批次迁移过程中发现的,排查过
副标题[/!--empirenews.page--]

携程一次Redis迁移容器后Slowlog“异常”分析

容器化对于Redis自动化运维效率、资源利用率方面都有巨大提升,携程在对Redis在容器上性能和稳定性进行充分验证后,启动了生产Redis迁移容器化的项目。其中第一批次两台宿主机,第二批次五台宿主机。

本次“异常”是第二批次迁移过程中发现的,排查过程一波三折,最终得出让人吃惊的结论。

希望本次结论能给遇到同样问题的小伙伴以启发,另外本次分析问题的思路对于分析其他疑难杂症也有一定借鉴作用。

一、问题描述

在某次Redis迁移容器后,DBA发来告警邮件,slowlog>500ms,同时在DBA的慢日志查询里可以看到有1800ms左右的日志,如下图1所示: 

携程一次Redis迁移容器后的Slowlog“异常”分析

图 1

二、分析过程

2.1 什么是Slowlog

在分析问题之前,先简单解释下Redis的slowlog。阅读Redis源码(图2)不难发现,当某次Redis的操作大于配置中slowlog-log-slower-than设置的值时,Redis就会将该值记录到内存中,通过slowlog get可以获取该次slowlog发生的时间和耗时,图1的监控数据也是从此获得。

携程一次Redis迁移容器后的Slowlog“异常”分析

图 2

也就是说,slowlog只是单纯的计算Redis执行的耗时时间,与其他因素如网络之类的都没关系。

2.2 矛盾的日志

每次slowlog都是1800+ms并且都随机出现,在第一批次Redis容器化的宿主机上完全没有这种现象,而QPS远小于第一批次迁移的某些集群,按常理很难解释,这时候翻看CAT记录,更加加重了我们的疑惑,见图3:

携程一次Redis迁移容器后的Slowlog“异常”分析

图 3

CAT是携程根据开源软件(https://github.com/dianping/cat)的定制版本,,用于客户端记录打点的耗时,从图中可以很清晰的看到,Redis打点的最大值367ms也远小于1800ms,它等于是说下面这张自相矛盾图,见图4:

携程一次Redis迁移容器后的Slowlog“异常”分析

图 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所示:

携程一次Redis迁移容器后的Slowlog“异常”分析

图 5

图5的程序大概运行了20分钟后,奇迹出现了,gettimeofday果然有问题,下面是上面程序测试时间打印出来的LOG,如图6:

携程一次Redis迁移容器后的Slowlog“异常”分析

图 6

图6中标红的时间减去1秒等于1813ms,与slowlog时间如此相近!在容器所在的物理机上也测试一遍,发现有同样的现象,排除因容器导致slowlog,希望的曙光似乎就在眼前了,那么问题又来了:

  1. 到底为什么会相差1800ms+呢?
  2. 为什么第一批机器没有这种现象呢?
  3. 为什么之前跑在物理机上的Redis没有这种现象呢?

带着这三个问题,重新审视系统调用gettimeofday获取当前时间背后的原理,发现一番新天地。

三、系统时钟

系统时钟的实现非常复杂,并且参考资料非常多。

简单来说 我们可以通过命令:

  1. 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的频率。

(编辑:云计算网_泰州站长网)

【声明】本站内容均来自网络,其相关言论仅代表作者个人观点,不代表本站立场。若无意侵犯到您的权利,请及时与联系站长删除相关内容!

热点阅读