【云吞铺子】性能抖动剖析（二）

网络抖动案例是一类处理难度较大的问题&＃xff0c;原因主要是很多抖动发生的频率不高&＃xff0c;且持续时间非常短极限情况可能仅有100ms以下&＃xff0c;而很多用户的业务应用对实时性要求非常高&＃xff0c;因此对此类在百毫秒的延迟也会非常敏感。本文记录的是一次多团队协作处理的抖动问题的过程&＃xff0c;由于用户的执着&＃xff0c;也使得我们在这个案例分析得较为深入&＃xff0c;希望对大家今后的此类案例的处理有所启发。

让我们先来看看问题现象吧&＃xff0c;用户的应用日志记录了百毫秒甚至1-2秒级别的延迟&＃xff0c;而且发生较为频繁&＃xff0c;由于业务的实时性要求较高&＃xff0c;因此对业务的影响较大&＃xff0c;当然其中也影响到了用户对迁云的信心。

在用户通过应用层面的排查怀疑问题来源于虚拟网络环境的时候&＃xff0c;我们需要做的第一件事就是首先要将问题简单化。这一步是非常必要的&＃xff0c;因为我们对用户的应用不可能有非常深入的了解&＃xff0c;所以用户的应用日志具体含义和记录方式对我们来说更像黑盒。我们所要做的是将问题现象转移到我们常见的系统组件上来&＃xff0c;比如简单到ping。所以我们第一件所做的事情就是编写脚本进行两台机器的内网互ping&＃xff0c;并将每次ping的延迟记录到文件。选择ping当然也是由于ping的间隔是可以设置到百毫秒的&＃xff0c;比较容易说明问题。

在互ping的测试中我们确实发现有百毫秒以上的延迟&＃xff0c;那么随后我们为了排除物理网络的影响&＃xff0c;选择一台机器进行对网关的ping测试&＃xff0c;同样发现了类似的延迟&＃xff1a;

来看看上面的ping测试结果吧&＃xff0c;初看也仅仅是一些百毫秒延迟的集中发生而已&＃xff0c;但是仔细观察就会发现每次发生都有这样的情况&＃xff0c;就是延迟在一组连续的ping上发生的&＃xff0c;并且延迟是倒序排列的。那么这意味着什么呢&＃xff1f;

通过以上的ping测试我们把问题简单化到了ping网关延迟上&＃xff0c;但是上面如此规律的测试结果的具体含义是什么。首先他意味着并没有丢包发生&＃xff0c;所以的ICMP请求都被系统发出并且收到回复&＃xff0c;但是这样的倒序排列&＃xff0c;更像是在问题时间段内所有的回复都没有被第一时间处理&＃xff0c;而是突然在800ms之后系统处理了所有之前发生回复&＃xff0c;因此才会产生这样的现象。那么我们此时可以有一个假设&＃xff0c;在这800ms之前系统停止了对网络包的处理。那么什么样的情况会导致系统停止对网络包的处理呢&＃xff1f;

答案是中断禁用&＃xff0c;硬件中断是系统处理网络包的第一也是必须步骤&＃xff0c;中断禁用会导致系统的软中断和中断都不能在CPU上发生&＃xff0c;从而使得当前在CPU上运行的指令是无法被打断的&＃xff0c;这经常被用于一些可能存在竞争风险的内核代码片段上&＃xff0c;这些代码片段可能会因为被中断打断而导致数据不同步甚至损坏。

在当时我们内核团队甚至通过编写示例驱动&＃xff0c;通过记录timer函数在一段时间内未能触发来验证了中断禁用的发生。那么庞大的内核代码中究竟是哪一部分的代码导致了这样的问题呢&＃xff1f;

在这段分析过程中&＃xff0c;我们做了大量实验&＃xff0c;比如通过编写内核驱动来禁用中断&＃xff0c;测试各类内核追踪方法是否能获得更进一步的信息&＃xff0c;如禁用中断的堆栈&＃xff0c;但是很可惜&＃xff0c;目前尚无很好的方法在不影响业务的情况下较轻量级地获得禁用中断时的内核堆栈&＃xff0c;原理也很简单&＃xff0c;硬件中断本身优先级要高于一般进程和软中断&＃xff0c;在其被禁用之后自然普通软件层面的追踪方法也不起作用了。

然而问题就隐藏在一类系统的内存资源上&＃xff0c;即系统的slab占用量相比正常系统要高出不少&＃xff1a;

我们可以看到其中dentry在slab中的占用量达到了非常高的程度&＃xff0c;dentry是内存中表示目录和文件的对象&＃xff0c;作为与inode的链接存在&＃xff0c;在一般情况下如此高数字的dentry项可能代表这系统有大量被打开的文件。然而此时我们首先需要解释大量的dentry项与禁用中断的关系&＃xff0c;我们来看看2.6内核的这一段代码&＃xff1a;

这是一段计算slab总量的代码&＃xff0c;我们注意到它是以遍历链表的方式来统计slab总量的&＃xff0c;而在进入链表之前调用了spin_lock_irq函数&＃xff0c;我们来看看它的实现&＃xff1a;

static inline void __spin_lock_irq(spinlock_t *lock)
{
local_irq_disable();


于是我们可以确认在统计slab信息的时候&＃xff0c;系统的行为是首先禁用中断&＃xff0c;然后遍历链表统计slab&＃xff0c;最后再次启用中断。那么整个禁用中断的时间将取决于链表中对象的个数&＃xff0c;如果其对象数量惊人&＃xff0c;很可能就会导致禁用中断时间过长。

验证问题也非常简单&＃xff0c;我们可以主动运行cat /proc/slabinfo在获取slab信息&＃xff0c;那么以上函数也将会被调用&＃xff0c;同时观察ping测试输出符合以上问题点的情况&＃xff0c;即可以大致确认问题原因了。

此时我们已经有了可以暂时缓解问题的方法了&＃xff0c;对dentry项是作为文件系统缓存的一部分存在的&＃xff0c;也就是真正的文件信息是存放于磁盘上的&＃xff0c;dentry只不过是在系统打开文件系统缓存在内存中的对象而已&＃xff0c;即使缓存被清空&＃xff0c;未来系统一样可以通过读取磁盘文件来重新生成dentry信息&＃xff0c;因此我们可以通过类似echo 2 > /proc/sys/vm/drop_caches && sync的方式来释放缓存&＃xff0c;缓解问题。

详细排查过程请查看视频。