php-cgi占用cpu100%的一次排障之旅&poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)

先说下我们网站的架构,由于目前网站访问量不是很大，但是由于最近公司网站要推广，所以将网站由单机切换成前端用nginx做负载均衡，带动两台web服务器，所有网页和静态文件都通过NFS共享调用，NFS服务装在其中的一个web服务器上，后端用mysql主从的方式，是很典型的架构。

 

切换成这个架构才2天，就收到nagios的报警，报警信息显示有一台web服务器负载很高，于是通过SecureCRT登录到服务器上，用top命令看了一下，发现有几个php-cgi进程占用了大量的CPU，如下：

13889 www       25  0  228m  14m 9344 S 100.4  0.1 14:51.22 php-cgi                                                                               

13882 www       25  0  227m  13m 9284 S 100.1  0.1 10:53.18 php-cgi                                                                                

13924 www       25  0  227m 9936 5732 S 100.1  0.1 23:20.80 php-cgi                                                                               

13927 www       25  0  226m 5228 2064 R 100.1  0.0 24:44.24 php-cgi                                                                               

13827 www       25   0 228m  15m  10m R 99.7 0.1  12:57.60 php-cgi                                                                                

13900 www       25  0 228m  19m  13m R 99.7 0.1   9:03.09 php-cgi

由上面的截图我们可以看出那几个php-cgi进程不但占用了大量的CPU，而且运行时间非常长，本来php-cgi接到一个请求运行很快的，怎么这几个运行那么久还没释放？于是采用命令ls -l /proc/13827/fd/查看这个长时间的进程到底在干什么事情，结果如下：

lrwx------ 1 www www 64 Dec 11 12:030 -> socket:[68444030]

l-wx------ 1 www www 64 Dec 11 12:031 -> pipe:[68444057]

l-wx------ 1 www www 64 Dec 11 12:032 -> pipe:[68444058]

lrwx------ 1 www www 64 Dec 11 12:033 -> socket:[68468225]

lrwx------ 1 www www 64 Dec 11 12:034 -> socket:[68469788]

lrwx------ 1 www www 64 Dec 11 12:035 -> socket:[68457928]

看到里面没有打开文件或者写入文件，这个进程没干什么事情，比较奇怪，然后采用strace命令跟踪下看看这个进程在做什么东西呢？

strace -p 13827

poll([{fd=4, events=POLLIN}], 1,0)     = 0 (Timeout)

select(5, [4], [4], [], {15, 0})        = 1 (out [4], left {15, 0})

poll([{fd=4, events=POLLIN}], 1,0)     = 0 (Timeout)

select(5, [4], [4], [], {15, 0})        = 1 (out [4], left {15, 0})

poll([{fd=4, events=POLLIN}], 1,0)     = 0 (Timeout)

select(5, [4], [4], [], {15, 0})        = 1 (out [4], left {15, 0})

poll([{fd=4, events=POLLIN}], 1,0)     = 0 (Timeout)

select(5, [4], [4], [], {15, 0})        =1 (out [4], left {15, 0})

poll([{fd=4, events=POLLIN}], 1,0)     = 0 (Timeout)

select(5, [4], [4], [], {15, 0})        = 1 (out [4], left {15, 0})

poll([{fd=4, events=POLLIN}], 1,0)     = 0 (Timeout)

select(5, [4], [4], [], {15, 0})        = 1 (out [4], left {15, 0})

poll([{fd=4, events=POLLIN}], 1,0)     = 0 (Timeout) …….

可以看出，这个进程不断的超时，到底为何会超时呢？？？看来需要从php-cgi的日志中查找问题了，由于原来php-fpm.conf配置的超时时间为0，也就是不设置超时时间。于是先将php-fpm.conf的超时时间设置成5s，然后超过5s的php-cgi的请求就会记录到php的慢日志中，设置如下：

     <value name="request_slowlog_timeout">3s</value>

     <value name="slowlog">logs/slow.log</value>

设置完成，利用命令/usr/local/php/sbin/php-fpm restart重启php-fpm，过一会查看slow.log的内容发现很多如下内容：

