一次Linux系统1分钟负载5000+的故障排错

时间：2015-09-02 19:09:21 阅读：670 评论：0 收藏：0 [点我收藏+]

标签：strace命令用法进程状态d linux进程分析 linux进程调试 strace调试程序

昨天上午查看Zabbix监控界面时，发现其中一台服务器的进程数量和1分钟负载已经达到了一个非常惊人的数量，Zabbix默认报警数值是进程数量在5分钟平均值大于1000，1分钟系统负载5分钟平均值大于5。

先大体列一下服务器的软硬件信息：

服务器硬件：Dell PowerEdge R720, 2 x Intel(R) Xeon(R) CPU E5-2640 v2 @ 2.00GHz；62.87 GB；PERC H710 SAS RAID5

服务器操作系统：Ubuntu 14.04 LTS，内核：3.13.0-24-generic

图1：Zabbix报警信息（Zabbix消息通知设定的是严重（average）级别以上通过Web短信网关发送短信报警）：

图2：Zabbix上触发器的报警条件

接着不久，就不断有同事反映该服务器响应非常慢，有些应用页面打开很久才出来。由于机房远在天边而且没有远程登录控制台的登录信息（这些信息在客户处），因此只能用xshell通过SSH登录到Linux系统，打开top命令看看系统运行情况，发现当前系统内已经有5800多个进程在运行，其中系统负载（1、5、15分钟）都达到了5400+，但奇怪的是CPU、内存和硬盘IO都并不高，按照常理，如此高的系统负载，CPU和IO等早已经应该是消耗殆尽了，但top显示并没有。

图3.1: Linux系统中的top信息

图3.2 通过iostat、vmstat等命令发现磁盘IO并不高，但系统负载却很高

有个开发人员说pid为14898的java进程并没有分配这么大的内存，这个进程有问题，要求负责编写该程序的另一个开发人员检查程序，当时我想，一个java进程也不至于把系统负载搞的这么高，一定有别的重要的原因没有发现。我按照往常的方法，先查看一下系统中究竟运行了什么样的程序导致系统内进程这么多，因此执行ps –ef | more，查看一下系统内全部进程的运行情况，结果发现此命令根本没法执行，刚输出了不到一个屏幕就卡死在屏幕上了，赶紧复制一个ssh session，继续执行，简单执行ps，看看能不能执行，结果发现ps输出的内容中有大量的ps进程，此处感想还好ps还能运行只是参数不能加太多了。打开top命令，查看一下一个ps命令对应的pid，用top –p pid打开，发现是Zabbix用户执行的ps命令，瞬间感觉不好，别是因为我之前写的Zabbix脚本中有问题导致ps命令没有退出，才导致的系统一分钟负载这么高。

图4：用top查看zabbix用户的进程信息，top –u zabbix

之前有同事电话问我系统中有个java进程无法结束，导致某个应用现在有两个java进程该怎么办，我跟他说试试sudo，结果sudo也不好用，root权限也无法杀死。由于当时在家里有事没在公司因此也没去查什么原因。所以此时，我想用kill杀掉zabbix的ps进程时就遇到了同样的问题，发现ps进程根本杀不死。无论是使用什么样的进程信号，TERM还是KILL都不好用。仔细一看，原来这些进程的状态都成了D状态（上图中S显示的那一列）。

关于D状态：D状态是一种特殊的进程状态代码（PROCESS STATE CODES），其英文示意是Uninterruptible sleep (usually IO)，意思是不可中断的睡眠（通常是由于IO问题引起的），这个IO可能是多种IO，内存、硬盘、网络、总线都是可能的。既然是D状态，那即便是root用户也无法杀死的，因为这样的进程它已经不接受任何进程信号，所以任何方式都将无法将其杀死，只能重新启动服务器。但这问题还没找到根源，不能草草的下结论。

检查Zabbix的用户参数中设定的脚本和命令行，发现大部分命令行有ps，但并不没有任何问题，因此初步排除Zabbix脚本或命令行中存在的问题，如下图所示：

图5：Zabbix用户参数命令行：

因此只能用strace命令找出ps -ef进程卡在那里。命令是strace -o strace_psef.log –f ps –ef

图6：通过strace命令找出命令执行中对系统的调用和收到的信号等信息

通过上图可以发现到open文件/proc/24602/cmdline时遇到了停止（等待），通过cat /proc/24602/cmdline文件发现也无法正确执行，也会卡死。中间发现像netstat，ps -p 24602 –o cmd这种命令都无法使用，甚至ps -p 1 –o cmd都无法显示，由于这些命令都是使用/proc目录下的文件的，因此/proc目录存在问题的可能性非常大，因此继续找原因，继续top -p 24602找出这个进程名称（发现除了top可用以外，pstree同样也是可用的）。

图7.1： ps -p 24602 –o cmd

图7.2：ps -p 1 –o cmd都无法显示

图7.3：附加的疑问，pts数值无法还原至0,

通过top -p 24602命令发现这个pid为14602的进程也是D状态的

图8：通过top -p 24602找出这个进程名称

但是发现top中不能使用c命令查看这个进程的命令行，因此只能进入/proc 目录看看有没有人品能看到该进程使用的一些fd（文件描述符，file descriptor），结果发现人品不错，通过cp复制出来的/proc/24602中找到了task目录下的fd，如下图所示：

图9：通过fd找到这个进程属于哪一个应用里面的

发现出问题的这个应用程序就是前天同事问我的那个，也是研发人员说存在问题的那个应用。经过昨天晚上的重启后发现，此进程的内存占用率依然很高，初步判断是程序的问题，当然也要检查一下IO问题，但是Ubuntu这个系统比较奇怪，系统日志中对此没有任何可用的信息，而java程序中产生的日志太多、信息太杂还是让更专业的开发人员去查吧。

到现在，问题的始作俑者算是找到了，但是为什么是由于IO问题导致还没找到原因，从上午开始写此文到现在，写此文之前已经告诉有关研发人员去分析代码去了，现在去问了下，初步定位在程序内部有一个模块存在死循环（不断的查询远端数据库）导致的，具体怎么改和深入测试还需要一些时间。

图10.1：昨天晚上该程序（图中pid为2988）的内存占用为1.4GB左右，符合常理，但今早上就11GB了（截图之前有过13GB、12GB的记录）