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

容器化对付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的频率。

（编辑：河北网）

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