一次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...