谁动了我的Cpu资源!
首先我简单解释一下客户所看到的问题。如下图第三行,top统计Cpu总体使用情况,使用了八个指标。这八个指标分别是:用户空间进程(us)、内核空间进程(sy)、高nice值的用户空间进程(ni)、空闲(id)、空闲等待io(wa)、中断上半部(hi)、中断下半部(si)、以及steal时间(st)。理论上来讲这八个指标之和应该是100%。这八个指标当中,id和wa是Cpu空闲时间的统计,这两个值之和越小,说明Cpu越忙碌。客户这台服务器的id与wa之和是0,所以这台服务器的Cpu使用率是100%,其中占比最大的是ni。
除了第三行Cpu总体统计指标之外,top会对Cpu的使用率,从进程维度上进行统计,也就是CPU这一列。因为这台服务器是16核的,所以每个进程(多线程)的Cpu使用率可以超过100%,同时所有进程Cpu使用率之和不能超过上线1600%(平均到每个核是100%)。
这个问题的“见鬼”之处在于,虽然这个系统里运行着787个进程,但这些进程使用Cpu之和,却远小于1600%这个值。
晴天霹雳:问题现场丢失
刚准备深入探究这个问题的时候,不幸的事情发生了。客户这台机器重启了。重启之后问题消失!虽然问题现场丢失了,但客户的质疑没有改变。客户强烈要求我们提供这台服务器Cpu打满的原因。
备注:很多时候,我们在遇到难以解释的问题的时候,往往倾向于把问题归结到和这个问题相关的“黑盒”的部分。这也是为什么,很多客户在遇到不容易解释的现象的时候,会怀疑原因在虚拟化层,或在物理机层,有时候甚至会怀疑阿里云的产品是不是“缺斤短两”了。
nice!
作为技术支持工程师,在没有重现环境的情况下,为了满足客户的需求,我这边做的第一件事情是,搞清楚ni这个指标的计算方法,跟客户沟通这个指标背后的理论知识,然后期望客户能够理解,这个指标跟物理机没有任何关系,纯粹是虚拟机内部行为。
nice是什么
在第一部分,我介绍Cpu八个统计指标的时候,提到了ni是高nice值的用户空间进程的Cpu使用率。nice值是什么呢,简单来讲,nice值代表着一个进程使用Cpu资源的优先程度。每个进程都会有一个与之对应的nice值,nice值越高,那么这个进程使用Cpu的优先级就越低,获得的处理器的时间相比较而言就会越少。而ni这个指标,统计的是系统中,所有nice值大于0的用户空间进程的Cpu的使用率。
一般情况下进程默认的nice值是0,而当有些进程需要更高的执行优先级的时候,我们会减小这些进程的nice值。当然有一些并不需要在高优先级运行的进程,例如我们跑编译程序gcc,去编译一个内核,这个操作预计会花几个小时,那么我们可以增加这个gcc进程的nice值。
linux会把真正的用户模式Cpu使用率拆分成两部分显示,nice值大于0的显示为ni,小于等于0的显示为us。
自己动手跑高ni
这里我们做一个简单的测试去验证上边的理论。我们使用for语句写一个简单的死循环程序loop,然后用objdump看代码编译之后的汇编程序。这段汇编非常简单,前两行准备堆栈指针;第三行初始化一个变量,这个变量位于堆栈上rpb-0x4这个位置;然后第四第五行重复递增这个变量。
00000000004004ed <main>:
4004ed:55 push %rbp
4004ee: 48 89 e5 mov %rsp,%rbp
4004f1:c7 45 fc 00 00 00 00 movl $0x0,-0x4(%rbp)
4004f8: 83 45 fc 01 addl $0x1,-0x4(%rbp)
4004fc: eb fa jmp 4004f8 <main+0xb>
4004fe: 66 90 xchg %ax,%ax
loop进程一旦被调度到一个Cpu上,那么这个Cpu就会被打满。如下两张图,左边是nice值为0的情况,右边是nice值为19的情况。进程nice值可以在图下边NI这一列看到。
下边是Cpu使用率拆分到每个核上的情况。
不满意的客户
我跟客户沟通ni这个指标背后的理论知识和我的结论:这个问题和物理机没有什么关系。对于我的结论,客户是不接受的。客户强调,在机器重启之前,他检查了系统里所有进程的Cpu的使用情况,他非常确定没有发现任何异常。虽然当时系统里有一百多个java进程,但是这些java进程的Cpu使用率都非常低。
时间大法,好!
以前处理系统夯机问题的时候,偶尔会走投无路。想象一下,一个复杂的系统中,运行着上千甚至上万的进程。而夯机则意味着,系统里的这些进程,像一团乱麻一样,纠缠在了一起。这个时候,只有从这些进程中整理出依赖关系,才能知道哪些进程是夯机问题的trouble maker,而哪些进程又是夯机问题的受害者。理清这些关系,大部分情况下,我们是靠理清资源的持有与等待关系。
可惜的是,这种分析方法并不是万能的。系统为了节省管理成本,只会有选择地维护其中某些资源的持有与等待关系。
在我们不能用这种方法分析问题的时候,另外一种方法就派上了用场。这种方法就是分析进程进入等待状态的先后顺序。我们称这种方法叫“时间大法”。
挖矿程序
在因为无法重现问题而“走投无路”的时候,“时间大法”给了我希望。首先,在sa日志里我找到了Cpu达到100%的开始时间是4月29日凌晨6点40。接着,我翻遍了系统里几乎所有的文件,发现有两个配置文件在6点39被创建。而存放这两个配置文件的目录,则有两个非常可疑的库文件libxmr-stak-c.a和libxmr-stak-backend.a。Google这两个文件,发现这是门罗币挖矿程序使用的名字。
还是不满意的客户
当把上边的发现同步给客户的时候,客户还是觉得证据不足。而且客户再次强调,他当时看了所有系统里运行的进程,如果有可疑的进程使用Cpu异常的话,他肯定早发现了。因为客户的坚持,压力再次回到了我们这一边。
隐藏linux进程方法一二三
如果客户所说的是真实情况的话,那么有什么方法可以隐藏linux进程,让客户不能从ps或top的输出中,读到进程信息呢?比较常用的三种方法是:创建进程的时候,把pid设置成为0;直接修改ps和top代码;或者hook libc里readdir和opendir等函数(因为ps和top的实现,直接使用了readdir和opendir等libc库函数,来读取/proc文件及其子目录)。
这个时候我突然想起自己之前曾经看到过的,在6点39被更改的另外一个文件ld.so.preload。第一次检查这个文件的时候,看到这个文件里被写了一条libjdk.so,想当然的以为这个文件和java有关,所以忽略了这条信息。
我知道事情的真相了!
这个时候,事情的全貌就显现出来了。在6点39分,有人给ld.so.preload增加了一个库文件。从那以后,所有的进程,启动的时候都会首先加载这个库,然后再加载其他库。这就产生一个效果,如果进程调用一个外部函数,这个函数的实现本来在其他库文件里,但是这个预先加载的库实现了同样的函数,那么动态链接会先使用预先加载的这个库里定义的这个函数。
记得上一次使用这个技巧的时候,还是多年前在写opengl trace工具的时候。后来转投微软系,linux上这些技巧就淡忘了。基本上来说,使用ld.so.preload,我们可以实现filter类工具,在filter工具中实现过滤,追踪,参数检查等功能。当然为了保证进程正常运行,我们的同名过滤函数,最终还是会调用原来的函数。
验证了一下,系统里所有的进程,因为重启,都加载了libjdk这个库文件到自己的地址空间里。下图是读bash进程/proc/<pid>/maps内容的输出。
libjdk的雕虫小技
这个库libjdk和java没有什么关系,他非常小,实现也非常简单。以致于我们甚至可以通过读汇编来理解它的行为。就如之前猜测的一样,这个库hook了readdir之类的函数,对读取/proc文件夹的操作做了过滤,所以客户在使用top或者ps命令的时候,得到的结果都是被过滤过的结果。这里不会对libjdk汇编代码进行深入分析,但是提供一个strings输出的这个库文件里包含的串。从这些串中,我们也能对这个库的行为猜个大概。
后记
回顾这个问题的处理过程,凭良心讲,这个问题本来并不算是什么疑难杂症。可能抓个core dump,分分钟就能搞定。但两件事情极大的增加了这个问题的排查难度,一个是问题环境丢失,一个是客户的坚持。