《PHP編程：記錄一次排查PHP腳本執(zhí)行卡住的問題》要點(diǎn)：
本文介紹了PHP編程：記錄一次排查PHP腳本執(zhí)行卡住的問題，希望對您有用。如果有疑問，可以聯(lián)系我們。

發(fā)現(xiàn)問題PHP編程

最近忽然從監(jiān)控中發(fā)現(xiàn),我們一個服務(wù)的一臺機(jī)器負(fù)載比同機(jī)房的其他機(jī)器要高,而流入流出流量沒有差別,進(jìn)一步查看發(fā)現(xiàn)每個機(jī)房都有一臺機(jī)器存在相同的現(xiàn)象,梳理后發(fā)現(xiàn)有問題的這些機(jī)器相比正常的機(jī)器多跑了一些PHP腳本,于是猜測是執(zhí)行腳本出問題導(dǎo)致.PHP編程

解決問題PHP編程

登錄機(jī)器后執(zhí)行top命令,果然發(fā)現(xiàn)存在一個CPU占用較高的PHP進(jìn)程,然后執(zhí)行下列命令,發(fā)現(xiàn)存在一個由crontab啟動的執(zhí)行了很長時間的PHP腳本：PHP編程

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

由于之前也遇到過PHP腳本執(zhí)行卡住的類似情況,當(dāng)時的懷疑是跨機(jī)房的Mysql查詢在網(wǎng)絡(luò)抖動時導(dǎo)致Mysql連接卡住了,于是理所當(dāng)然的將所有卡住的進(jìn)程都kill掉了,再從負(fù)載上看機(jī)器馬上就恢復(fù)正常了,于是心滿意足的跑去干別的了.PHP編程

過了一段時間,刷了下監(jiān)控,發(fā)現(xiàn)問題又出現(xiàn)了,注釋掉crontab并kill掉進(jìn)程后,手動執(zhí)行問題腳本,竟然能穩(wěn)定復(fù)現(xiàn)問題!看來是把問題想得太簡單了,嘗試用strace命令看下卡住的進(jìn)程當(dāng)前究竟在干什么：PHP編程

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

什么輸出都沒有!再用netstat看下這個進(jìn)程是否打開了什么端口：PHP編程

[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 

可以看到進(jìn)程打開了兩個端口,分別與Mysql和Redis建立了連接,并且處于連接建立(ESTABLISHED)和對方主動關(guān)閉連接(CLOSE_WAIT)的狀態(tài)；初看確實(shí)像是和數(shù)據(jù)庫的連接卡住了,但是因?yàn)槌赃^虧上過當(dāng),咱們使用tcpdump抓包看進(jìn)程和數(shù)據(jù)庫之間的交互：PHP編程

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

抓了好一會,~/mysql.cap 文件中卻也沒有任何輸出,難道進(jìn)程和Mysql之間已經(jīng)沒有任何交互了?那為什么連接建立沒有關(guān)閉呢?看來只能從頭追蹤一下腳本的執(zhí)行情況了：PHP編程

首先為了能來得及strace到進(jìn)程,在PHP腳本最開始的時候輸出進(jìn)程的pid并sleep 10s:PHP編程

 echo getmypid(); sleep(10); 

然后啟動tcpdump準(zhǔn)備抓包本機(jī)和Mysql的交互過程.PHP編程

最后執(zhí)行PHP腳本,并復(fù)制輸出的pid后在新窗口中執(zhí)行strace命令.PHP編程

這下strace和tcpdump都有內(nèi)容了!從strace結(jié)果看recvfrom之后不再有poll,但并沒有看出來有什么不對：PHP編程

//...
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

再從抓包結(jié)果看,執(zhí)行了兩條SQL查詢語句之后,進(jìn)程沒有再次發(fā)送查詢請求的包,從程序記錄SQL語句日志中,也發(fā)現(xiàn)確實(shí)只執(zhí)行了兩條：PHP編程

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

但從這些現(xiàn)象中,仍然沒有能看出任何端倪,只好祭出終極大法：輸出調(diào)試!大概看了下代碼,并在關(guān)鍵地方添加輸出語句,于是代碼看起來如下：PHP編程

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

執(zhí)行后輸出如下,查詢type為2的網(wǎng)址時卡住了：PHP編程

start foreach
foreach 1
foreach 2

開始懷疑調(diào)用的getSites()方法有問題,代碼如下:PHP編程

$sites = array(); // 省略從數(shù)據(jù)庫查詢的代碼
$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;

原來這里為了實(shí)現(xiàn)拿8個不重復(fù)的網(wǎng)址寫了2個循環(huán),如果結(jié)果中不重復(fù)的網(wǎng)址只有7個就會有一個空,少于7個就會有死循環(huán)!于是查了下type為2的網(wǎng)址個數(shù),果然是只有6個!PHP編程

總結(jié)PHP編程

該問題從發(fā)現(xiàn)到解決花了大概1天時間,雖然最后證明是低級的代碼BUG導(dǎo)致,但是整個排查過程還是挺有收獲的,最開始的想當(dāng)然證明是非常膚淺的,過程中tcpdump和strace的結(jié)果也已經(jīng)很能說明問題了,對各個工具的應(yīng)用應(yīng)該要更加熟練,工具的結(jié)果也要深入分析.以上就是這篇文章的全部內(nèi)容了,希望本文的內(nèi)容對大家的學(xué)習(xí)或者工作能帶來一定的幫助,如果有疑問大家可以留言交流.
PHP編程

轉(zhuǎn)載請注明本頁網(wǎng)址：
http://www.snjht.com/jiaocheng/2233.html