一次PHP脚本执行卡住的问题排查记录

原文连接：http://tabalt.net/blog/php-sc...

最近从监控上发现，咱们一个服务的一台机器负载比同机房的其余机器要高，而流入流出流量没有差异，进一步查看发现每一个机房都有一台机器存在相同的现象，梳理后发现有问题的这些机器相比正常的机器多跑了一些PHP脚本，因而猜想是执行脚本出问题致使。

登陆机器后执行top命令，果真发现存在一个CPU占用较高的PHP进程，而后执行下列命令，发现存在一个由crontab启动的执行了很长时间的PHP脚本：

ps aux | grep 'php' | grep -v 'php-fpm'

因为以前也遇到过PHP脚本执行卡住的相似状况，当时的怀疑是跨机房的Mysql查询在网络抖动时致使Mysql链接卡住了，因而理所固然的将全部卡住的进程都kill掉了，再从负载上看机器立刻就恢复正常了，因而心满意足的跑去干别的了。

过了一段时间，刷了下监控，发现问题又出现了，注释掉crontab并kill掉进程后，手动执行问题脚本，居然能稳定复现问题！看来是把问题想得太简单了，尝试用strace命令看下卡住的进程当前究竟在干什么：

[tabalt@localhost ~] sudo strace -p 13793
Process 13793 attached - interrupt to quit

什么输出都没有！再用netstat看下这个进程是否打开了什么端口：

[tabalt@localhost ~] sudo netstat -tunpa | grep 13793
tcp        0      0 192.168.1.100:38019        192.168.1.101:3306        ESTABLISHED 13793/php
tcp        0      0 192.168.1.100:47107        192.168.1.102:6379        CLOSE_WAIT  13793/php

能够看到进程打开了两个端口，分别与Mysql和Redis创建了链接，而且处于链接创建（ESTABLISHED）和对方主动关闭链接（CLOSE_WAIT）的状态；初看确实像是和数据库的链接卡住了，可是由于吃过亏上过当，我们使用tcpdump抓包看进程和数据库之间的交互：

tcpdump -i eth0 host 192.168.1.101 and port 3306 -w ~/mysql.cap

抓了好一会，~/mysql.cap 文件中却也没有任何输出，难道进程和Mysql之间已经没有任何交互了？那为何链接创建没有关闭呢？看来只能从头追踪一下脚本的执行状况了：

• 首先为了能来得及strace到进程，在PHP脚本最开始的时候输出进程的pid并sleep 10s:

  echo getmypid();
  sleep(10);

• 而后启动tcpdump准备抓包本机和Mysql的交互过程。

• 最后执行PHP脚本，并复制输出的pid后在新窗口中执行strace命令。

这下strace和tcpdump都有内容了！从strace结果看recvfrom以后再也不有poll，但并无看出来有什么不对：

//...
poll([{fd=4, events=POLLIN|POLLERR|POLLHUP}], 1, 1471228928) = 1 ([{fd=4, revents=POLLIN}])
recvfrom(4, "://xxx.com/\0\0\23jiadia"..., 271, MSG_DONTWAIT, NULL, NULL) = 271
poll([{fd=4, events=POLLIN|POLLERR|POLLHUP}], 1, 1471228928) = 1 ([{fd=4, revents=POLLIN}])
recvfrom(4, "_b?ie=UTF8&node=658390051\0\0008www."..., 271, MSG_DONTWAIT, NULL, NULL) = 206

再从抓包结果看，执行了两条SQL查询语句以后，进程没有再次发送查询请求的包，从程序记录SQL语句日志中，也发现确实只执行了两条：

select * from sites where type = 1 limit 50;
select * from sites where type = 2 limit 50;

但从这些现象中，仍然没有能看出任何端倪，只好祭出终极大法：输出调试！大概看了下代码，并在关键地方添加输出语句，因而代码看起来以下：

echo("start foreach\n");
foreach($types as $type)
{
    echo("foreach $type\n");
    $result[$type] = $this->getSites($type);
}
echo("end foreach\n");

执行后输出以下，查询type为2的网址时卡住了：

start foreach
foreach 1
foreach 2

开始怀疑调用的getSites()方法有问题，代码以下:

$sites = array();   // 省略从数据库查询的代码
$siteNum = 8;       // 省略从配置读的代码
$urlKeys = $result = array();
for($i = 0; $i < $siteNum; $i++)
{
    do {
        $site = array_shift($sites);
        $urlKey = md5($site['url']);
    } while(array_key_exists($urlKey, $urlKeys));

    $urlKeys[$urlKey] = 1;
    $result[] = $site;
}
return $result;

原来这里为了实现拿8个不重复的网址写了2个循环，若是结果中不重复的网址只有7个就会有一个空，少于7个就会有死循环！因而查了下type为2的网址个数，果真是只有6个！

总结一下，该问题从发现到解决花了大概1天时间，虽然最后证实是低级的代码BUG致使，可是整个排查过程仍是挺有收获的，最开始的想固然证实是很是肤浅的，过程当中tcpdump和strace的结果也已经很能说明问题了，对各个工具的应用应该要更加熟练，工具的结果也要深刻分析。

若是文章对您有帮助，欢迎打赏， 您的支持是我码字的动力！

原文连接：http://tabalt.net/blog/php-sc...