一次PHP腳本執行卡住的問題排查記錄
最近從監控上發現，我們一個服務的一臺機器負載比同機房的其他機器要高，而流入流出流量沒有差別，進一步查看發現每個機房都有一臺機器存在相同的現象，梳理后發現有問題的這些機器相比正常的機器多跑了一些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腳本。
這下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 order by weight desc limit 50;
select * from sites where type = 2 order by weight desc 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 = array();
for($i = 0; $i < $siteNum; $i++)
{
do {
$site = array_shift($sitesData);
$urlKey = md5($site['url']);
} while(array_key_exists($urlKey, $url_keys));
$urlKeys[$urlKey] = 1;
$result[] = $site;
}
return $result;
原來這里為了實現拿8個不重復的網址寫了2個循環，如果結果中不重復的網址只有7個就會有一個空，少于7個就會有死循環！于是查了下type為2的網址個數，果然是只有6個！
總結一下，該問題從發現到解決花了大概1天時間，雖然最后證明是低級的代碼BUG導致，但是整個排查過程還是挺有收獲的，最開始的想當然證明是非常膚淺的，過程中tcpdump和strace的結果也已經很能說明問題了，對各個工具的應用應該要更加熟練，工具的結果也要深入分析。
來自：http://tabalt.net/blog/php-script-execution-stuck-record/