發(fā)現(xiàn)問(wèn)題

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

解決問(wèn)題

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

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

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

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

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

什么輸出都沒(méi)有！再用netstat看下這個(gè)進(jìn)程是否打開了什么端口：

[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)程打開了兩個(gè)端口，分別與Mysql和Redis建立了連接，并且處于連接建立（ESTABLISHED）和對(duì)方主動(dòng)關(guān)閉連接（CLOSE_WAIT）的狀態(tài)；初看確實(shí)像是和數(shù)據(jù)庫(kù)的連接卡住了，但是因?yàn)槌赃^(guò)虧上過(guò)當(dāng)，咱們使用tcpdump抓包看進(jìn)程和數(shù)據(jù)庫(kù)之間的交互：

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

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

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

 echo getmypid(); sleep(10); 

然后啟動(dòng)tcpdump準(zhǔn)備抓包本機(jī)和Mysql的交互過(guò)程。

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

這下strace和tcpdump都有內(nèi)容了！從strace結(jié)果看recvfrom之后不再有poll，但并沒(méi)有看出來(lái)有什么不對(duì)：

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

再?gòu)淖グY(jié)果看，執(zhí)行了兩條SQL查詢語(yǔ)句之后，進(jìn)程沒(méi)有再次發(fā)送查詢請(qǐng)求的包，從程序記錄SQL語(yǔ)句日志中，也發(fā)現(xiàn)確實(shí)只執(zhí)行了兩條：

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

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

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)址時(shí)卡住了：

start foreach
foreach 1
foreach 2

開始懷疑調(diào)用的getSites()方法有問(wèn)題，代碼如下:

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

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

總結(jié)

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

最新評(píng)論