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 httpdroot      3553  0.0  2.6 312672 13476 ?        Ss   Aug03   0:03 /usr/local/apache2/sbin/httpd -k restartwww       4759  0.0  4.4 320664 22584 ?        S    20:31   0:00 /usr/local/apache2/sbin/httpd -k restartwww       4760  0.0  3.2 316548 16672 ?        S    20:31   0:00 /usr/local/apache2/sbin/httpd -k restartwww       4761  0.0  3.2 316548 16672 ?        S    20:31   0:00 /usr/local/apache2/sbin/httpd -k restartwww       4762  0.0  3.2 316548 16672 ?        S    20:31   0:00 /usr/local/apache2/sbin/httpd -k restartwww       4763  0.1  4.9 319552 25036 ?        S    20:31   0:00 /usr/local/apache2/sbin/httpd -k restartwww       4766  0.0  3.2 316548 16672 ?        S    20:32   0:00 /usr/local/apache2/sbin/httpd -k restartroot      4890  0.0  0.1  61188   732 pts/3    R+   20:35   0:00 grep httpdwww      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) = 0write(107, "get APPS_SCREEN_API_CURR_TOKEN \r"..., 33) = 33read(107, 0x14130e48, 8196)             = -1 EAGAIN (Resource temporarily unavailable)poll([{fd=107, events=POLLIN}], 1, 200) = 1 ([{fd=107, revents=POLLIN}])read(107, "VALUE APPS_SCREEN_API_CURR_TOKEN"..., 8196) = 107write(107, "quit\r\n", 6)               = 6read(107, 0x14130e48, 8196)             = -1 EAGAIN (Resource temporarily unavailable)poll([{fd=107, events=POLLIN}], 1, 200) = 1 ([{fd=107, revents=POLLIN}])read(107, "", 8196)                     = 0shutdown(107, 2 /* send and receive */) = 0close(107)                              = 0open("/dev/random", O_RDONLY)           = 107read(107,

?

注意，最后一行输出并不完整，说明Apache进程堵塞在read系统调用上。read的对象是 /dev/random，看起来与随机数有关。但是，哪里的代码会用到随机数呢？

?

找到关键代码

根据前面输出的IP和PORT，包括调用参数，我们确定这是在访问memcached。于是，顺藤摸瓜，找到访问memcached之后的一段代码：

?

$size = mcrypt_get_iv_size (MCRYPT_BLOWFISH,MCRYPT_MODE_ECB); $iv = mcrypt_create_iv($size, MCRYPT_DEV_RANDOM); $m = mcrypt_ecb (MCRYPT_BLOWFISH,$key,$dmcryptText,MCRYPT_DECRYPT,$iv);

?

其中，第二行代码，出现了RANDOM，查了一下php手册，当第二个参数为MCRYPT_DEV_RANDOM时，mcrypt_create_iv存在堵塞的可能性。MCRYPT_DEV_URANDOM则不会阻塞。

?

线上故障得以解决

虽然还不知道具体原因，但是本着快速解决问题的原则，决定替换参数立刻上线。

果然，问题得以解决，刷新页面时，从未如此酣畅淋漓！

?

分析故障现象

线上的Apache进程很大的概率会走到上述代码，因此很可能被block一段时间。于是，当前页面就会很慢。

当所有Apache进程都被block时，后续请求必须等待空闲的Apache进程，因此后续页面都将变得很慢。

由于Apache进程unblock的时间不可确定，因此后续页面的等待时间也时长时短。

?

深挖原因

虽然问题解决，但是本质原因还没搞清楚：为什么MCRYPT_DEV_RANDOM会堵塞，而MCRYPT_DEV_URANDOM从不会堵塞。

google了一下/dev/random，维基百科一如既往的靠谱：

14 楼 mfkvfn 2012-12-05 虽然不用php，不过看着好像很牛的样子，顶1下。