投递人 itwriter 发布于 2018-06-15 10:31 原文链接 [收藏] « »

  阿里妹导读:对于工程师来说,排查不一样的问题,往往会有不一样的难点。有的问题难在重现,但只要能重现一次,那么问题就会迎刃而解;有的问题难在调试,比如排查一个刷卡机内的 SD 卡,通过数据线连接到电脑上出现文件系统不可见的问题。这可能需要研究刷卡机嵌入式操作系统,和桌面操作系统的文件系统、存储系统,以及设备管理三层的实现,才能最终定位到问题。

  对于阿里云技术支持的同学来说,还有另外一种比较特别的技术难题。这类问题的难度来源于客户的坚持:当我们的客户对一个我们自己看起来无关紧要的问题盘根问底的时候,这个问题就会变得非常棘手。今天,阿里技术专家声东,将和大家分享一个经典案例。

  谁动了我的 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,分分钟就能搞定。但两件事情极大的增加了这个问题的排查难度,一个是问题环境丢失,一个是客户的坚持。

  当然如果不是问题环境丢失,那么我也不会去尝试其他的排查思路,如果不是客户的坚持,我也不会做到把汇编代码都拿出来做证据的这种程度。客户的高要求,不断的敦促,是我们不断提升服务能力的重要驱动力。

24小时阅读排行

    最新新闻

      相关新闻