日期:2014-05-16  浏览次数:20716 次

Linux随机数发生器导致Apache进程全部Block的问题追查

今天上午,运营同事报告一个严重故障,现象是网站页面速度非常慢,基本不可用。工程师开始追查问题。

首先介绍一下系统架构:前端 Apache,中间PHP,后端MySQL,经典的LAMP架构。

?

猜测数据库出现性能问题

?

第一反应,怀疑数据库数据量太大。我们一直定期清理数据库,保证单表数据量在一定范围内。而这段时间一直没有清理,数据量可能过大。立刻执行delete语句,单表减少100W条记录。但是,问题依旧。

后来,DBA同学发现慢查询,存在filesort。果断增加索引,慢查询消失。但是,问题依旧。

无奈之下,怀疑机房网络问题。但是其他产品线都没有问题,网络组也没有故障通报。因此,否决这种可能。

?

线下环境复现故障

时间已经到了下午5点,决定重新梳理思路,反复观察故障现象。总结几点:

  • 页面响应速度不稳定,或慢或快,或稍慢,或奇慢,缺少一种规律性
  • 甚至,在一位同事的电脑上,刷新几次都很快。

由于没有权限看线上日志(其实代码中也没有打任何日志),无法从日志中获取有效信息。为了方便调试,我们决定在线下环境部署代码并尝试复现故障。

结果,线下环境中,故障基本必现。可以肯定,与网络环境没有关系,与线上的memcahced/mysql的运行状况也没有关系。

我们在PHP代码的不同位置插入调试代码?echo ‘xxx’;exit; ?, 试图确定何处代码在堵塞。

我们惊奇的发现,当一个页面处于等待响应的状态时,后续页面必然也在等待。而且,后续页面没有执行任何PHP代码。我们推断,Aapache进程block住了!

?

Strace Apache进程

为了搞清楚Apache进程block在什么地方,我们使用strace工具观察Apache进程的系统调用。

先找出Apache的进程号。

?

[root@vm11030032 ~]# ps aux|grep httpd
root      3553  0.0  2.6 312672 13476 ?        Ss   Aug03   0:03 /usr/local/apache2/sbin/httpd -k restart
www       4759  0.0  4.4 320664 22584 ?        S    20:31   0:00 /usr/local/apache2/sbin/httpd -k restart
www       4760  0.0  3.2 316548 16672 ?        S    20:31   0:00 /usr/local/apache2/sbin/httpd -k restart
www       4761  0.0  3.2 316548 16672 ?        S    20:31   0:00 /usr/local/apache2/sbin/httpd -k restart
www       4762  0.0  3.2 316548 16672 ?        S    20:31   0:00 /usr/local/apache2/sbin/httpd -k restart
www       4763  0.1  4.9 319552 25036 ?        S    20:31   0:00 /usr/local/apache2/sbin/httpd -k restart
www       4766  0.0  3.2 316548 16672 ?        S    20:32   0:00 /usr/local/apache2/sbin/httpd -k restart
root      4890  0.0  0.1  61188   732 pts/3    R+   20:35   0:00 grep httpd
www      30809  0.0  6.0 327304 30772 ?        T    16:43   0:01 /usr/local/apache2/sbin/httpd -k restart
??

然后,随便挑一个进程号,strace上去:strace -p 4759

接着,反复刷新页面,总有一个请求会落到PID为4759的进程上。

终于,一个请求过来,快速刷屏,戛然而止,输出内容定格在:

?

connect(107, {sa_family=AF_INET, sin_port=htons(7634), sin_addr=inet_addr("10.73.19.246")}, 16) = -1 EINPROGRESS (Operation now in progress)
poll([{fd=107, events=POLLOUT}], 1, 1000) = 1 ([{fd=107, revents=POLLOUT}])
connect(107, {sa_family=AF_INET, sin_port=htons(7634), sin_addr=inet_addr("10.73.19.246")}, 16) = 0
write(107, "get APPS_SCREEN_API_CURR_TOKEN \r"..., 33) = 33
read(107, 0x14130e