script_filename =/data/htdocs/bbs.hrloo.com/apl.php
[0x00007fffb060fd70] file_get_contents() /data/htdocs/bbs.hrloo.com/apl.php:10

查看/data/htdocs/bbs.hrloo.com/apl.php第十行的内容如下：

echo file_get_contents('http://121.10.108.227:86/yh.asp');

网上查了一下发现了介绍php这个函数当里面网址响应很慢的时候就会出现CPU占用很高的情况，而且会一直卡住，不会超时，再看看这个链接，访问一下指向到了一个小说网站，是别人攻击后嵌入的，将这个文件还原后恢复正常。奇怪的是那个安装NFS的web服务器却不会出现那个问题，看来是由于本来那个站点又慢，通过NFS调用就更慢了，因此出现了这个故障。感谢这次故障，才发现了这个严重的问题。

file_get_contents()导致nginx出现504

Linux
Nginx+PHP-CGI(php-fpm) 的Web环境
突然发现系统负载上升，top 查看后发现很多 php-cgi 进程 CPU 使用率接近100%
找其中一个 CPU 100% 的 php-cgi 进程的 PID，用strace -p 10747跟踪，结果发现以下结果：
select(7, [6], [6], [], {15, 0}) = 1 (out [6], left {15, 0})
poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)
select(7, [6], [6], [], {15, 0}) = 1 (out [6], left {15, 0})
poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)
select(7, [6], [6], [], {15, 0}) = 1 (out [6], left {15, 0})
poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)
select(7, [6], [6], [], {15, 0}) = 1 (out [6], left {15, 0})
poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)
select(7, [6], [6], [], {15, 0}) = 1 (out [6], left {15, 0})
poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)
select(7, [6], [6], [], {15, 0}) = 1 (out [6], left {15, 0})
poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)
select(7, [6], [6], [], {15, 0}) = 1 (out [6], left {15, 0})
poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)
select(7, [6], [6], [], {15, 0}) = 1 (out [6], left {15, 0})
poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)
select(7, [6], [6], [], {15, 0}) = 1 (out [6], left {15, 0})
poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)
select(7, [6], [6], [], {15, 0}) = 1 (out [6], left {15, 0})
poll([{fd=6, events=POLLIN}], 1, 0) = 0 (Timeout)

几乎可以肯定是file_get_contents()导致的问题，
原因是：file_get_contents的目标网站如果反应过慢，file_get_contents就会一直卡在那里不会超时，
我们知道php.ini 里面max_execution_time 可以设置 PHP 脚本的最大执行时间，但是，在 php-cgi(php-fpm) 中，该参数不会起效。真正能够控制 PHP 脚本最大执行时间的是 php-fpm.conf 配置文件中的以下参数：

The timeout (in seconds) for serving a single request after which the worker process will be terminated  
Should be used when 'max_execution_time' ini option does not stop script execution for some reason  
'0s' means 'off'  
<value name="request_terminate_timeout">0s</value> 

　默认值为 0 秒，也就是说，PHP 脚本会一直执行下去。这样，当所有的 php-cgi 进程都卡在 file_get_contents() 函数时，这台 Nginx+PHP 的 WebServer 已经无法再处理新的 PHP 请求了，Nginx 将给用户返回“502 Bad Gateway”。修改该参数，设置一个 PHP 脚本最大执行时间是必要的，但是，治标不治本。例如改成 30s，如果发生 file_get_contents() 获取网页内容较慢的情况，这就意味着 150 个 php-cgi 进程，每秒钟只能处理 5 个请求，WebServer 同样很难避免“502 Bad Gateway”。

　　要做到彻底解决，不妨重新封装一下file_get_contents函数：

1 2 3 4 5 6 7 8 9

function _file_get_content( $str ) { $ctx = stream_context_create( array (      'http' => array (          'timeout' => 10 //设置一个超时时间，单位为秒          )      )  );  return file_get_contents ( $str , 0, $ctx );  }

如此 用_file_get_content代替直接使用file_get_contents 问题解决。